log4jdbc之sql执行时间日志记录原理解析

log4jdbc可以用来记录sql执行日志，该文就我们常使用的sql执行信息日志（jdbc.sqltiming ）原理进行分析：

使用步骤：

1.需要在pom文件添加依赖：

<dependency>
<groupId>com.googlecode.log4jdbc</groupId>
<artifactId>log4jdbc</artifactId>
<scope>runtime</scope>
</dependency>

<!--log4jdbc使用slf4j用来记录日志-->
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
</dependency>

<!--底层使用logback记录日志-->

<dependency><groupId>ch.qos.logback</groupId><artifactId>logback-classic</artifactId><scope>runtime</scope></dependency>

工作原理：

1.下面看下log4jdbc中的相关类：



我们经常看到的sql执行时间信息：

13:25:31.736 [1659326468@qtp-1849186564-196] INFO  jdbc.sqltiming - select 1 

 {executed in 0 msec}

就是在StatementSpy类中打印出来的，现在我们看下该类的定义：

public class StatementSpy implements Statement, Spy

{

  protected final SpyLogDelegator log;

  /**

   * 创建statement的connection类.

   */

  protected ConnectionSpy connectionSpy;

  /**

   * The real statement that this StatementSpy wraps.

   */

  protected Statement realStatement;

//执行sql的方法

  public boolean execute(String sql, String[] columnNames) throws SQLException
  {
    String methodCall = "execute(" + sql + ", " + columnNames + ")";
    reportStatementSql(sql, methodCall);
    long tstart = System.currentTimeMillis();
    try
    {

//调用Statement类的execute方法执行sql语句

      boolean result = realStatement.execute(sql, columnNames);

//打印sql执行时间信息

      reportStatementSqlTiming(System.currentTimeMillis() - tstart, sql, methodCall);
      return reportReturn(methodCall, result);
    }
    catch (SQLException s)
    {
      reportException(methodCall, s, sql, System.currentTimeMillis() - tstart);
      throw s;
    }
  }