如何利用日志链路追踪程序执行的慢SQL？
导读：查看SQL的执行效率，不难想到使用explain分析慢查询，但是前提是你需要非常了解业务背景。否则很难精准定位到。
系统都是逐渐演进的，一个系统在运行中必须是根据场景逐渐地提高优化性能。高并发就是对资源的节约的考验，这种考验除了更换优秀和先进的技术，优化架构，还在于从小处出发，对尽可能节约的资源进行节约。
而在一个系统的数据访问中，系统的瓶颈往往是来自于数据库，因此我们要尽可能减少对数据库的访问！
一、背景
有没有遇到这种情况，领导突然安排一件事情：这几个接口压测指标太低需要针对性优化一下。
当然理想的情况下你对业务场景非常熟悉，可以大概定位问题来分析业务精准评估哪些SQL会有性能瓶颈。
然后开始百度：如何提高SQL执行效率？
通过 explain、show profile 和 trace 等诊断工具来分析慢查询。
但是大多数情况下业务线过长，不可能一个人完成。涉及到各种策略模式、监听动作。想直接定位到点还是需要输出请求发起后所触发的执行的SQL以及执行效率。这里效率单单指代SQL执行的时间。
目标明确后开始整活吧。
二、添加JDBC追踪
继续前一篇文章的话题：如何利用好日志链路追踪做性能分析？
▐ SQL执行时间公式
要想处理此类问题首先的分析，SQL执行时间计算如何来划分？SQL的语句执行过程大致如下图所示。
如果想统计SQL执行时间。所以对于程序而言可以得到粗略公式
SQL执行时间=提取数据之后时间-语法解析开始时间▐ 添加增加JDBC追踪
阅读过Hibernate或者MyBatis等持久化框架的应该比较了解Statement位于java.sql基础包下
Statement提供了用于执行静态 SQL 语句并返回它产生的结果的对象。默认情况下，每个Statement对象只能同时打开一个ResultSet对象。
因此，如果一个ResultSet对象的读取与另一个的读取交错，则每个对象都必须由不同的Statement对象生成。如果存在打开的对象，则Statement接口中的所有执行方法都会隐式关闭该Statement的当前ResultSet对象。
继续查看源码可以发现在Statement提供了用于执行方法后，PreparedStatement预编译 SQL语句的对象。SQL 语句被预编译并存储在PreparedStatement对象中。然后可以使用此对象多次有效地执行此语句。
为了验证这个思路，可以借鉴其他定制化数据库驱动。
定义StatementWraper实现Statement提供了用于执行静态 SQL 语句并返回它产生的结果的对象。
记录日志详情
public class StatementWraper implements Statement {
private Statement raw;
public StatementWraper(Statement raw) {
super();
this.raw = raw;
}
/**
* 记录日志
*/
protected void doLog(String opt, String sql, long startTime) {
if (sql != null) {
sql = sql.replaceAll("\\\\s+", " ");
}
TraceUtil.log(StringHelper.join(
"dt：", System.currentTimeMillis() - startTime,
"，TRACE-JDBC：", opt,
"，SQL：",sql));
}
// ========== 记录日志 ==========
@Override
public ResultSet executeQuery(String sql) throws SQLException {
long startTime = System.currentTimeMillis();
try {
return raw.executeQuery(sql);
} finally {
doLog("executeQuery", sql, startTime);
}
}
....
这样就有了文章开头的程序执行过程中锁触发的SQL执行耗时情况。
同理定义PreparedStatementWraper实现PreparedStatement
public class PreparedStatementWraper extends StatementWraper
implements PreparedStatement {
private PreparedStatement raw;
private String sql;
public PreparedStatementWraper(PreparedStatement raw, String sql) {
super(raw);
this.raw = raw;
this.sql = sql;
}
// ========== 记录日志 ==========
@Override
public ResultSet executeQuery() throws SQLException {
long startTime = System.currentTimeMillis();
try {
return raw.executeQuery();
} finally {
doLog("executeQuery", sql, startTime);
}
}
....
最后日志输出使用logback组件进行日志采集
对这类问题先前有做介绍
