log4jdbc实现慢查询sql记录

首先，明确一个概念，这个也是之前一直没怎么搞清楚的：

    log4jdbc一共有三个分支，log4jdbc是原版，最近终于加入Maven的主仓库中，fork之一是log4jdbc-remix，后来又再fork了一个log4jdbc-log4j2。

原版Log4jdbc：https://code.google.com/p/log4jdbc/

       github地址：https://github.com/arthurblake/log4jdbc

log4jdbc-remix地址：http://code.google.com/p/log4jdbc-remix/

log4jdbc-log4j2地址：https://code.google.com/p/log4jdbc-log4j2/

这次使用的是：

<dependency>
    <groupId>org.lazyluke</groupId>
    <artifactId>log4jdbc-remix</artifactId>
    <version>0.2.7</version>
</dependency>

入门使用方法可以参考本人之前的一篇文章：http://blog.csdn.net/ycpanda/article/details/39769737

一、场景需求

目的：针对经分系统进行sql调优，一般的来说，都是非实时性系统。

通常在dev时，log4jdbc是Info level级，为了方便打印sql调试。发布到线上时，就会关闭sql打印，因为太多sql的信息了，意义不大。

然而，系统运行时，有几个功能点会加载速度比较慢，如何去优化系统性能，找到慢查询sql呢？本来想用druid去实现的，但是好几个老系统难得去修改。然后想到，Log4jdbc-remix不是可以打印每条sql的执行时间么，如果我去反编译覆盖重写类，然后加入时间判断条件，不久OK了么？真为自己机智了一把。

INFO  jdbc.sqltiming - SELECT xx FROM table R  
 {executed in 31 msec}

二、动手修改

1、首先，找到了 Slf4jSpyLogDelegator 类，因为这个类有

[java] view plain copy

1. private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");  
2. private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");  
3. private final Logger resultSetTableLogger = LoggerFactory.getLogger("jdbc.resultsettable");  
4. private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");  
5. private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");  
6. private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");  
7. private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");  
8. private static String nl = System.getProperty("line.separator");  

看到 jdbc.sqltiming ，就知道找到和尚庙了。然后向下翻阅，在333行处：

[java] view plain copy

1. public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql)  
2.   {  
3.     if ((this.sqlTimingLogger.isErrorEnabled()) && ((!DriverSpy.DumpSqlFilteringOn) || (shouldSqlBeLogged(sql))))  
4.     {  
5.       if ((DriverSpy.SqlTimingErrorThresholdEnabled) && (execTime >= DriverSpy.SqlTimingErrorThresholdMsec))  
6.       {  
7.         this.sqlTimingLogger.error(buildSqlTimingDump(spy, execTime, methodCall, sql, true));  
8.       }  
9.       else if (this.sqlTimingLogger.isWarnEnabled())  
10.       {  
11.         if ((DriverSpy.SqlTimingWarnThresholdEnabled) && (execTime >= DriverSpy.SqlTimingWarnThresholdMsec))  
12.         {  
13.           this.sqlTimingLogger.warn(buildSqlTimingDump(spy, execTime, methodCall, sql, true));  
14.         }  
15.         else if (this.sqlTimingLogger.isDebugEnabled())  
16.         {  
17.           this.sqlTimingLogger.debug(buildSqlTimingDump(spy, execTime, methodCall, sql, true));  
18.         }  
19.         else if (this.sqlTimingLogger.isInfoEnabled())  
20.         {  
21.           this.sqlTimingLogger.info(buildSqlTimingDump(spy, execTime, methodCall, sql, false));  
22.         }  
23.       }  
24.     }  
25.   }  

有 execTime和sql ，感觉这事要成了。正准备修改，我靠，怎么会有  execTime >= DriverSpy.SqlTimingWarnThresholdMsec  这种阈值判断？难道已经实现啦？没我用武之地？

2、转战到 DriverSpy 类，心里甚是挖凉--->

[java] view plain copy

1. private Driver lastUnderlyingDriverRequested;  
2. private static Map rdbmsSpecifics;  
3. static final SpyLogDelegator log = SpyLogFactory.getSpyLogDelegator();  
4. static String DebugStackPrefix;  
5. static boolean TraceFromApplication;  
6. static boolean SqlTimingWarnThresholdEnabled;  
7. static long SqlTimingWarnThresholdMsec;  
8. static boolean SqlTimingErrorThresholdEnabled;  
9. static long SqlTimingErrorThresholdMsec;  
10. static boolean DumpBooleanAsTrueFalse;  
11. static int DumpSqlMaxLineLength;  
12. static boolean StatementUsageWarn;  
13. static boolean DumpSqlSelect;  
14. static boolean DumpSqlInsert;  
15. static boolean DumpSqlUpdate;  
16. static boolean DumpSqlDelete;  
17. static boolean DumpSqlCreate;  
18. static boolean DumpSqlFilteringOn;  
19. static boolean DumpSqlAddSemicolon;  
20. static boolean DumpFullDebugStackTrace;  
21. static boolean AutoLoadPopularDrivers;  
22. static boolean TrimSql;  
23. static boolean SuppressGetGeneratedKeysException;  
24. static RdbmsSpecifics defaultRdbmsSpecifics = new RdbmsSpecifics();  

这参数配置咋这多啊，哪里来的？然后向下找到356行，发现有个静态块，然后

[java] view plain copy

1. log.debug("... log4jdbc initializing ...");  
2. InputStream propStream = DriverSpy.class.getResourceAsStream("/log4jdbc.properties");  
3. Properties props = new Properties(System.getProperties());  
4. //...下面省略了...  

不多说了，已哭死。部分逻辑如下：

[java] view plain copy

1. //......  
2. DebugStackPrefix = getStringOption(props, "log4jdbc.debug.stack.prefix");  
3. TraceFromApplication = DebugStackPrefix != null;  
4.   
5. Long thresh = getLongOption(props, "log4jdbc.sqltiming.warn.threshold");  
6. SqlTimingWarnThresholdEnabled = thresh != null;  
7. if (SqlTimingWarnThresholdEnabled)  
8. {  
9.   SqlTimingWarnThresholdMsec = thresh.longValue();  
10. }  
11.   
12. thresh = getLongOption(props, "log4jdbc.sqltiming.error.threshold");  
13. SqlTimingErrorThresholdEnabled = thresh != null;  
14. if (SqlTimingErrorThresholdEnabled)  
15. {  
16.   SqlTimingErrorThresholdMsec = thresh.longValue();  
17. }  
18.   
19. DumpBooleanAsTrueFalse = getBooleanOption(props, "log4jdbc.dump.booleanastruefalse", false);  
20.   
21. DumpSqlMaxLineLength = getLongOption(props, "log4jdbc.dump.sql.maxlinelength", 90L).intValue();  
22.   
23. DumpFullDebugStackTrace = getBooleanOption(props, "log4jdbc.dump.fulldebugstacktrace", false);  
24.   
25. StatementUsageWarn = getBooleanOption(props, "log4jdbc.statement.warn", false);  
26.   
27. DumpSqlSelect = getBooleanOption(props, "log4jdbc.dump.sql.select", true);  
28. DumpSqlInsert = getBooleanOption(props, "log4jdbc.dump.sql.insert", true);  
29. DumpSqlUpdate = getBooleanOption(props, "log4jdbc.dump.sql.update", true);  
30. DumpSqlDelete = getBooleanOption(props, "log4jdbc.dump.sql.delete", true);  
31. DumpSqlCreate = getBooleanOption(props, "log4jdbc.dump.sql.create", true);  
32.   
33. DumpSqlFilteringOn = (!DumpSqlSelect) || (!DumpSqlInsert) || (!DumpSqlUpdate) || (!DumpSqlDelete) || (!DumpSqlCreate);  
34.   
35. //......  

折腾了半天，发现回到了原点。-_-|||

其实在

https://code.google.com/p/log4jdbc-log4j2/

https://code.google.com/p/log4jdbc/

页面上都有options的说明，(为了避免大家一起爬墙，贴出来如下)：

log4jdbc-log4j2  options

propertydefaultdescriptionlog4jdbc.drivers

One or more fully qualified class names for JDBC drivers that log4jdbc should load and wrap.
 If more than one driver needs to be specified here, they should be comma separated with no spaces. 
This option is not normally needed because most popular JDBC drivers are already loaded by default-- 
this should be used if one or more additional JDBC drivers that (log4jdbc doesn't already wrap) needs 
to be included.log4jdbc.auto.load.popular.driverstrueSet this to false to disable the feature where popular drivers are automatically loaded. If this is false, 
you must set the log4jdbc.drivers property in order to load the driver(s) you want.log4jdbc.debug.stack.prefix

A REGEX matching the package name of your application. 
The call stack will be searched down to the first occurrence of a class that has the matching REGEX. 
If this is not set, the actual class that called into log4jdbc is used in the debug output 
(in many cases this will be a connection pool class.) For example, setting a system property such as 
this: -Dlog4jdbc.debug.stack.prefix=^com\.mycompany\.myapp.*would cause the 
call stack to be searched for the first call that came from code in the com.mycompany.myapp package 
or below, thus if all of your sql generating code was in code located in the com.mycompany.myapp 
package or any subpackages, this would be printed in the debug information, 
rather than the package name for a connection pool, object relational system, etc. 

Please note that the behavior of this property has changed as compared to the 
standard log4jdbc implementation. This property is now a REGEX, instead of being just the package 
prefix of the stack trace. So, for instance, if you want to target the prefix org.mypackage, the value of this 
property should be: ^org\.mypackage.*.log4jdbc.sqltiming.warn.threshold

Millisecond time value. Causes SQL that takes the number of milliseconds specified or more time to 
execute to be logged at the warning level in the sqltiming log. 
Note that the sqltiming log must be enabled at the warn log level for this feature to work. 
Also the logged output for this setting will log with debug information that is normally only shown 
when the sqltiming log is enabled at the debug level. This can help you to more quickly find 
slower running SQL without adding overhead or logging for normal running SQL that 
executes below the threshold level (if the logging level is set appropriately.)log4jdbc.sqltiming.error.threshold

Millisecond time value. Causes SQL that takes the number of milliseconds specified or more time to 
execute to be logged at the error level in the sqltiming log. 
Note that the sqltiming log must be enabled at the error log level for this feature to work. 
Also the logged output for this setting will log with debug information that is normally only shown 
when the sqltiming log is enabled at the debug level. 
This can help you to more quickly find slower running SQL without adding overhead or 
logging for normal running SQL that executes below the threshold level 
(if the logging level is set appropriately.)log4jdbc.dump.booleanastruefalsefalseWhen dumping boolean values in SQL, dump them as 'true' or 'false'. 
If this option is not set, they will be dumped as 1 or 0 as many databases 
do not have a boolean type, and this allows for more portable sql dumping.log4jdbc.dump.sql.maxlinelength90When dumping SQL, if this is greater than 0, than the dumped SQL will be broken up into lines that 
are no longer than this value. Set this value to 0 if you don't want log4jdbc to try and break the SQL 
into lines this way. In future versions of log4jdbc, this will probably default to 0.log4jdbc.dump.fulldebugstacktracefalseIf dumping in debug mode, dump the full stack trace. This will result in EXTREMELY voluminous output, 
but can be very useful under some circumstances when trying to track down the call chain for 
generated SQL.log4jdbc.dump.sql.selecttrueSet this to false to suppress SQL select statements in the output. 
Note that if you use the Log4j 2 logger, it is also possible to control select statements output via 
the marker LOG4JDBC_SELECT (see section "Disabling some SQL operations, 
or dispatching them in different files" above). The use of this property prepend the use of the marker.log4jdbc.dump.sql.inserttrueSet this to false to suppress SQL insert statements in the output. 
Note that if you use the Log4j 2 logger, it is also possible to control insert statements output via 
the marker LOG4JDBC_INSERT (see section "Disabling some SQL operations, 
or dispatching them in different files" above). The use of this property prepend the use of the marker.log4jdbc.dump.sql.updatetrueSet this to false to suppress SQL update statements in the output. 
Note that if you use the Log4j 2 logger, it is also possible to control update statements output via 
the marker LOG4JDBC_UPDATE (see section "Disabling some SQL operations, 
or dispatching them in different files" above). The use of this property prepend the use of the marker.log4jdbc.dump.sql.deletetrueSet this to false to suppress SQL delete statements in the output. 
Note that if you use the Log4j 2 logger, it is also possible to control delete statements output 
via the marker LOG4JDBC_DELETE (see section "Disabling some SQL operations, 
or dispatching them in different files" above). The use of this property prepend the use of the marker.log4jdbc.dump.sql.createtrueSet this to false to suppress SQL create statements in the output. 
Note that if you use the Log4j 2 logger, it is also possible to control create statements output via 
the marker LOG4JDBC_CREATE (see section "Disabling some SQL operations, 
or dispatching them in different files" above). The use of this property prepend the use of the marker.log4jdbc.dump.sql.addsemicolonfalseSet this to true to add an extra semicolon to the end of SQL in the output. 
This can be useful when you want to generate SQL from a program with log4jdbc 
in order to create a script to feed back into a database to run at a later time.log4jdbc.spylogdelegator.namenet.sf.log4jdbc.log.log4j2.Log4j2SpyLogDelegatorThe qualified class name of the SpyLogDelegator to use. 
Note that if you want to use log4jdbc-log4j2 with SLF4J rather than Log4j 2, 
you must set this property to: net.sf.log4jdbc.log.slf4j.Slf4jSpyLogDelegator. 
This is a new property, not present in the standard log4jdbc implementation.log4jdbc.statement.warnfalseSet this to true to display warnings (Why would you care?) in the log when 
Statements are used in the log. NOTE, this was always true 
in releases previous to 1.2alpha2. It is false by default starting with release 1.2 alpha 2.log4jdbc.trim.sqltrueSet this to false to not trim the logged SQL. (Previous versions always trimmed the SQL.)log4jdbc.trim.sql.extrablanklinestrueSet this to false to not trim extra blank lines in the logged SQL (
by default, when more than one blank line in a row occurs, the contiguou lines are collapsed 
to just one blank line.) (Previous versions didn't trim extra blank lines at all.)log4jdbc.suppress.generated.keys.exceptionfalseSet to true to ignore any exception produced by the method, Statement.getGeneratedKeys() 
(Useful for using log4jdbc with Coldfusion

Of note, an additional property allows to set the name of the property file:

propertydefaultdescriptionlog4jdbc.log4j2.properties.filelog4jdbc.log4j2.propertiesSet the name of the property file to use 

log4jdbc

propertydefaultdescriptionsincelog4jdbc.drivers

One or more fully qualified class names for JDBC drivers that log4jdbc should load and wrap. 
If more than one driver needs to be specified here, they should be comma separated with no spaces. 
This option is not normally needed because most popular JDBC drivers are already loaded by default-- 
this should be used if one or more additional JDBC drivers that (log4jdbc doesn't already wrap) 
needs to be included.1.0log4jdbc.auto.load.popular.driverstrueSet this to false to disable the feature where popular drivers are automatically loaded. 
If this is false, you must set the log4jdbc.drivers property in order to load the driver(s) you want.1.2beta2log4jdbc.debug.stack.prefix

The partial (or full) package prefix for the package name of your application. 
The call stack will be searched down to the first occurrence of a class that has the matching prefix. 
If this is not set, the actual class that called into log4jdbc is used in the debug output 
(in many cases this will be a connection pool class.) For example, setting a system property 
such as this: -Dlog4jdbc.debug.stack.prefix=com.mycompany.myapp Would cause 
the call stack to be searched for the first call that came from code 
in the com.mycompany.myapp package or below, thus if all of your sql generating code 
was in code located in the com.mycompany.myapp package or any subpackages, 
this would be printed in the debug information, rather than the package name for a connection pool, 
object relational system, etc.1.0log4jdbc.sqltiming.warn.threshold

Millisecond time value. Causes SQL that takes the number of milliseconds specified or more time 
to execute to be logged at the warning level in the sqltiming log. 
Note that the sqltiming log must be enabled at the warn log level for this feature to work.
 Also the logged output for this setting will log with debug information that is normally only shown 
when the sqltiming log is enabled at the debug level. 
This can help you to more quickly find slower running SQL without adding overhead or logging 
for normal running SQL that executes below the threshold level (if the logging level is set appropriately.)1.1beta1log4jdbc.sqltiming.error.threshold

Millisecond time value. Causes SQL that takes the number of milliseconds specified or more time 
to execute to be logged at the error level in the sqltiming log. 
Note that the sqltiming log must be enabled at the error log level for this feature to work. 
Also the logged output for this setting will log with debug information that is normally only shown 
when the sqltiming log is enabled at the debug level. 
This can help you to more quickly find slower running SQL without adding overhead or logging 
for normal running SQL that executes below the threshold level (if the logging level is set appropriately.)1.1beta1log4jdbc.dump.booleanastruefalsefalseWhen dumping boolean values in SQL, dump them as 'true' or 'false'. 
If this option is not set, they will be dumped as 1 or 0 as many databases do not have a boolean type, 
and this allows for more portable sql dumping.1.2alpha1log4jdbc.dump.sql.maxlinelength90When dumping SQL, if this is greater than 0, than the dumped SQL will be broken up into lines 
that are no longer than this value. Set this value to 0 if you don't want log4jdbc to try 
and break the SQL into lines this way. In future versions of log4jdbc, this will probably default to 0.1.2alpha1log4jdbc.dump.fulldebugstacktracefalseIf dumping in debug mode, dump the full stack trace. 
This will result in EXTREMELY voluminous output, but can be very useful under some circumstances 
when trying to track down the call chain for generated SQL.1.2alpha1log4jdbc.dump.sql.selecttrueSet this to false to suppress SQL select statements in the output.1.2alpha1log4jdbc.dump.sql.inserttrueSet this to false to suppress SQL insert statements in the output.1.2alpha1log4jdbc.dump.sql.updatetrueSet this to false to suppress SQL update statements in the output.1.2alpha1log4jdbc.dump.sql.deletetrueSet this to false to suppress SQL delete statements in the output.1.2alpha1log4jdbc.dump.sql.createtrueSet this to false to suppress SQL create statements in the output.1.2alpha1log4jdbc.dump.sql.addsemicolonfalseSet this to true to add an extra semicolon to the end of SQL in the output. 
This can be useful when you want to generate SQL from a program with log4jdbc in order to 
create a script to feed back into a database to run at a later time.1.2alpha1log4jdbc.statement.warnfalseSet this to true to display warnings (Why would you care?) in the log when Statements are used 
in the log. NOTE, this was always true in releases previous to 1.2alpha2. It is false by default 
starting with release 1.2 alpha 2.1.2alpha2log4jdbc.trim.sqltrueSet this to false to not trim the logged SQL. (Previous versions always trimmed the SQL.)1.2beta2log4jdbc.trim.sql.extrablanklinestrueSet this to false to not trim extra blank lines in the logged SQL 
(by default, when more than one blank line in a row occurs, the contiguous lines are collapsed to 
just one blank line.) (Previous versions didn't trim extra blank lines at all.)1.2log4jdbc.suppress.generated.keys.exceptionfalseSet to true to ignore any exception produced by the method, Statement.getGeneratedKeys() 
(Useful for using log4jdbc with Coldfusion.)1.2beta2

so,一切都柳暗花明了。

三、如何在工程中实现

1、对于maven工程，在src/main/resources下新增一个配置文件： log4jdbc.properties

内容如下：

#只显示含调用栈的包名的语句
#log4jdbc.debug.stack.prefix=

#这2个是在一起的,和数据库驱动有关。实际作用本人未尝试
#log4jdbc.auto.load.popular.drivers=true
#log4jdbc.drivers=

#执行时间阀值，单位为ms，将Log级别调为Warning，则只会打印执行较慢的语句
log4jdbc.sqltiming.warn.threshold=2000
#log4jdbc.sqltiming.error.threshold=

#是把boolean记录为 'true'/'false' 还是 1/0. 默认设置为false,不启用,为了移植性.
#log4jdbc.dump.booleanastruefalse=

#输出的sql,一行最大的字符数，默认90. 以后新版可能为0
#log4jdbc.dump.sql.maxlinelength=90

#If dumping in debug mode, dump the full stack trace. 默认false
#log4jdbc.dump.fulldebugstacktrace=false

#是否记录某些类型的语句，默认true
#log4jdbc.dump.sql.select=true
#log4jdbc.dump.sql.insert=true
#log4jdbc.dump.sql.update=true
#log4jdbc.dump.sql.delete=true
#log4jdbc.dump.sql.create=true

#输出sql末尾处加入分号，默认false
#log4jdbc.dump.sql.addsemicolon=

#默认true，
#log4jdbc.trim.sql=true

#display warnings in the log when Statements are used in the log. 默认false,不是太理解
#log4jdbc.statement.warn=false

#gnore any exception produced by the method, Statement.getGeneratedKeys() .默认false
#log4jdbc.suppress.generated.keys.exception=false

在上面，只设置了warn阈值，其它默认。

2、修改日志文件配置：(本处使用的是logback)

<!-- 指定logger的设置，additivity指示是否遵循缺省的继承机制-->
<logger name='jdbc.sqltiming' additivity='true' level="warn"/>
<logger name='jdbc.audit' additivity='false'/>
<logger name='jdbc.resultset' additivity='false'/>
<logger name='jdbc.connection' additivity='false'/>
<logger name='jdbc.resultsettable' additivity='false'/>
<logger name="jdbc.sqlonly" additivity="false"/>

然后，会发现工程console中，sql打印少了很多很多。

但是这种固定配置，在dev时开发时，会不方便调试，所以我们要用maven profile，进行自动打包配置。实现在dev时，level='info'，产品环境时，level='warn'。

打包请参考：

maven多环境打包配置