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 类，因为这个类有


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);

//......

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

其实在

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

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

页面上都有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‘。

打包请参考：

maven多环境打包配置

时间： 2024-10-03 01:42:18

log4jdbc实现慢查询sql记录的相关文章

mysql-关联查询sql记录

//查询账单关联订单 select o.id as id, o.order_no as orderNo, o.case_no as caseNo, o.send_time as sendTime, o.final_time as finalTime, (select ca.car_no from fm_order_case ca where ca.case_no = o.case_no) as carNo, (select co.service_money from fm_order_cost

查询SQLSERVER执行过的SQL记录

原文:查询SQLSERVER执行过的SQL记录 有的时候,需要知道SQLSERVER执行了什么语句,可以用下面的方法: SELECT TOP 1000 --创建时间 QS.creation_time, --查询语句 SUBSTRING(ST.text,(QS.statement_start_offset/2)+1, ((CASE QS.statement_end_offset WHEN -1 THEN DATALENGTH(st.text) ELSE QS.statement_end_offse

sql查询重复记录的方法

1.查找表中多余的重复记录,重复记录是根据单个字段(peopleId)来判断 select * from people  where peopleId in (select peopleId from people group by peopleId having count(peopleId) > 1) 2.查找表中多个字段的重复记录 select * from vitae a where (a.peopleId,a.seq) in (select peopleId,seq from vita

sql查询重复记录、删除重复记录方法大全

1.查询重复记录单字段 select * from tbl a where  exists(select 1 from  tbl b where a.username=b.username group by username  having count(*) > 1) 2.查询重复次数 select clistname,count(clistname) from clalist  group by clistname having count(*)>1 3.删除重复记录,留有rowid最小的记

sql查询总记录以及 查询每条光缆下的所涉及到表的信息

/*光缆有条少条隐患1,查询光缆表Optic_Cable, 2,根据光缆表关联的光缆巡检(轨迹巡检)的路线查标石(Optic_LinePat轨迹的路线名称),(Optic_LinePat_Sub,轨迹路线下的标石),3,然后根据标石关联巡检信息表中这个标石的所有隐患次数(Optic_LinePat_Rec巡检产生的信息表,根据上面查询到的标石进行隐患匹配)*/select a.光缆条数 as glcount,a.光缆长度 as gllength,b.正常端口 as yesdk,b.损坏端口 as

mysql如何配置sql记录

原文链接:http://www.qqdeveloper.com/detail/11/1.html 为什么要记录sql记录 主要目的是为了检测我们的网站安全问题,有效的避免一些sql注入或者是xss攻击. 如何实现 这里主要以windows系统中的my.ini文件为例,Linux系统的配置文件是my.conf,本例中以5.6为例. ?方式一 ?    ?log = "D:/wamp64/logs/mysql.log" // 日子记录文件 ?    ?log_slow_queries =

009-Hadoop Hive sql语法详解4-DQL 操作:数据查询SQL

1 基本的Select 操作 SELECT [ALL | DISTINCT] select_expr, select_expr, ...FROM table_reference[WHERE where_condition][GROUP BY col_list [HAVING condition]][   CLUSTER BY col_list  | [DISTRIBUTE BY col_list] [SORT BY| ORDER BY col_list] [LIMIT number]•使用ALL

基本的查询sql语句

day03  基本的查询sql语句 一.概述: 学习MySQL数据库中一定要学会sql的查询功能,说白了,使用数据库就是存储数据,查询数据,使用这些数据的一个过程.只有查看了才知道我们是否存储成功,是否可以直接使用这些数据. 二.具体的sql 1.查询数据库的基本语法:         select 需要查询的字段名和内容         from  指定相关的表名         where  查询时所需要的条件         group by  如何对结果分组         order 

Mssql 查询某记录前后N条

Sqlserver 查询指定记录前后N条,包括当前数据 条件 [ID] 查询 [N]条 select * from [Table] where ID in (select top ([N]+1) ID from [Table] where id <=[ID] order by id descunionselect top [N] ID from [Table] where id>[ID] order by id )order by ID 例如:有数据表 A id    name    date