How does Java use the MySQL driver interceptor to implement SQL time-consuming calculations?

Background

One of the company's requirements is that the company's existing link tracking log component must support MySQL's sql execution time printing. The common method to implement link tracking is to implement third-party frameworks or tools. The interceptor interface or filter interface is no exception for MySQL. In fact, it just implements the interceptor interface driven by MySQL.

Specific implementation

MySQL channels have different versions, and the interceptor interfaces of different versions are different, so you need to implement the response interceptor according to the different versions of the MySQL driver you are using. , Next, we will introduce the implementation methods of MySQL channel 5, 6, and 8 respectively.

MySQL5

Here we take the MySQL channel 5.1.18 version as an example to implement the StatementInterceptorV2 interface. The main implementation logic is in preProcess and postProcess method, these two methods are methods to be executed before and after SQL execution. The framework I use is logback. MDC is used here to record a timestamp before SQL execution. The code is in the postProcess method. MDC.put("sql_exec_time", start);, you can also use ThreadLocal, etc. to implement it, and then use MDC.get("sql_exec_time") in the postProcess method Take out the recorded time before sql execution, and finally subtract the time before sql execution from the current timestamp to calculate the sql execution time.

import static net.logstash.logback.marker.Markers.append;

import com.mysql.jdbc.Connection;
import com.mysql.jdbc.ResultSetInternalMethods;
import com.mysql.jdbc.Statement;
import com.mysql.jdbc.StatementInterceptorV2;
import com.redick.util.LogUtil;
import java.sql.SQLException;
import java.util.Properties;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;

/**
 * @author Redick01
 */
@Slf4j
public class Mysql5StatementInterceptor implements StatementInterceptorV2 {

    @Override
    public void init(Connection connection, Properties properties) throws SQLException {

    }

    @Override
    public ResultSetInternalMethods preProcess(String s, Statement statement, Connection connection)
            throws SQLException {
        String start = String.valueOf(System.currentTimeMillis());
        MDC.put("sql_exec_time", start);
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_before"), "开始执行sql");
        return null;
    }

    @Override
    public boolean executeTopLevelOnly() {
        return false;
    }

    @Override
    public void destroy() {

    }

    @Override
    public ResultSetInternalMethods postProcess(String s, Statement statement,
            ResultSetInternalMethods resultSetInternalMethods, Connection connection, int i,
            boolean b, boolean b1, SQLException e) throws SQLException {
        long start = Long.parseLong(MDC.get("sql_exec_time"));
        long end = System.currentTimeMillis();
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_after")
                .and(append(LogUtil.kLOG_KEY_SQL_EXEC_DURATION, end - start)), "结束执行sql");
        return null;
    }
}

MySQL6

MySQL6 and MySQL5 are basically the same, but the interface is not the same, just put the code directly

import static net.logstash.logback.marker.Markers.append;

import com.mysql.cj.api.MysqlConnection;
import com.mysql.cj.api.jdbc.Statement;
import com.mysql.cj.api.jdbc.interceptors.StatementInterceptor;
import com.mysql.cj.api.log.Log;
import com.mysql.cj.api.mysqla.result.Resultset;
import com.redick.util.LogUtil;
import java.sql.SQLException;
import java.util.Properties;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;

/**
 * @author Redick01
 */
@Slf4j
public class Mysql6StatementInterceptor implements StatementInterceptor {

    @Override
    public StatementInterceptor init(MysqlConnection mysqlConnection, Properties properties,
            Log log) {
        return null;
    }

    @Override
    public <T extends Resultset> T preProcess(String s, Statement statement) throws SQLException {
        String start = String.valueOf(System.currentTimeMillis());
        MDC.put("sql_exec_time", start);
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_before"), "开始执行sql");
        return null;
    }

    @Override
    public boolean executeTopLevelOnly() {
        return false;
    }

    @Override
    public void destroy() {

    }

    @Override
    public <T extends Resultset> T postProcess(String s, Statement statement, T t, int i, boolean b,
            boolean b1, Exception e) throws SQLException {
        long start = Long.parseLong(MDC.get("sql_exec_time"));
        long end = System.currentTimeMillis();
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_after")
                .and(append(LogUtil.kLOG_KEY_SQL_EXEC_DURATION, end - start)), "结束执行sql");
        return null;
    }
}

MySQL8

Interception of MySQL8 and MySQL5/6 The interceptor interface is different again. The interceptor interface of MySQL8 is com.mysql.cj.interceptors.QueryInterceptor. The method of counting sql execution time is still the same. The code is as follows:

import static net.logstash.logback.marker.Markers.append;

import com.mysql.cj.MysqlConnection;
import com.mysql.cj.Query;
import com.mysql.cj.interceptors.QueryInterceptor;
import com.mysql.cj.log.Log;
import com.mysql.cj.protocol.Resultset;
import com.mysql.cj.protocol.ServerSession;
import com.redick.util.LogUtil;
import java.util.Properties;
import java.util.function.Supplier;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;

/**
 * @author Redick01
 */
@Slf4j
public class Mysql8QueryInterceptor implements QueryInterceptor {

    @Override
    public QueryInterceptor init(MysqlConnection mysqlConnection, Properties properties, Log log) {
        return null;
    }

    @Override
    public <T extends Resultset> T preProcess(Supplier<String> supplier, Query query) {
        String start = String.valueOf(System.currentTimeMillis());
        MDC.put("sql_exec_time", start);
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_before"), "开始执行sql");
        return null;
    }

    @Override
    public boolean executeTopLevelOnly() {
        return false;
    }

    @Override
    public void destroy() {

    }

    @Override
    public <T extends Resultset> T postProcess(Supplier<String> supplier, Query query, T t,
            ServerSession serverSession) {
        long start = Long.parseLong(MDC.get("sql_exec_time"));
        long end = System.currentTimeMillis();
        log.info(LogUtil.customizeMarker(LogUtil.kLOG_KEY_TRACE_TAG, "sql_exec_after")
                .and(append(LogUtil.kLOG_KEY_SQL_EXEC_DURATION, end - start)), "结束执行sql");
        return null;
    }
}

Use Method

MySQL5 and 6 are used in the same way. Add the following statementInterceptors parameters to the url of the database link. For example:

 url: jdbc:mysql://127.0.0.1:3316/log-helper?useUnicode=true&characterEncoding=UTF8&statementInterceptors=com.redick.support.mysql.Mysql5StatementInterceptor&serverTimezone=CST

MySQL8 adds ## to the url. #queryInterceptorsParameters, for example:

url: jdbc:mysql://127.0.0.1:3316/log-helper?useUnicode=true&characterEncoding=UTF8&queryInterceptors=com.redick.support.mysql.Mysql8QueryInterceptor&serverTimezone=CST

Test results

sql pre-execution log

{"@timestamp":"2023-02-28T17:16:29.234+08:00","@version":"0.0.1","message":"开始执行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-3321-exec-4","level":"INFO","level_value":20000,"traceId":"9ed930dc-4cc6-4719-bf33-9fcb618fd65b","spanId":"1","request_type":"getName","parentId":"0","trace_tag":"sql_exec_before"}

sql post-execution log, sql_duration identification takes 3ms to execute sql

{"@timestamp":"2023-02-28T17:16:29.237+08:00","@version":"0.0.1","message":"结束执行sql","logger_name":"com.redick.support.mysql.Mysql5StatementInterceptor","thread_name":"http-nio-3321-exec-4","level":"INFO","level_value":20000,"traceId":"9ed930dc-4cc6-4719-bf33-9fcb618fd65b","spanId":"1","request_type":"getName","parentId":"0","trace_tag":"sql_exec_after","sql_duration":3}

The above is the detailed content of How does Java use the MySQL driver interceptor to implement SQL time-consuming calculations?. For more information, please follow other related articles on the PHP Chinese website!