码迷,mamicode.com
首页 > 数据库 > 详细

log4jdbc实现慢查询sql记录

时间:2015-06-16 16:45:47      阅读:264      评论:0      收藏:0      [点我收藏+]

标签:log4jdbc   慢查询   sql优化   

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

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

这次使用的是:
<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));
        }
      }
    }
  }

execTime sql ,感觉这事要成了。正准备修改,我靠,怎么会有  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‘。

打包请参考:

log4jdbc实现慢查询sql记录

标签:log4jdbc   慢查询   sql优化   

原文地址:http://blog.csdn.net/ycpanda/article/details/46519941

(0)
(0)
   
举报
评论 一句话评论(0
登录后才能评论!
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码!