java收集sql监控_java笔记：自己动手写javaEE框架（三）--引入SQL监控技术P6spy

软件151 黄旭 1531610120

任何系统里，日志和一定的监控是相当重要的，在一个软件整个生命周期里维护永远是大头同时是痛苦的，而日志和监控就是为后期维护提供了良好的基础和手段，在java工程里面大多使用log4j来记录系统日志，这个技术几乎所有的java工程师都很熟悉，不太明白了，大家可以查查百度。这里我打算引入一个能监控JDBC执行语句的框架到我写的java框架里面，这个框架非常的好用，他就是p6spy。

“如果优化SQL语句,如何进行系统调优”，这样的问题我想很多程序员都听到过，优化和调优是一个高难度的技术技能，只有具有扎实的技术功底和多年的项目经验才把他做好。我以前遇到这样的提问，思路很机械，都是从SQL语法，索引，分区，算法来考虑，其实优化和调优程序环境的搭配也是很重要的，例如，现在做java企业级项目，大多使用了orm技术，很少会直接去用jdbc操作数据库，而orm技术对jdbc的封装让最终执行的sql语句的原型离程序员越来越远，因此对jbdc执行的原生态的sql语句的掌控是相当重要的。

在这里我可以分享一下我的经验。我现在比较推崇ibatis，它既实现了orm思想，又保留了sql语句的使用而不是像hibernate那样对数据库做完全面向对象的映射，而产生了很多新的东西，比如hql。这是一个简便的设计，我觉得系统设计最佳的方案就是新老兼容。其实不同的程序员擅长的技术也不同，做java的程序员当然对java更熟悉，开发数据库的程序员对数据库很在行，假如你现在开发一个后台数据库数据量很大，业务操作很复杂的系统，我这里会首推ibatis技术做orm层，因为这样的大系统到了数据库层面和dba打交道很多，对sql语句以及数据库优化很多，而ibatis直接写sql语句的优点就很明显了，java程序员和dba的沟通和程序的交互也就方便多了。我最近做了几个这样的系统，系统做完后我都会把重要的sql语句从系统里抽取出来给dba优化，而dba优化后我基本只要拷贝到程序里就可以，为整个工作带来了便利。此外系统上线，如果操作数据库报错，在日志里提取sql语句，进行检查，检查后维护程序也是有很大的便利，最后用sql嵌入orm，程序架构的变迁所带来的问题也会少很多，因此我以后开发系统orm技术的首选就是ibatis了。

但是ibatis执行jdbc是使用prepareStatement，所以最终打印出来的sql语句是下面的格式：

2011-10-13 11:17:36 Connection - {conn-100000} Connection

2011-10-13 11:17:36 Connection - {conn-100000} Preparing Statement: select t.username,t.password,t.enabled from users t where t.username = ?

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Executing Statement: select t.username,t.password,t.enabled from users t where t.username = ?

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Parameters: [sharpxiajun]

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Types: [java.lang.String]

我们拷贝出sql语句还要改写，真是烦死人了，那么p6spy就能解决这个问题，它会把?替换成参数，看看我加入了p6spy后执行的效果吧。

|statement| select t.username,t.password,t.enabled from users t where t.username = 'sharpxiajun'

P6spy使用很简单，只要完成下面步骤就行：

1.将p6spy.jar包放到应用的classpath所在的路径中；

2.修改连接池或者连接配置的jdbc的驱动为p6spy所提供的保证后的驱动，com.p6spy.engine.spy.P6SpyDriver

3.修改spy.properties并将其放到类搜索目录.

下面我们开始开发了。

1.新的工程结构图如下：

新添两个jar包：log4j-1.2.12.jar和p6spy.jar

2.将log4j.properties和spy.properties拷贝到src下面(暂时拷贝到src下面，其实应该放到conf下面，因为现在都是在本地测试，没有发布到tomcat下面，就把两个文件拷贝到默认的路径下)

log4j.properties内容如下：

log4j.debug=true

log4j.rootLogger=INFO,CONSOLE,STDOUT

#-----CONSOLE-----

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender

log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout

log4j.appender.CONSOLE.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %c{1} - %m%n

#-----SQL LOG-----

log4j.logger.java.sql.Connection=DEBUG

log4j.logger.java.sql.Statement=DEBUG

log4j.logger.java.sql.PreparedStatement=DEBUG

log4j.logger.com.ibatis=debug

log4j.logger.com.ibatis.common.jdbc.SimpleDataSource=debug

log4j.logger.com.ibatis.common.jdbc.ScriptRunner=debug

log4j.logger.com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate=debug

日志打印到控制台里，SQL LOG下的配置表示打印出jbdc以及ibatis的日志。

spy.properties内容如下：

module.log=com.p6spy.engine.logging.P6LogFactory

realdriver=oracle.jdbc.driver.OracleDriver

deregisterdrivers=true

executionthreshold=

outagedetection=false

outagedetectioninterval=

filter=false

include =

exclude =

sqlexpression =

autoflush = true

dateformat=

includecategories=

excludecategories=info,debug,result,batch

stringmatcher=

stacktrace=false

stacktraceclass=

reloadproperties=false

reloadpropertiesinterval=60

useprefix=false

appender=com.p6spy.engine.logging.appender.StdoutLogger

append=true

log4j.appender.STDOUT=org.apache.log4j.ConsoleAppender

log4j.appender.STDOUT.layout=org.apache.log4j.SimpleLayout

log4j.appender.STDOUT.layout.ConversionPattern=p6spy

log4j.logger.p6spy=DEBUG,STDOUT

这里只要修改下realdriver=oracle.jdbc.driver.OracleDriver就行。

3.接下来我们只要更改下数据库的驱动就行了，修改下constants.properties，内容如下：

#db.driverClass = oracle.jdbc.driver.OracleDriver

db.driverClass = com.p6spy.engine.spy.P6SpyDriver

db.user = sharpxiajun

db.password = sharpxiajun

db.jdbcUrl = jdbc:oracle:thin:@127.0.0.1:1521:orcl

#db.driverClass = com.mysql.jdbc.Driver

#db.user = root

#db.password = root

#db.jdbcUrl = jdbc\:mysql\://localhost\:3306/sq_xidi?useUnicode\=true&characterEncoding\=utf-8

4.最后修改下USERS.xml配置文件，让查询方法接收到参数，如下：

select t.username,t.password,t.enabled from users t

t.username = #username#

执行结果如下：

log4j: Parsing for [root] with value=[INFO,CONSOLE,STDOUT].

log4j: Level token is [INFO].

log4j: Category root set to INFO

log4j: Parsing appender named "CONSOLE".

log4j: Parsing layout options for "CONSOLE".

log4j: Setting property [conversionPattern] to [%d{yyyy-MM-dd HH:mm:ss} %c{1} - %m%n].

log4j: End of parsing for "CONSOLE".

log4j: Parsed "CONSOLE" options.

log4j: Parsing appender named "STDOUT".

log4j:ERROR Could not find value for key log4j.appender.STDOUT

log4j:ERROR Could not instantiate appender named "STDOUT".

log4j: Parsing for [com.ibatis.common.jdbc.SimpleDataSource] with value=[debug].

log4j: Level token is [debug].

log4j: Category com.ibatis.common.jdbc.SimpleDataSource set to DEBUG

log4j: Handling log4j.additivity.com.ibatis.common.jdbc.SimpleDataSource=[null]

log4j: Parsing for [java.sql.Connection] with value=[DEBUG].

log4j: Level token is [DEBUG].

log4j: Category java.sql.Connection set to DEBUG

log4j: Handling log4j.additivity.java.sql.Connection=[null]

log4j: Parsing for [com.ibatis] with value=[debug].

log4j: Level token is [debug].

log4j: Category com.ibatis set to DEBUG

log4j: Handling log4j.additivity.com.ibatis=[null]

log4j: Parsing for [java.sql.Statement] with value=[DEBUG].

log4j: Level token is [DEBUG].

log4j: Category java.sql.Statement set to DEBUG

log4j: Handling log4j.additivity.java.sql.Statement=[null]

log4j: Parsing for [com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate] with value=[debug].

log4j: Level token is [debug].

log4j: Category com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate set to DEBUG

log4j: Handling log4j.additivity.com.ibatis.sqlmap.engine.impl.SqlMapClientDelegate=[null]

log4j: Parsing for [com.ibatis.common.jdbc.ScriptRunner] with value=[debug].

log4j: Level token is [debug].

log4j: Category com.ibatis.common.jdbc.ScriptRunner set to DEBUG

log4j: Handling log4j.additivity.com.ibatis.common.jdbc.ScriptRunner=[null]

log4j: Parsing for [java.sql.PreparedStatement] with value=[DEBUG].

log4j: Level token is [DEBUG].

log4j: Category java.sql.PreparedStatement set to DEBUG

log4j: Handling log4j.additivity.java.sql.PreparedStatement=[null]

log4j: Finished configuring.

初始化测试类....

2011-10-13 11:17:35 XmlBeanDefinitionReader - Loading XML bean definitions from class path resource [conf/applicationContext.xml]

2011-10-13 11:17:35 GenericApplicationContext - Refreshing org.springframework.context.support.GenericApplicationContext@2808b3: startup date [Thu Oct 13 11:17:35 CST 2011]; root of context hierarchy

2011-10-13 11:17:35 PropertyPlaceholderConfigurer - Loading properties file from class path resource [conf/constants.properties]

2011-10-13 11:17:35 DefaultListableBeanFactory - Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@1de17f4: defining beans [usersDao,userService,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,propertyConfigurer,myDataSource,sqlMapClient,sqlMapClientTemplate,transactionManager,methodServiceAdvisor,org.springframework.aop.config.internalAutoProxyCreator,baseServiceMethods,org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0]; root of factory hierarchy

2011-10-13 11:17:35 MLog - MLog clients using log4j logging.

2011-10-13 11:17:35 C3P0Registry - Initializing c3p0-0.9.1.2 [built 21-May-2007 15:04:56; debug? true; trace: 10]

2011-10-13 11:17:36 AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 0, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> 2wyjv28i1xq0ktewu9ral|131303f, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> com.p6spy.engine.spy.P6SpyDriver, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 2wyjv28i1xq0ktewu9ral|131303f, idleConnectionTestPeriod -> 0, initialPoolSize -> 3, jdbcUrl -> jdbc:oracle:thin:@127.0.0.1:1521:orcl, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 0, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 15, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 3, numHelperThreads -> 3, numThreadsAwaitingCheckoutDefaultUser -> 0, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, usesTraditionalReflectiveProxies -> false ]

2011-10-13 11:17:36 TransactionalTestExecutionListener - Began transaction (1): transaction manager [org.springframework.jdbc.datasource.DataSourceTransactionManager@6db33c]; rollback [false]

测试开始....

进入到了方法拦截器。。。。

调用的service：

cn.com.sharpxiajun.service.impl.UsersServiceImpl@23bdd1

调用的方法:

public abstract java.util.List cn.com.sharpxiajun.service.UsersService.queryUsersList(java.util.Map) throws java.lang.Exception

参数是：

{username=sharpxiajun}

2011-10-13 11:17:36 Connection - {conn-100000} Connection

2011-10-13 11:17:36 Connection - {conn-100000} Preparing Statement: select t.username,t.password,t.enabled from users t where t.username = ?

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Executing Statement: select t.username,t.password,t.enabled from users t where t.username = ?

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Parameters: [sharpxiajun]

2011-10-13 11:17:36 PreparedStatement - {pstm-100001} Types: [java.lang.String]

|statement| select t.username,t.password,t.enabled from users t where t.username = 'sharpxiajun'

返回结果是:

[]

拦截器执行结束!!

[]

测试结束!!

|commit|

2011-10-13 11:17:36 TransactionalTestExecutionListener - Committed transaction after test execution for test context [[TestContext@1fac852 testClass = UsersServiceImplTest, locations = array['classpath:conf/applicationContext.xml'], testInstance = cn.com.sharpxiajun.junittest.service.UsersServiceImplTest@1758cd1, testMethod = testQueryUserList@UsersServiceImplTest, testException = [null]]]

2011-10-13 11:17:36 GenericApplicationContext - Closing org.springframework.context.support.GenericApplicationContext@2808b3: startup date [Thu Oct 13 11:17:35 CST 2011]; root of context hierarchy

2011-10-13 11:17:36 DefaultListableBeanFactory - Destroying singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@1de17f4: defining beans [usersDao,userService,org.springframework.context.annotation.internalConfigurationAnnotationProcessor,org.springframework.context.annotation.internalAutowiredAnnotationProcessor,org.springframework.context.annotation.internalRequiredAnnotationProcessor,org.springframework.context.annotation.internalCommonAnnotationProcessor,propertyConfigurer,myDataSource,sqlMapClient,sqlMapClientTemplate,transactionManager,methodServiceAdvisor,org.springframework.aop.config.internalAutoProxyCreator,baseServiceMethods,org.springframework.aop.support.DefaultBeanFactoryPointcutAdvisor#0]; root of factory hierarchy