GrailsでHibernateが発行するSQLをロギングする

今回は、Grailsのドメインクラスの裏にいるHibernateが発行しているSQLをロギングする方法です。

中野靖治のGroovy活用術第7回
- 2016年03月24日公開

GrailsでHibernateが発行するSQLをロギングする

はじめに

こんにちは。NTTソフトウェアの中野です。今回は、Grailsのドメインクラスの裏にいるHibernateが発行しているSQLをロギングする方法です。

なぜSQLをロギングするのか

HibernateのようにSQLが隠蔽されているO/Rマッパの場合、どのようなSQLが実際に発行されているかを確認することはとても重要です。わかりやすいソースコードが無駄のないSQLを発行してくれる保証はありません。逆にソースコード上のわかりやすさだけを気にしすぎたために、非効率なSQLが大量に発行されてしまう場合もあります。実装時から実際のSQLをロギングして確認するようにして、性能問題を作り込まないように心がけましょう。

ロギング設定

基本的に、ログレベルを適切に指定すれば出力されます。あとはオプションをいくつかつけて読みやすくしたり情報を付加したり、という感じです。

なお、実際にプロダクトに適用する場合には、ログ出力のオーバーヘッドによる性能劣化を防ぐため、developmentやtest環境でのみ出力するように設定することをお勧めします。

Grails 3.x

2つのファイルに設定を追加します。

application.yml

#...
hibernate:
#...

# [A-1] ロギング時にSQLをフォーマットして出力する
format_sql: true

# [A-2] SQL発行箇所の情報をSQLコメントとして出力する(気休め程度)
use_sql_comments: true
#...

logback.groovy

//...

// [L-1] SQLを出力する(プレイスホルダは「?」表記のまま)
logger 'org.hibernate.SQL', DEBUG, ['STDOUT'], false

// [L-2] SQLのプレイスホルダに対するパラメータを出力する(enum以外)
logger 'org.hibernate.type.descriptor.sql.BasicBinder', TRACE, ['STDOUT'], false

// [L-3] SQLのプレイスホルダに対するパラメータを出力する(enum)
logger 'org.hibernate.type.EnumType', TRACE, ['STDOUT'], false

// [L-4] HibernateではなくGroovy SQLを使っている場合も漏らさずロギングする
logger 'groovy.sql.Sql', DEBUG, ['STDOUT'], false

上記ではデフォルトで用意されているConsoleAppenderであるSTDOUTに対して出力指定していますが、実際に利用するときには各プロジェクトの適切なアペンダを指定してください。

なお、前回の独自プロファイルの例として、logback.groovyファイルのサンプルを紹介しましたが、実は上と同等のSQLのロギング設定が既に仕込まれています。

Grails 2.x

基本的な設定はGrails 3.xの場合と同様ですが、Groovy SQLでロギングに使っているjava.util.LoggerとGrails 2.xでデフォルトのSLF4J+Log4jとを連携させるために、2つの追加設定が必要となります([C-1], [B-1])。

DataSource.groovy

//...
hibernate {
//...

// [A-1] ロギング時にSQLをフォーマットして出力する
format_sql = true

// [A-2] SQL発行箇所の情報をSQLコメントとして出力する(気休め程度)
use_sql_comments = true
}
//...

Config.groovy

//...
environments {
development {
grails.logging.jul.usebridge = true
}
test {
// [C-1] test環境でGroovy SQLのログを出力するために必要
grails.logging.jul.usebridge = true
}
production {
grails.logging.jul.usebridge = false
// TODO: grails.serverURL = "http://www.changeme.com"
}
}

// log4j configuration
log4j.main = {
//...

// [L-1] SQLを出力する(プレイスホルダは「?」表記のまま)
debug 'org.hibernate.SQL'

// [L-2] SQLのプレイスホルダに対するパラメータを出力する(enum以外)
trace 'org.hibernate.type.descriptor.sql.BasicBinder'

// [L-3] SQLのプレイスホルダに対するパラメータを出力する(enum)
trace 'org.hibernate.type.EnumType'

// [L-4] HibernateではなくGroovy SQLを使っている場合も漏らさずロギングする
debug 'groovy.sql.Sql'

BootStrap.groovy

import groovy.sql.Sql
import java.util.logging.Level

class BootStrap {
def init = { servletContext ->
// [B-1] Groovy SQL用ロガーのログレベルをLog4jのDEBUG相当に設定する
Sql.LOG.level = Level.FINE
}
}

試してみる

Grails 3.1.4で試してみます。

ドメインクラス

class Person {
String name
Integer age
BloodType bloodType
static constraints = {
name blank: false, maxSize: 1000
age min: 0
}
}

enumクラス

enum BloodType {
A, B, AB, O
}

テストクラス

import grails.test.mixin.integration.Integration
import grails.transaction.*
import groovy.sql.Sql
import spock.lang.*

@Integration
@Stepwise
@Transactional
class PersonSpec extends Specification {

def dataSource

void "insert"() {
given:
def person = new Person(name: "Oda Nobunaga", age: 47, bloodType: BloodType.A)

when:
person.save(failOnError: true, flush: true)

then:
person.count() == 1
}

void "update"() {
given:
def person = Person.findByName("Oda Nobunaga")

when:
person.age = 99
person.save(failOnError: true, flush: true)

then:
person.count() == 1
person.age == 99
}

void "Groovy SQL"() {
given:
def sql = new Sql(dataSource)

when:
def persons = sql.rows("SELECT * FROM person WHERE name = ?", ["Oda Nobunaga"])

then:
persons*.name == ["Oda Nobunaga"]
}

void "delete"() {
given:
def person = Person.findByName("Oda Nobunaga")

when:
person.delete(flush: true)

then:
person.count() == 0
}
}

上記のテストを実行すると、以下のようにログが標準出力(STDOUT)に出力されます。説明のために (筆者注) というメモを適宜追記してあります。

Grails application running at http://localhost:8080 in environment: test
DEBUG org.hibernate.SQL -
/* insert grails3x.sql.logging.Person
*/ insert
into
person
(id, version, age, blood_type, name)
values
(null, ?, ?, ?, ?)

(筆者注)
[L-1]の設定によって出力されます。
[A-1]の設定によって読みやすいようにフォーマットされています。
[A-1]を指定しない、またはfalseを指定した場合は1行にまとめて出力されます。
[A-2]の設定によって先頭にどのドメインクラスに関連したSQLであるかが、コメント情報として出力されます。

TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [0]

(筆者注)
[L-2]の設定によって各プレイスホルダの実際のパラメータが出力されます。

TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [INTEGER] - [47]
TRACE org.hibernate.type.EnumType - Binding [A] to parameter: [3]

(筆者注)
[L-3]の設定によってenum型のパラメータも出力されます。
[L-3]の設定がない場合はenum型のパラメータ情報だけ出力されないのでご注意ください。

TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [4] as [VARCHAR] - [Oda Nobunaga]
DEBUG org.hibernate.SQL -
/* criteria query */ select
count(*) as y0_
from
person this_
DEBUG org.hibernate.SQL -
/* criteria query */ select
this_.id as id1_0_0_,
this_.version as version2_0_0_,
this_.age as age3_0_0_,
this_.blood_type as blood_ty4_0_0_,
this_.name as name5_0_0_
from
person this_
where
this_.name=? limit ?
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [Oda Nobunaga]
TRACE org.hibernate.type.EnumType - Returning [A] as column [blood_ty4_0_0_]
DEBUG org.hibernate.SQL -
/* update
grails3x.sql.logging.Person */ update
person
set
version=?,
age=?,
blood_type=?,
name=?
where
id=?
and version=?
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [1]
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [INTEGER] - [99]
TRACE org.hibernate.type.EnumType - Binding [A] to parameter: [3]
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [4] as [VARCHAR] - [Oda Nobunaga]
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [5] as [BIGINT] - [1]
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [6] as [BIGINT] - [0]
DEBUG org.hibernate.SQL -
/* criteria query */ select
count(*) as y0_
from
person this_
DEBUG groovy.sql.Sql - SELECT * FROM person WHERE name = ? | [Oda Nobunaga]

(筆者注)
[L-4]の設定によってGroovy SQLを使ったSQLも出力されます。
プレイスホルダのパラメータはパイプ記号の後ろに出力されます。

DEBUG org.hibernate.SQL -
/* criteria query */ select
this_.id as id1_0_0_,
this_.version as version2_0_0_,
this_.age as age3_0_0_,
this_.blood_type as blood_ty4_0_0_,
this_.name as name5_0_0_
from
person this_
where
this_.name=? limit ?
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [VARCHAR] - [Oda Nobunaga]
TRACE org.hibernate.type.EnumType - Returning [A] as column [blood_ty4_0_0_]
DEBUG org.hibernate.SQL -
/* delete grails3x.sql.logging.Person */ delete
from
person
where
id=?
and version=?
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [BIGINT] - [1]
TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [2] as [BIGINT] - [1]
DEBUG org.hibernate.SQL -
/* criteria query */ select
count(*) as y0_
from
person this_

おわりに

今回のサンプルコードは、GitHubに公開してあります。

Grails 3.x: https://github.com/nobeans/grails3x-sql-logging (Grails 3.1.4で作成＆動作確認)
Grails 2.x: https://github.com/nobeans/grails2x-sql-logging (Grails 2.5.4で作成＆動作確認)

コメントや不具合等があればIssuesやPull Requestでお願いいたします。

連載シリーズ

中野靖治のGroovy活用術