SQL 耗时跟踪

#java #mysql #trace
@Slf4j
public class InspectSqlStackFilter extends FilterEventAdapter {
    private final Set<String> firstStacks = new ConcurrentHashSet<>();

    @Override
    public boolean statement_execute(FilterChain chain, StatementProxy statement, String sql) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            boolean result = super.statement_execute(chain, statement, sql);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public boolean statement_execute(FilterChain chain, StatementProxy statement, String sql, int autoGeneratedKeys) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            boolean result = super.statement_execute(chain, statement, sql, autoGeneratedKeys);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public boolean statement_execute(FilterChain chain, StatementProxy statement, String sql, int[] columnIndexes) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            boolean result = super.statement_execute(chain, statement, sql, columnIndexes);
            doLogAsExecute(chain, statement, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public boolean statement_execute(FilterChain chain, StatementProxy statement, String sql, String[] columnNames) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            boolean result = super.statement_execute(chain, statement, sql, columnNames);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int[] statement_executeBatch(FilterChain chain, StatementProxy statement) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int[] result = super.statement_executeBatch(chain, statement);
            doLogAsExecute(chain, statement, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public ResultSetProxy statement_executeQuery(FilterChain chain, StatementProxy statement, String sql) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            ResultSetProxy result = super.statement_executeQuery(chain, statement, sql);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int statement_executeUpdate(FilterChain chain, StatementProxy statement, String sql) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int result = super.statement_executeUpdate(chain, statement, sql);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int statement_executeUpdate(FilterChain chain, StatementProxy statement, String sql, int autoGeneratedKeys) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int result = super.statement_executeUpdate(chain, statement, sql, autoGeneratedKeys);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int statement_executeUpdate(FilterChain chain, StatementProxy statement, String sql, int[] columnIndexes) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int result = super.statement_executeUpdate(chain, statement, sql, columnIndexes);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int statement_executeUpdate(FilterChain chain, StatementProxy statement, String sql, String[] columnNames) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int result = super.statement_executeUpdate(chain, statement, sql, columnNames);
            doLogAsExecute(chain, statement, sql, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public boolean preparedStatement_execute(FilterChain chain, PreparedStatementProxy statement) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            boolean result = super.preparedStatement_execute(chain, statement);
            doLogAsExecute(chain, statement, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public ResultSetProxy preparedStatement_executeQuery(FilterChain chain, PreparedStatementProxy statement) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            ResultSetProxy result = super.preparedStatement_executeQuery(chain, statement);
            doLogAsExecute(chain, statement, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    @Override
    public int preparedStatement_executeUpdate(FilterChain chain, PreparedStatementProxy statement) throws SQLException {
        try {
            long startTime = System.currentTimeMillis();
            int result = super.preparedStatement_executeUpdate(chain, statement);
            doLogAsExecute(chain, statement, System.currentTimeMillis() - startTime);
            return result;
        } catch (SQLException ex) {
            throw unwrapException(ex, chain, statement);
        }
    }

    private SQLException unwrapException(SQLException ex, FilterChain chain, StatementProxy statement){
        String message = String.format("\nurl -> %s\nsql -> %s\nerros->%s", chain.getDataSource().getUrl(), statement.getLastExecuteSql(), ex.getMessage());
        if (ex instanceof CommunicationsException) {
            Throwable cause = ex.getCause();
            if (cause instanceof SocketTimeoutException) {
                return new SQLException(message, cause);
            } else if (cause instanceof CJCommunicationsException) {
                if (cause.getCause() instanceof SocketTimeoutException) {
                    return new SQLException(message, cause.getCause());
                }
            }
        }
        return new SQLException(message, ex.getCause());
    }

    private void doLogAsExecute(FilterChain chain, StatementProxy statement, long duration) {
        this.doLogAsExecute(chain, statement, null, duration);
    }


    public static void main(String[] args) {
    }

    private void doLogAsExecute(FilterChain chain, StatementProxy statement, String sql, long duration) {


        String applicationName = SpringContextHolder.getApplicationName();
        if (duration < 1000) {
            return;
        }

        if (
                applicationName.startsWith("example-live") ||
                applicationName.startsWith("example-score") ||
                applicationName.startsWith("example-news") ||
                applicationName.startsWith("example-uc") ||
                applicationName.startsWith("example-support") ||
                applicationName.startsWith("example-sms") ||
                applicationName.startsWith("example-integral")
        ) {

            LinkedList<String> lines = new LinkedList<>();

            LinkedList<String> stacks = new LinkedList<>();

            String firstStack = null;
            StackTraceElement[] stackTraces = Thread.currentThread().getStackTrace();
            for (int i = 15; i < stackTraces.length - 1; i++) {
                StackTraceElement stackTrace = stackTraces[i];
                String className = stackTrace.getClassName();
                if (className.startsWith("com.example.base")) {
                    continue;
                }

                if (className.startsWith("com.example")) {
                    if (stackTrace.getLineNumber() == -1) {
                        continue;
                    }
                    int lastPoint = className.lastIndexOf(".");
                    String javaFileName = className.substring(lastPoint + 1);
                    String line = String.format("%s.%s(%s.java:%s)",
                            className, stackTrace.getMethodName(), javaFileName, stackTrace.getLineNumber());

                    if (firstStack == null) {
                        firstStack = line;
                        if (firstStacks.contains(firstStack)) {
                            return;
                        }
                        firstStacks.add(firstStack);
                    }

                    lines.add("\t" + line);
                    stacks.add(line);
                }
                if (className.startsWith("org.springframework.web")) {
                    break;
                }
            }
            try {
                if (lines.isEmpty()) {
                    return;
                }

                lines.addFirst("\nstackTraces: \t");

                if (sql == null) {
                    sql = statement.getLastExecuteSql();
                }
                Map<Integer, JdbcParameter> parameters = statement.getParameters();
                if (!parameters.isEmpty()) {
                    Map<Integer, Object> hashMap = new HashMap<>();
                    for (Map.Entry<Integer, JdbcParameter> entry : parameters.entrySet()) {
                        hashMap.put(entry.getKey(), entry.getValue().getValue());
                    }
                    lines.addFirst("parameters: " + hashMap);
                }
                if (sql != null) {
                    sql = SQLUtils.format(sql, DbType.mysql);
                    lines.addFirst("sql: " + sql);
                    SpringContextHolder.publishEvent(new InspectSqlEvent(sql.replaceAll("\\s+", " "), stacks));
                }

                lines.addFirst("url: " + chain.getDataSource().getUrl());
                lines.addFirst("duration: " + duration + "ms");


                lines.addLast("\n\n-----------------------dividing---------------------\n\n");
                File file = new File("sql_trace_info.txt");
                FileUtils.writeLines(file, "UTF-8", lines, true);

            } catch (IOException ignore) {
            }
        }
    }

}