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

r囧r小猫 2021-09-14 00:24 284阅读 0赞

##     ##

我们在使用 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 中加上：

这时的日志输出格式与控制台下没多少分别，只是跟着 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=?

只有红色部分不同，应用上了 Log4J 或 Slf4J 的配置了，可以看到执行的时间、线程等相关信息。

我们想知道前面输出的 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 中配置为：

之后看输出：

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=fantasia@sina.com][email_fantasia_sina.com]\}  
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 中配置：

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

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

参考：1. [Hibernate Parameter Logging][]

本文链接 [http://unmi.cc/hibernate-log-sql-log4j-slf4j][http_unmi.cc_hibernate-log-sql-log4j-slf4j], 来自 [隔叶黄莺 Unmi Blog][Unmi Blog]

[email_fantasia_sina.com]: mailto:%7bemail=fantasia@sina.com
[Hibernate Parameter Logging]: http://geeklondon.com/blog/view/the-blind-needing-the-bind
[http_unmi.cc_hibernate-log-sql-log4j-slf4j]: http://unmi.cc/hibernate-log-sql-log4j-slf4j
[Unmi Blog]: http://unmi.cc/