（轉）靈活控制 Hibernate 的日志或 SQL 輸出，以便於診斷

背景：項目開發需要。之前對於hibernate日志輸出，log4j的綁定，之間的關系一直不是很清楚。終於找到一篇介紹的很詳細的文章。

文章出處：https://unmi.cc/hibernate-log-sql-log4j-slf4j/

hibernate配置

我們在使用 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 語句，相比上面兩條而言，這個配置會稍稍陌生些

與spring聯合配置spring-config.xml：

<bean id="sessionFactory" class="org.springframework.orm.hibernate4.LocalSessionFactoryBean" >
        <property name="dataSource" ref="dataSource"/>
        <property name="mappingLocations">
            <list>
                <value>classpath:szfs/tms/service/manage/conf/hbm/*/*.hbm.xml</value>
                <value>classpath:szfs/tms/service/manage/conf/hbm/*.hbm.xml</value>
            </list>
        </property>
        
        <property name="hibernateProperties">
            <props>
                <prop key="hibernate.dialect">${hibernate.dialect}</prop>
                <prop key="hibernate.show_sql">${hibernate.show_sql}</prop>
<!-- <prop key="hibernate.show_sql">true</prop> -->
                <prop key="hibernate.format_sql">true</prop>
                <prop key="hibernate.query.substitutions">${hibernate.query.substitutions}</prop>
                <prop key="hibernate.default_batch_fetch_size">${hibernate.default_batch_fetch_size}</prop>
                <prop key="hibernate.max_fetch_depth">${hibernate.max_fetch_depth}</prop>
                <prop key="hibernate.generate_statistics">${hibernate.generate_statistics}</prop>
                <prop key="hibernate.bytecode.use_reflection_optimizer">${hibernate.bytecode.use_reflection_optimizer}</prop>

                <prop key="hibernate.cache.use_second_level_cache">${hibernate.cache.use_second_level_cache}</prop>
                <prop key="hibernate.cache.use_query_cache">${hibernate.cache.use_query_cache}</prop>
                <prop key="hibernate.cache.region.factory_class">${hibernate.cache.region.factory_class}</prop>
                <prop key="net.sf.ehcache.configurationResourceName">${net.sf.ehcache.configurationResourceName}</prop>
                <prop key="hibernate.cache.use_structured_entries">${hibernate.cache.use_structured_entries}</prop>
            </props>
        </property>
        
        <property name="entityInterceptor">
            <bean id ="customNullsFirstInterceptor" class="szfs.tms.service.framework.interceptor.CustomNullsFirstInterceptor" />
        </property>
      </bean>

 

 來看看加了上面三條配置后產生的效果，執行了 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 語句。

ps：以上各配置是hibernate相關的配置。配置完成后就會顯示在控制台中。

日志輸出與日志框架聯系

打印sql語句

Hibernate 默認是把 SQL 語句是輸出到控制台，而控制台中的內容查閱起來並不方便，例如超過控制台緩存的內容會被清掉，不是誰都能看到控制台，難以與時間關聯起來。雖然有些應用服務器會把控制台輸出重定向到文件，但總沒有 Log4J 或 Slf4J 那樣的專業日志工具來得便捷。

log4j.properties或log4j.xml 

因為 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 時)。

ps：這個問題困擾我好久，每次看到控制台輸出的sql語句都是重復的，對於有強迫症的我，真是無法忍受。

 log4back.xml

如果用的是 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=?

 

只有紅色部分不同，應用上了 Log4J 或 Slf4J 的配置了，可以看到執行的時間、線程等相關信息。

打印parameter result結果

我們想知道前面輸出的 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 級別之下，它們會表示不受影響。 

ps：這里涉及到log4j.rootLogger 與log4j.logger的優先級問題。都配置后，log4j.logger的優先級較高。

 

有時候想要顯示查詢中命名參數的值，用 :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=[e-mail]}
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中配置

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 可能配置很不相象了，需斟酌應對。