灵活控制 Hibernate 的日志或 SQL 输出，以便于诊断

我们在使用 Hibernate 时一般只会关注是否显示生成的 SQL 语句，不过有些时候还不够。默认时 Hibernate 执行的 SQL 语句是打印在控制台上的，它也可以配置为输出给 Log4J 或是 Log4Back，还能显示出更详细的参数和取值信息。这里简单讲来。

Hibernate 的配置文件 hibernate.cfg.xml 里提供有三个有关显示 SQL 的配置项，如果是与 Spring 联合，也可以配置到 Spring 的配置中。它们的取值是 boolean 值。

1) hibernate.show_sql - 是否显示所生成 SQL 语句，我们最常和它打交道

2)hibernate.format_sql-是否格式化生成的SQL语句，增加可读性，不然全挤在一行

3) hibernate.use_sql_comments - 是否显示注释，用以指出什么操作产生的 SQL 语句，相比上面两条而言，这个配置会稍稍陌生些

来看看加了上面三条配置后产生的效果，执行了 Hibernate 查询后，在控制台上产生如下输出：

Hibernate:
/* load collection cc.unmi.test.model.Post.securities */ select
securities0_.post_id as post1_7_1_,
security1_.shareclassid as sharecla1_16_0_,
security1_.company_id as company2_16_0_,
from
Post_Security_Relationship securities0_
inner join
unmi.securities security1_
on securities0_.shareclassid=security1_.shareclassid
where
securities0_.post_id=?

      hibernate.show_sql 控制全局是否显示生成的 SQL 语句，hibernate.format_sql 格式化后的效果如上，不然就是一行，而 hibernate.use_sql_comments 输出的是红色的部分，表明是在加哉 securities 集合时所执行的 SQL 语句。

Hibernate 默认是把 SQL 语句是输出到控制台，而控制台中的内容查阅起来并不方便，例如超过控制台缓存的内容会被清掉，不是谁都能看到控制台，难以与时间关联起来。虽然有些应用服务器会把控制台输出重定向到文件，但总没有 Log4J 或 Slf4J 那样的专业日志工具来得便捷。

因为 Hibernate 在输出 SQL 时使用的 logger 名为 org.hibernate.SQL, 所以想要让 SQL 语句输出到 Log4J 或是 Slf4J 日志中(日志文件或是记在别处，由 Appender 决定的)，只要在 log4j.properties(log4j.xml 参考相应配置) 中加上：

log4j.logger.org.hibernate.SQL=DEBUG

记得同时把 Hibernate 配置文件中(或者 Spring 中关于 Hibernate 的配置中) 的 hibernate.show_sql 设置为 false，不然可能在控制台下会有双份输出(Log4J 配置了 ConsoleAppender 时)。

如果就用的是 Log4Back 的话，就在 Log4Back 的配置文件 log4back.xml 中加上：

<logger name="org.hibernate.SQL" level="DEBUG"/>

这时的日志输出格式与控制台下没多少分别，只是跟着 Log4J 或 Slf4J 跑而已，像：

20:13:40.757 [http-8080-1] DEBUG org.hibernate.SQL -
/* load collection cc.unmi.test.model.Post.tags */ select
tags0_.post_id as post1_7_1_,
tags0_.tag_id as tag2_1_,
elementite1_.id as id3_0_,
from
Post_Tag_Relationship tags0_
inner join
unmi.element_item elementite1_
on tags0_.tag_id=elementite1_.id
where
tags0_.post_id=?

我们想知道前面输出的 SQL 语句中的 ? 参数代表的实际值是什么，还需要打开一个日志 org.hibernate.type.descriptor.sql.BasicBinder 的输出级别为 TRACE，这里同时把 org.hibernate.type.descriptor.sql.BasicExtractor 的输出级别也设置为 TRACE，来看看效果：

log4j.properties 中配置为：

log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=TRACE
log4j. loggerorg.hibernate.type.descriptor.sql.BasicExtractor=TRACE

      logback.xml 中配置为：

<logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE"/>
<logger name="org.hibernate.type.descriptor.sql.BasicExtractor" level="TRACE"/>

 

之后看输出：

20:13:40.710 [http-8080-1] DEBUG org.hibernate.SQL -
/* load collection cc.unmi.test.model.Post.categories */ select
categories0_.post_id as post1_7_1_,
elementite1_.id as id3_0_,
from
Post_Category_Relationship categories0_
inner join
unmi.element_item elementite1_
on categories0_.category_id=elementite1_.id
where
categories0_.post_id=?
20:13:40.710 [http-8080-1] TRACE org.hibernate.type.descriptor.sql.BasicBinder - binding parameter [1] as [INTEGER] - 10
20:13:40.710 [http-8080-1] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [1002] as column [id3_0_]
20:13:40.710 [http-8080-1] TRACE org.hibernate.type.descriptor.sql.BasicExtractor - found [10] as column [post1_7_1_]

 

红色部分是 org.hibernate.type.descriptor.sql.BasicBinder=TRACE控制的，显示了绑定给 SQL 的参数列表。蓝色部分是org.hibernate.type.descriptor.sql.BasicExtractor=TRACE 控制的，显示了查询后记录的字段值。注意这两个属性是要设置到 TRACE 级别，所以在一般日志的全局 DEBUG 级别之下，它们会表示不受影响。

有时候想要显示查询中命名参数的值，用 :email 而不是 ? 的形式，则还需要引入两个：

log4j.logger.org.hibernate.engine.QueryParameters=DEBUG
log4j.logger.org.hibernate.engine.query.HQLQueryPlan=DEBUG

 

效果是这样的：

20:13:40.710 [http-8080-1] org.hibernate.engine.query.HQLQueryPlan - find: from User where email = :email
20:13:40.710 [http-8080-1] org.hibernate.engine.QueryParameters - named parameters: {[email protected]}
20:13:40.726 [http-8080-1] org.hibernate.SQL -
/* named HQL query findUserByEmail */ select
user0_.id as id0_,
user0_.email as email0_,
user0_.enabled as enabled0_,
user0_.encodedPassword as encodedP8_0_
from
User user0_
where
user0_.email=?

对上面综合一下，比较好的配置可以参考：

hibernate.cfg.xml 中配置：

<property name="hibernate.show_sql">false</property>
<property name="hibernate.format_sql">true</property>
<property name="hibernate.use_sql_comments">true</property>

 

或者是在 Spring 中关于 Hibernate 的配置属性：

<prop key="hibernate.show_sql">false</prop>
<prop key="hibernate.format_sql">true</prop>
<prop key="hibernate.use_sql_comments">true</prop>

而在日志配置中，如 log4j.properties 中配置：

log4j.logger.org.hibernate.type.descriptor.sql.BasicBinder=TRACE
log4j.logger.org.hibernate.type.descriptor.sql.BasicExtractor=TRACE
log4j.logger.org.hibernate.SQL=DEBUG
log4j.logger.org.hibernate.engine.QueryParameters=DEBUG
log4j.logger.org.hibernate.engine.query.HQLQueryPlan=DEBUG

 

倘若用的是 Slf4J 话，就在 logback.xml 中配置：

<logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE"/>
<logger name="org.hibernate.type.descriptor.sql.BasicExtractor" level="TRACE"/>
<logger name="org.hibernate.SQL" level="DEBUG"/>
<logger name="org.hibernate.engine.QueryParameters" level="DEBUG"/>
<logger name="org.hibernate.engine.query.HQLQueryPlan" level="DEBUG"/>

如果你会觉得日志太多的话，反正我是会这么觉得，那么可考虑把org.hibernate.type.descriptor.sql.BasicExtractor 设置为 DEBUG，或不设置该配置项。

注： 本文是在Hibernate 3.6.0 Final 下做的测试，如果是用的其他版本的 Hibernate，尤其是Hibernate 2.x 可能配置很不相象了，需斟酌应对。