log4jdbc实现慢查询sql记录

首先,明确一个概念,这个也是之前一直没怎么搞清楚的:
    log4jdbc一共有三个分支,log4jdbc是原版,最近终于加入Maven的主仓库中,fork之一是log4jdbc-remix,后来又再fork了一个 log4jdbc-log4j2

        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 类,因为这个类有
private final Logger jdbcLogger = LoggerFactory.getLogger("jdbc.audit");
private final Logger resultSetLogger = LoggerFactory.getLogger("jdbc.resultset");
private final Logger resultSetTableLogger = LoggerFactory.getLogger("jdbc.resultsettable");
private final Logger sqlOnlyLogger = LoggerFactory.getLogger("jdbc.sqlonly");
private final Logger sqlTimingLogger = LoggerFactory.getLogger("jdbc.sqltiming");
private final Logger connectionLogger = LoggerFactory.getLogger("jdbc.connection");
private final Logger debugLogger = LoggerFactory.getLogger("log4jdbc.debug");
private static String nl = System.getProperty("line.separator");

看到  jdbc.sqltiming ,就知道找到和尚庙了。然后向下翻阅,在333行处:
public void sqlTimingOccured(Spy spy, long execTime, String methodCall, String sql)
  {
    if ((this.sqlTimingLogger.isErrorEnabled()) && ((!DriverSpy.DumpSqlFilteringOn) || (shouldSqlBeLogged(sql))))
    {
      if ((DriverSpy.SqlTimingErrorThresholdEnabled) && (execTime >= DriverSpy.SqlTimingErrorThresholdMsec))
      {
        this.sqlTimingLogger.error(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
      }
      else if (this.sqlTimingLogger.isWarnEnabled())
      {
        if ((DriverSpy.SqlTimingWarnThresholdEnabled) && (execTime >= DriverSpy.SqlTimingWarnThresholdMsec))
        {
          this.sqlTimingLogger.warn(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
        }
        else if (this.sqlTimingLogger.isDebugEnabled())
        {
          this.sqlTimingLogger.debug(buildSqlTimingDump(spy, execTime, methodCall, sql, true));
        }
        else if (this.sqlTimingLogger.isInfoEnabled())
        {
          this.sqlTimingLogger.info(buildSqlTimingDump(spy, execTime, methodCall, sql, false));
        }
      }
    }
  }



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

2、转战到 DriverSpy  心里甚是挖凉--->
private Driver lastUnderlyingDriverRequested;
private static Map rdbmsSpecifics;
static final SpyLogDelegator log = SpyLogFactory.getSpyLogDelegator();
static String DebugStackPrefix;
static boolean TraceFromApplication;
static boolean SqlTimingWarnThresholdEnabled;
static long SqlTimingWarnThresholdMsec;
static boolean SqlTimingErrorThresholdEnabled;
static long SqlTimingErrorThresholdMsec;
static boolean DumpBooleanAsTrueFalse;
static int DumpSqlMaxLineLength;
static boolean StatementUsageWarn;
static boolean DumpSqlSelect;
static boolean DumpSqlInsert;
static boolean DumpSqlUpdate;
static boolean DumpSqlDelete;
static boolean DumpSqlCreate;
static boolean DumpSqlFilteringOn;
static boolean DumpSqlAddSemicolon;
static boolean DumpFullDebugStackTrace;
static boolean AutoLoadPopularDrivers;
static boolean TrimSql;
static boolean SuppressGetGeneratedKeysException;
static RdbmsSpecifics defaultRdbmsSpecifics = new RdbmsSpecifics();

这参数配置咋这多啊,哪里来的? 然后向下找到356行,发现有个静态块,然后
log.debug("... log4jdbc initializing ...");
InputStream propStream = DriverSpy.class.getResourceAsStream("/log4jdbc.properties");
Properties props = new Properties(System.getProperties());
//...下面省略了...


不多说了,已哭死。部分逻辑如下:
//......
DebugStackPrefix = getStringOption(props, "log4jdbc.debug.stack.prefix");
TraceFromApplication = DebugStackPrefix != null;

Long thresh = getLongOption(props, "log4jdbc.sqltiming.warn.threshold");
SqlTimingWarnThresholdEnabled = thresh != null;
if (SqlTimingWarnThresholdEnabled)
{
  SqlTimingWarnThresholdMsec = thresh.longValue();
}

thresh = getLongOption(props, "log4jdbc.sqltiming.error.threshold");
SqlTimingErrorThresholdEnabled = thresh != null;
if (SqlTimingErrorThresholdEnabled)
{
  SqlTimingErrorThresholdMsec = thresh.longValue();
}

DumpBooleanAsTrueFalse = getBooleanOption(props, "log4jdbc.dump.booleanastruefalse", false);

DumpSqlMaxLineLength = getLongOption(props, "log4jdbc.dump.sql.maxlinelength", 90L).intValue();

DumpFullDebugStackTrace = getBooleanOption(props, "log4jdbc.dump.fulldebugstacktrace", false);

StatementUsageWarn = getBooleanOption(props, "log4jdbc.statement.warn", false);

DumpSqlSelect = getBooleanOption(props, "log4jdbc.dump.sql.select", true);
DumpSqlInsert = getBooleanOption(props, "log4jdbc.dump.sql.insert", true);
DumpSqlUpdate = getBooleanOption(props, "log4jdbc.dump.sql.update", true);
DumpSqlDelete = getBooleanOption(props, "log4jdbc.dump.sql.delete", true);
DumpSqlCreate = getBooleanOption(props, "log4jdbc.dump.sql.create", true);

DumpSqlFilteringOn = (!DumpSqlSelect) || (!DumpSqlInsert) || (!DumpSqlUpdate) || (!DumpSqlDelete) || (!DumpSqlCreate);

//......




折腾了半天,发现回到了原点。-_-|||
其实在
页面上都有options的说明,(为了避免大家一起爬墙,贴出来如下):
log4jdbc-log4j2  options
property default description
log4jdbc.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.drivers true Set 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.booleanastruefalse false When 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.maxlinelength 90 When 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.fulldebugstacktrace false If 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.select true Set 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.insert true Set 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.update true Set 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.delete true Set 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.create true Set 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.addsemicolon false Set 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.name net.sf.log4jdbc.log.log4j2.Log4j2SpyLogDelegator The 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.warn false Set 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.sql true Set this to false to not trim the logged SQL. (Previous versions always trimmed the SQL.)
log4jdbc.trim.sql.extrablanklines true Set 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.exception false Set 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:

property default description
log4jdbc.log4j2.properties.file log4jdbc.log4j2.properties Set the name of the property file to use 


log4jdbc
property default description since
log4jdbc.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.0
log4jdbc.auto.load.popular.drivers true Set 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.2beta2
log4jdbc.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.0
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.)
1.1beta1
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.)
1.1beta1
log4jdbc.dump.booleanastruefalse false When 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.2alpha1
log4jdbc.dump.sql.maxlinelength 90 When 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.2alpha1
log4jdbc.dump.fulldebugstacktrace false If 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.2alpha1
log4jdbc.dump.sql.select true Set this to false to suppress SQL select statements in the output. 1.2alpha1
log4jdbc.dump.sql.insert true Set this to false to suppress SQL insert statements in the output. 1.2alpha1
log4jdbc.dump.sql.update true Set this to false to suppress SQL update statements in the output. 1.2alpha1
log4jdbc.dump.sql.delete true Set this to false to suppress SQL delete statements in the output. 1.2alpha1
log4jdbc.dump.sql.create true Set this to false to suppress SQL create statements in the output. 1.2alpha1
log4jdbc.dump.sql.addsemicolon false Set 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.2alpha1
log4jdbc.statement.warn false Set 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.2alpha2
log4jdbc.trim.sql true Set this to false to not trim the logged SQL. (Previous versions always trimmed the SQL.) 1.2beta2
log4jdbc.trim.sql.extrablanklines true Set 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.2
log4jdbc.suppress.generated.keys.exception false Set 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'。

打包请参考:
  • 2
    点赞
  • 4
    收藏
    觉得还不错? 一键收藏
  • 1
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论 1
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值