解Bug之路-記一次中間件致使的慢SQL排查過程

解Bug之路-記一次中間件致使的慢SQL排查過程

前言

最近發現線上出現一個奇葩的問題，這問題讓筆者定位了好長時間，期間排查問題的過程仍是挺有意思的，正好博客也很久不更新了，就以此爲素材寫出了本篇文章。

Bug現場

咱們的分庫分表中間件在通過一年的沉澱以後，已經到了比較穩定的階段。並且通過線上壓測的檢驗，單臺每秒可以執行1.7W條sql。但線上狀況仍是有出乎咱們意料的狀況。有一個業務線反映，天天有幾條sql有長達十幾秒的超時。並且sql是主鍵更新或主鍵查詢，更奇怪的是出現超時的是不一樣的sql,彷佛毫無規律可尋,以下圖所示:

一個值得注意的點，就是此業務只有一部分流量走咱們的中間件，另外一部分仍是直接走數據庫的，而超時的sql只會在連中間件的時候出現，以下圖所示:

很明顯，是引入了中間件以後致使的問題。

排查是否sql確實慢

因爲數據庫中間件只關心sql,並無記錄對應應用的traceId,因此很難將對應的請求和sql對應起來。在這裏，咱們先粗略的統計了在應用端超時的sql的類型是否會有超時的狀況。
分析了日誌，發現那段時間全部的sql在日後端數據執行的時候都只有0.5ms,很是的快。以下圖所示:

看來是中間件和數據庫之間的交互是正常的，那麼繼續排查線索。

尋找超時規律

因爲比較難綁定對應請求和中間件執行sql之間的關係，因而筆者就想着列出全部的異常狀況，看看其時間點是否有規律，以排查一些批處理致使中間件性能降低的現象。下面是某幾條超時sql業務方給出的信息:

業務開始時間	執行sql的應用ip	業務執行耗時(s)
2018-12-24 09:45:24	xx.xx.xx.247	11.75
2018-12-24 12:06:10	xx.xx.xx.240	10.77
2018-12-24 12:07:19	xx.xx.xx.138	13.71
2018-12-24 22:43:07	xx.xx.xx.247	10.77
2018-12-24 22:43:04	xx.xx.xx.245	13.71

看上去貌似沒什麼規律，慢sql存在於不一樣的應用ip之上，排除某臺應用出問題的可能。
超時時間從早上9點到晚上22點都有發現超時，排除了某個點集中性能降低的可能。

注意到一個微小的規律

筆者觀察了一堆數據一段時間，終於發現了一點小規律，以下面兩條所示:

業務開始時間	執行sql的應用ip	業務執行耗時(s)
2018-12-24 22:43:07	xx.xx.xx.247	10.77
2018-12-24 22:43:04	xx.xx.xx.245	13.71

這兩筆sql超時對應的時間點挺接近的，一個是22:43:07,一個是22:43:04,中間只差了3s,而後與後面的業務執行耗時相加，發現更接近了,讓咱們從新整理下:

業務開始時間	執行sql的應用ip	業務執行耗時(s)	業務完成時間(s)
2018-12-24 22:43:07	xx.xx.xx.247	10.77	22:43:17.77
2018-12-24 22:43:04	xx.xx.xx.245	13.71	22.43:17.71

發現這兩筆業務雖然開始時間不一樣，但確是同時完成的，這多是個巧合，也多是bug出現致使的結果。因而繼續看下是否有這些規律的慢sql,讓業務又提供了最近的慢sql,發現這種現象雖然少，可是確實發生了不止一次。筆者忽然感受到，這絕對不是巧合。

由上述規律致使的思考

筆者聯想到咱們中間件有好多臺，假設是中間件那邊卡住的話，若是在那一瞬間，有兩臺sql同時落到同一臺的話，中間件先卡住，而後在中間件恢復的那一瞬間，以0.5ms的速度執行完再返回就會致使這種現象。以下圖所示:

固然了還有另外一種可能，就是sql先以0.5ms的速度執行完，而後中間件那邊卡住了，和上面的區別只是中間件卡的位置不一樣而已，另外一種可能以下圖所示:

是否落到同一臺中間件

線上一共4臺中間件,在經歷了一堆複雜線上日誌撈取分析相對應以後，發現那兩條sql確實落在了同一臺中間件上。爲了保證猜測無誤，又找了兩條符合此規律的sql,一樣的也落在同一臺中間件上面，並且這兩臺中間件並非同一臺，排除某臺機器有問題。以下圖所示:

業務日誌和中間件日誌相對照

在上述發現的基礎上，又經歷了各類日誌分析對應以後，終於找到了耗時sql日誌和業務日誌對應的關聯。而後發現一個關鍵信息。中間件在接收到sql時候會打印一條日誌，發如今應用發出sql到接收到sql還沒來得及作後面的路由邏輯以前就差了10s左右，而後sql執行到返回確是很是快速的，以下圖所示:

查看對應中間件那個時間點其它sql有無異常

筆者撈取了那個時間點中間件的日誌，發現除了這兩條sql以外，其它sql都很正常，總體耗時都在1ms左右，這又讓筆者陷入了思考之中。

再從日誌中找信息

在對當前中間件的日誌作了各類思考各類分析以後，又發現一個詭異的點，發如今1s以內，處理慢sql對應的NIO線程的處理sql數量遠遠小於其它NIO線程。更進一步，發如今這1s的某個時間點以前，慢sql所在的NIO線程徹底不打印任何日誌,以下圖所示:

同時也發現兩條sql都落在對應的Reactor-Thread-2的線程裏面，再往前回溯，發現近10s內的線程都沒有打印任何信息，好像什麼都沒處理。以下圖所示:

感受離真相愈來愈近了。這邊就很明顯了，reactor線程被卡住了！

尋找reactor線程爲什麼被卡住

筆者繼續順藤摸瓜，比較了一下幾個卡住的reactor線程最後打印的日誌，發現這幾條日誌對應的sql都很快返回了，沒什麼異常。而後又比較了一下幾個卡住的reactor線程恢復後打印出來的第一條sql，發現貌似它們經過路由解析起來都很慢,達到了1ms(正常是0.01ms)，而後找出了其對應的sql,發現這幾條sql都是150K左右的大小,按正常思路，這消失的10s應該就是處理這150K的sql了，以下圖所示:

爲什麼處理150K的sql會耗時10s

排查是不是網絡問題

首先，這條sql在接入中間件以前就有，也就耗時0.5ms左右。並且中間件在往數據庫發送sql的過程當中也是差很少的時間。若是說網絡有問題的話，那麼這段時間應該會變長,此種狀況暫不考慮。

排查是不是nio網絡處理代碼的問題

筆者鑑於多是中間件nio處理代碼的問題，構造了一樣的sql在線下進行復現，發現執行很快毫無壓力。筆者一度懷疑是線上環境的問題,traceroute了一下發現網絡基本和線下搭建的環境同樣，都是APP機器直連中間件機器，MTU都是1500，中間也沒任何路由。思路一下又陷入了停滯。

柳暗花明

思考良久無果以後。筆者以爲排查一下是不是構造的場景有問題，忽然發現，線上是用的prepareStatement,而筆者在命令行裏面用的是statement,二者是有區別的，prepare是按照select ?,?,?帶參數的形式而statement直接是select 1,2,3這樣的形式。

而在咱們的中間件中，因爲後端的數據庫對使用prepareStatement的sql具備較大的性能提高，咱們也支持了prepareStatement。並且爲了可以複用原來的sql解析代碼，咱們會在接收到對應的sql和參數以後將其還原成不帶?的sql算出路由到的數據庫節點後，再將原始的帶?的sql和參數prepare到對應的數據庫，以下圖所示:

從新構造prepareStatement場景

筆者從新構造了prepareStatement場景以後，發如今150K的sql下，確實耗時達到了10s,感受終於見到曙光了。

最終緣由字符串拼接

因爲是線下，在各類地方打日誌以後，終於發現耗時就是在這個將帶?的sql渲染爲不帶問號的sql上面。下面是代碼示意:

String sql="select ?,?,?,?,?,?...?,?,?...";
for(int i=0 ; i < paramCount;i++){
	sql = sql.replaceFirst("\\?",param[i]);
}
return sql;

這個replaceFirst在字符串特別大，須要替換的字符頻率出現的特別多的時候方面有巨大的性能消耗。以前就發現replaceFirst這個操做裏面有正則的操做致使特殊符號不能正確渲染sql(另外參數裏面帶?也不能正確渲染)，因而其改爲了用split ?的方式進行sql的渲染。可是這個版本並無在此應用對應的集羣上使用。可能也正是這些額外的正則操做致使了這個replaceFirst性能在這種狀況下特別差。

對應優化

將其改爲新版本後，新代碼以下所示:

String splits[] = sql.split("\\?");
String result="";
for(int i=0;i<splits.length;i++){
	if(i<paramNumber){
		result+=splits[i]+getParamString(paramNumber);
	}else{
		result+=splits[i];
	}
}
return result;

這個解析時間從10s降低至2s，但感受仍是不夠滿意。
經同事提醒，試下StringBuilder。因爲此應用使用的是jdk1.8，筆者一直以爲jdk1.8已經能夠直接用原生的字符串拼接不須要用StringBuilder了。但仍是試了一試，發現從2s降低至8ms!
改爲StringBuilder的代碼後以下所示:

String splits[] = sql.split("\\?");
StringBuilder builder = new StringBuilder();
for(int i=0;i<splits.length;i++){
	if(i<paramNumber){
		builder.append(splits[i]).append(getParamString(paramNumber));
	}else{
		builder.append(splits[i])；
	}
}
return builder.toString();

筆者查了下資料，發現jdk 1.8雖然作了優化，可是每作一次拼接仍是新建了一個StringBuilder，因此在大字符串頻繁拼接的場景仍是須要用一個StringBuilder，以免額外的性能損耗。

總結

IO線程不能作任何耗時的操做，這樣會致使整個吞吐量急劇降低，對應分庫分表這種基礎組件在編寫代碼的時候必需要仔細評估，連java原生的replaceFirst也會在特定狀況下出現巨大的性能問題，不能遺漏任何一個點,不然就是下一個坑。
每一次複雜Bug的分析過程都是一次挑戰，解決問題最重要也是最困難的是定位問題。而定位問題須要的是在看到現象時候可以浮現出的各類思路，而後經過日誌等信息去一條條否決本身的思路，直至達到惟一的那個問題點。

公衆號

關注筆者公衆號，獲取更多幹貨文章: