用log4jdbc发现性能问题

介绍

• log4jdbc是一个java的jdbc驱动, 可以用于记录SQL日志和SQL执行时间等信息
• log4jdbc使用SLF4J（Simple Logging Facade）作为日志系统, 其特性有:
  • 支持JDBC3和JDBC4
  • 易于配置: 在大部分情况下，只需要改变驱动类名并在现在jdbc url前加上"jdbc:log4", 设置好日志输出级别即可使用
  • 能够自动把SQL变量值加到SQL输出日志中，改进易读性和方便调试
  • 可以生成SQL语句的时间, 以供快速标识出应用程序中执行比较慢的SQL语句
  • 可以生成SQL连接数信息, 以帮助识别连接池/线程问题
  • 支持现有大部分JDBC驱动

使用步骤

• 下载jar包放到lib目录下: log4jdbc4-1.2.jar: 适用于jdk 1.6 & 1.7(或log4jdbc3-1.2.jar: 适用于jdk 1.4 & 1.5)
• 确保lib目录下log4jdbc.jar、log4j.jar、slf4j-api.jar、slf4j-log4j12.jar四个包存在（如果之前lib中存在slf4j-simple.jar需将slf4j-simple.jar移出lib目录）
• 修改当前JDBC driver为net.sf.log4jdbc.DriverSpy，在jdbc url前加上log4jdbc

  • 例如你当前使用的jdbc配置为:

    com.mysql.jdbc.Driver jdbc:mysql://localhost:1527//db-derby-10.2.2.0-bin/databases/MyDatabase
    

  • 将其改为:

    net.sf.log4jdbc.DriverSpyjdbc:log4jdbc:mysql://localhost:1527//db-derby-10.2.2.0-bin/databases/MyDatabase
    

• 选择使用的logger及log级别, 并在log4j.xml(若无log4j.xml配置, 将其放在classpath即可)中设定:
  • 在log4jdbc有5个log级别: DEBUG < INFO WARN ERROR FATAL DEBUG info warn error fatal p>
  • 可以指定log的输出, 我们用到的两个为:
    • 标准输出: ConsoleAppender
    • 打印至文件: FileAppender
• 重启程序, 当程序对mysql有请求时, 便会打出所配置的log

使用log4jdbc发现的问题

• 在sqltiming的log中看到有多处select xxx from xxx where xxx=xxx;的语句, 怀疑此处的逻辑有问题, 找到相应的code, 发现其原因为开发忘记加用户是否已登陆的逻辑

    //格式为：响应时间        请求时刻        sql       
    3       2013-03-21 13:18:52.790 SELECT COUNT(1) FROM GuideGrade WHERE guideId = 8605588 AND userEmail = 'ppppp2001@126.com'
    1       2013-03-21 13:18:52.791 SELECT grade FROM GuideGrade WHERE guideId = 9321748 AND userEmail = '';
    1       2013-03-21 13:18:52.792 UPDATE GuideGrade SET grade = 5, updateTime = '2013-03-21 13:18:52' WHERE guideId = 8585852 AND userEmail = 'dddd2001@163.com'
    1       2013-03-21 13:18:52.793 UPDATE GuideGrade SET grade = 1, updateTime = '2013-03-21 13:18:52' WHERE guideId = 8605588 AND userEmail = 'ppppp2001@126.com'
    1       2013-03-21 13:18:52.802 UPDATE GuideGrade SET grade = 4, updateTime = '2013-03-21 13:18:52' WHERE guideId = 8516797 AND userEmail = 'eeeeeeee@163.com'
    21      2013-03-21 13:18:52.844 SELECT grade FROM GuideGrade WHERE guideId = 8814769 AND userEmail = '';
    1       2013-03-21 13:18:52.853 SELECT grade FROM GuideGrade WHERE guideId = 9249748 AND userEmail = '';
    1       2013-03-21 13:18:52.853 SELECT COUNT(1) FROM UserInfo WHERE userEmail='kkkkkkk@163.com'
    0       2013-03-21 13:18:52.854 SELECT COUNT(1) FROM UserInfo WHERE userEmail='kkkkkkk@163.com'
    0       2013-03-21 13:18:52.856 SELECT COUNT(1) FROM GuideGrade WHERE guideId = 8643419 AND userEmail = 'kkkkkkk@163.com'
    1       2013-03-21 13:18:52.858 UPDATE GuideGrade SET grade = 3, updateTime = '2013-03-21 13:18:52' WHERE guideId = 8643419 AND userEmail = 'kkkkkkk@163.com'
    11      2013-03-21 13:18:52.859 SELECT grade FROM GuideGrade WHERE guideId = 9335835 AND userEmail = '';
    1       2013-03-21 13:18:52.880 SELECT grade FROM GuideGrade WHERE guideId = 9191890 AND userEmail = '';
    2       2013-03-21 13:18:52.883 SELECT grade FROM GuideGrade WHERE guideId = 7653493 AND userEmail = '';
    0       2013-03-21 13:18:52.929 SELECT grade FROM GuideGrade WHERE guideId = 8896489 AND userEmail = '';
    1       2013-03-21 13:18:52.932 SELECT COUNT(1) FROM UserInfo WHERE userEmail='hhhhhhhhhhhh@163.com'
  

• 在sqltiming的log中看到有些语句会重复出现, 怀疑此处的逻辑有问题, 找到相应的code, 发现只需select一次即可

    //格式为：响应时间        请求时刻        sql
    1       2013-03-21 13:18:53.500 SELECT grade FROM GuideGrade WHERE guideId = 8937011 AND userEmail = '';
    1       2013-03-21 13:18:53.541 SELECT COUNT(1) FROM UserInfo WHERE userEmail='xxxxxx8@163.com'
    0       2013-03-21 13:18:53.543 SELECT COUNT(1) FROM UserInfo WHERE userEmail='xxxxxx8@163.com'
    1       2013-03-21 13:18:53.544 SELECT COUNT(1) FROM UserInfo WHERE userEmail='nnnnnnnnn@126.com'
    1       2013-03-21 13:18:53.544 SELECT COUNT(1) FROM UserInfo WHERE userEmail='llllllll@163.com'
    0       2013-03-21 13:18:53.545 SELECT COUNT(1) FROM UserInfo WHERE userEmail='llllllll@163.com'
    1       2013-03-21 13:18:53.546 SELECT COUNT(1) FROM UserInfo WHERE userEmail='nnnnnnnnn@126.com'
  

• 未完待续, 相信你能有更好的分析手段及mysql优化收获

参考资料

• log4jdbc project
• java日志系统
• Analyzing JDBC Logs with log4jdbc