grailsのHibernateでSQLのパラメータまで出力する

元ネタ http://burtbeckwith.com/blog/?p=1604

grailsでSQLを出力する方法は２通りあってDataSource.groovyで

dataSource {
    ...
    logSql = true
}

とするか、Config.groovyで

log4j = {
    ...
    debug  'org.hibernate.SQL'
}

とするか。前者は標準出力で、後者はログとして出力される。これで出力されるSQLにパラメータは出力されない。

以下の様な感じ。

    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)

今までパラメータまで出力する場合は、後者のログの出力レベルを変更してやる方法でorg.hibernate.typeパッケージをtraceとして方法でやっていた。

log4j = {
    ...
    trace  'org.hibernate.type'
    debug  'org.hibernate.SQL'
}

この設定でどんなログが出力されるのか以下のテストを実行。(見やすいようにDataSource.groovyにformatSql=trueを追加して実行)

    def "logの確認"() {
        given:
        new Book(title: 'a').save(flush: true)
        new Book(title: 'b').save(flush: true)
        new Book(title: 'c').save(flush: true)
        Book.withSession { it.clear() } // selectで1次キャッシュを使わないようにクリア

        when:
        def books = Book.list()

        then:
        books.size() == 3
    }

ログは以下のようなに出力される。

| Running 1 spock test... 1 of 1
--Output from logの確認--
2012-10-20 13:08:57,706 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:08:57,707 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:08:57,707 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - a
2012-10-20 13:08:57,710 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:08:57,710 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:08:57,710 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - b
2012-10-20 13:08:57,713 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:08:57,713 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:08:57,713 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - c
2012-10-20 13:08:57,749 [main] DEBUG org.hibernate.SQL - 
    select
        this_.id as id24_0_,
        this_.version as version24_0_,
        this_.title as title24_0_ 
    from
        book this_
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1] as column [id24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [a] as column [title24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [2] as column [id24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [b] as column [title24_0_]
2012-10-20 13:08:57,750 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [3] as column [id24_0_]
2012-10-20 13:08:57,751 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version24_0_]
| Completed 1 spock test, 0 failed in 250ms

これで見れるようになる！のだけどselectした時のResultSetに含まれるログが大量に出力される。上の例では問題ないが、ResultSetの件数が多い場合はこれがノイズになる。

ResultSetのパラメータは出力されないようにしたい。上記のログが出力されているパッケージをみるとinsertの時はorg.hibernate.type.descriptor.sql.BasicBinderで、selectの時はorg.hibernate.type.descriptor.sql.BasicExtractorからログ出ていることがわかる。そこで以下のようにConfig.groovyを変更する。

log4j = {
    ...
    trace 'org.hibernate.type.descriptor.sql.BasicBinder'
    debug 'org.hibernate.SQL'
}

この状態でもう一度実行してみる。

| Running 1 spock test... 1 of 1
--Output from logの確認--
2012-10-20 13:07:53,797 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:07:53,798 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:07:53,798 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - a
2012-10-20 13:07:53,801 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:07:53,801 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:07:53,801 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - b
2012-10-20 13:07:53,804 [main] DEBUG org.hibernate.SQL - 
    insert 
    into
        book
        (id, version, title) 
    values
        (null, ?, ?)
2012-10-20 13:07:53,804 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:07:53,805 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - c
2012-10-20 13:07:53,849 [main] DEBUG org.hibernate.SQL - 
    select
        this_.id as id22_0_,
        this_.version as version22_0_,
        this_.title as title22_0_ 
    from
| Completed 1 spock test, 0 failed in 113ms

なかなか良い感じ。

あと元ネタのURLで

hibernate {
   ...
   use_sql_comments = true
}

というsqlコメントを出してくれるオプションがあるようだ。知らなかった。

注意としてDataSource.groovyの dataSource {...} の方ではなく hibernate {...} の方に記述する必要がある。dataSourceの方に記述する方法はないかと調べてみ見たが実装は以下のようになっており、use_sql_commentsに関する処理は無さそう。てことでhibernateに書かなければならない。

// grails 2.1.1での情報
// org.codehaus.groovy.grails.plugins.orm.hibernate.HibernatePluginSupport
// 157行目あたり
            if (ds.loggingSql || ds.logSql) {
                hibProps."hibernate.show_sql" = "true"
            }
            if (ds.formatSql) {
                hibProps."hibernate.format_sql" = "true"
            }

ということで諦めてhibernateの方に書いて実行してみる。

--Output from logの確認--
2012-10-20 13:27:10,397 [main] DEBUG org.hibernate.SQL - 
    /* insert test.Book
        */ insert 
        into
            book
            (id, version, title) 
        values
            (null, ?, ?)
2012-10-20 13:27:10,398 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:27:10,398 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - a
2012-10-20 13:27:10,401 [main] DEBUG org.hibernate.SQL - 
    /* insert test.Book
        */ insert 
        into
            book
            (id, version, title) 
        values
            (null, ?, ?)
2012-10-20 13:27:10,402 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:27:10,402 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - b
2012-10-20 13:27:10,404 [main] DEBUG org.hibernate.SQL - 
    /* insert test.Book
        */ insert 
        into
            book
            (id, version, title) 
        values
            (null, ?, ?)
2012-10-20 13:27:10,405 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - 0
2012-10-20 13:27:10,405 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [VARCHAR] - c
2012-10-20 13:27:10,462 [main] DEBUG org.hibernate.SQL - 
    /* criteria query */ select
        this_.id as id32_0_,
        this_.version as version32_0_,
        this_.title as title32_0_ 
    from
        book this_
2012-10-20 13:27:10,462 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1] as column [id32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [a] as column [title32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [2] as column [id32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [b] as column [title32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [3] as column [id32_0_]
2012-10-20 13:27:10,463 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [0] as column [version32_0_]
| Completed 1 spock test, 0 failed in 135ms

でたが/* criteria query */とかでそんなに嬉しくないけど、出てないより出ていたほうが何かの助けるなるかもしれない。試しに

        println '=' * 100
        Book.withCriteria {
            eq 'title', 'a'
        }

        println '=' * 100
        Book.where {
            title == 'a'
        }.list()

        println '=' * 100
        Book.findByTitle('a')

        println '=' * 100
        Book.findAll('from Book as b where b.title = :title', [title: 'a'])

というコードを実行してみたら以下の様に出た。

====================================================================================================
2012-10-20 13:34:41,168 [main] DEBUG org.hibernate.SQL - 
    /* criteria query */ select
        this_.id as id40_0_,
        this_.version as version40_0_,
        this_.title as title40_0_ 
    from
        book this_ 
    where
        this_.title=?
2012-10-20 13:34:41,168 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - a
2012-10-20 13:34:41,169 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1] as column [id40_0_]
====================================================================================================
2012-10-20 13:34:41,184 [main] DEBUG org.hibernate.SQL - 
    /* criteria query */ select
        this_.id as id40_0_,
        this_.version as version40_0_,
        this_.title as title40_0_ 
    from
        book this_ 
    where
        this_.title=?
2012-10-20 13:34:41,185 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - a
2012-10-20 13:34:41,185 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1] as column [id40_0_]
====================================================================================================
2012-10-20 13:34:41,207 [main] DEBUG org.hibernate.SQL - 
    /* criteria query */ select
        this_.id as id40_0_,
        this_.version as version40_0_,
        this_.title as title40_0_ 
    from
        book this_ 
    where
        this_.title=? limit ?
2012-10-20 13:34:41,209 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - a
2012-10-20 13:34:41,210 [main] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1] as column [id40_0_]
====================================================================================================
2012-10-20 13:34:41,226 [main] DEBUG org.hibernate.SQL - 
    /* 
from
    Book as b 
where
    b.title = :title */ select
        book0_.id as id40_,
        book0_.version as version40_,
        book0_.title as title40_ 
    from
        book book0_ 
    where
        book0_.title=?
2012-10-20 13:34:41,227 [main] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - a
| Completed 1 spock test, 0 failed in 177ms

なるほどHQLで便利は場面はあるかもしれない。てことでHibernateログを出すときは
Config.groovyに

log4j = {
    ...
    trace  'org.hibernate.type.descriptor.sql.BasicBinder'
    debug  'org.hibernate.SQL'
}

を追加。DataSource.groovyに

hibernate {
    ...
    format_sql = true
    use_sql_comments = true
}

を追加がお勧めかな。