系統(tǒng)都是逐漸演進(jìn)的，一個(gè)系統(tǒng)在運(yùn)行中必須是根據(jù)場(chǎng)景逐漸地提高優(yōu)化性能。高并發(fā)就是對(duì)資源的節(jié)約的考驗(yàn)，這種考驗(yàn)除了更換優(yōu)秀和先進(jìn)的技術(shù)，優(yōu)化架構(gòu)，還在于從小處出發(fā)，對(duì)盡可能節(jié)約的資源進(jìn)行節(jié)約。
而在一個(gè)系統(tǒng)的數(shù)據(jù)訪問中，系統(tǒng)的瓶頸往往是來自于數(shù)據(jù)庫(kù)，因此我們要盡可能減少對(duì)數(shù)據(jù)庫(kù)的訪問！
一、背景
有沒有遇到這種情況，領(lǐng)導(dǎo)突然安排一件事情：這幾個(gè)接口壓測(cè)指標(biāo)太低需要針對(duì)性優(yōu)化一下。
當(dāng)然理想的情況下你對(duì)業(yè)務(wù)場(chǎng)景非常熟悉，可以大概定位問題來分析業(yè)務(wù)精準(zhǔn)評(píng)估哪些 SQL 會(huì)有性能瓶頸。
然后開始百度：如何提高 SQL 執(zhí)行效率？
通過 explain、show profile 和 trace 等診斷工具來分析慢查詢。
但是大多數(shù)情況下業(yè)務(wù)線過長(zhǎng)，不可能一個(gè)人完成。涉及到各種策略模式、監(jiān)聽動(dòng)作。想直接定位到點(diǎn)還是需要輸出請(qǐng)求發(fā)起后所觸發(fā)的執(zhí)行的 SQL 以及執(zhí)行效率。這里效率單單指代 SQL 執(zhí)行的時(shí)間。
目標(biāo)明確后開始整活吧。
二、添加 JDBC 追蹤
繼續(xù)前一篇文章的話題：如何利用好日志鏈路追蹤做性能分析？
? SQL 執(zhí)行時(shí)間公式
要想處理此類問題首先的分析，SQL 執(zhí)行時(shí)間計(jì)算如何來劃分？SQL 的語句執(zhí)行過程大致如下圖所示。
如果想統(tǒng)計(jì) SQL 執(zhí)行時(shí)間。所以對(duì)于程序而言可以得到粗略公式
SQL執(zhí)行時(shí)間=提取數(shù)據(jù)之后時(shí)間-語法解析開始時(shí)間
復(fù)制代碼
? 添加增加 JDBC 追蹤
閱讀過 Hibernate 或者 MyBatis 等持久化框架的應(yīng)該比較了解 Statement 位于 java.sql 基礎(chǔ)包下
Statement 提供了用于執(zhí)行靜態(tài) SQL 語句并返回它產(chǎn)生的結(jié)果的對(duì)象。默認(rèn)情況下，每個(gè) Statement 對(duì)象只能同時(shí)打開一個(gè) ResultSet 對(duì)象。
因此，如果一個(gè) ResultSet 對(duì)象的讀取與另一個(gè)的讀取交錯(cuò)，則每個(gè)對(duì)象都必須由不同的 Statement 對(duì)象生成。如果存在打開的對(duì)象，則 Statement 接口中的所有執(zhí)行方法都會(huì)隱式關(guān)閉該 Statement 的當(dāng)前 ResultSet 對(duì)象。
繼續(xù)查看源碼可以發(fā)現(xiàn)在 Statement 提供了用于執(zhí)行方法后，PreparedStatement 預(yù)編譯 SQL 語句的對(duì)象。SQL 語句被預(yù)編譯并存儲(chǔ)在 PreparedStatement 對(duì)象中。然后可以使用此對(duì)象多次有效地執(zhí)行此語句。
為了驗(yàn)證這個(gè)思路，可以借鑒其他定制化數(shù)據(jù)庫(kù)驅(qū)動(dòng)。
定義 StatementWraper 實(shí)現(xiàn) Statement 提供了用于執(zhí)行靜態(tài) SQL 語句并返回它產(chǎn)生的結(jié)果的對(duì)象。
記錄日志詳情
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);
}
}
....
這樣就有了文章開頭的程序執(zhí)行過程中鎖觸發(fā)的 SQL 執(zhí)行耗時(shí)情況。
同理定義 PreparedStatementWraper 實(shí)現(xiàn) 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 組件進(jìn)行日志采集
對(duì)這類問題先前有做介紹
