SQL執行速度慢?查查中介軟體

資料庫頻道發表於2019-02-15

前言

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

Bug現場

我們的分庫分表中介軟體在經過一年的沉澱之後,已經到了比較穩定的階段。而且經過線上壓測的檢驗,單臺每秒能夠執行1.7W條sql。但線上情況還是有出乎我們意料的情況。有一個業務線反映,每天有幾條sql有長達十幾秒的超時。而且sql是主鍵更新或主鍵查詢,更奇怪的是出現超時的是不同的sql,似乎毫無規律可尋,如下圖所示: SQL執行速度慢?查查中介軟體
一個值得注意的點,就是此業務只有一部分流量走我們的中介軟體,另一部分還是直接走資料庫的,而超時的sql只會在連中介軟體的時候出現,如下圖所示:
SQL執行速度慢?查查中介軟體
很明顯,是引入了中介軟體之後導致的問題。

排查是否sql確實慢

由於資料庫中介軟體只關心sql,並沒有記錄對應應用的traceId,所以很難將對應的請求和sql對應起來。在這裡,我們先粗略的統計了在應用端超時的sql的型別是否會有超時的情況。 分析了日誌,發現那段時間所有的sql在往後端資料執行的時候都只有0.5ms,非常的快。如下圖所示:
SQL執行速度慢?查查中介軟體
看來是中介軟體和資料庫之間的互動是正常的,那麼繼續排查線索。

尋找超時規律

由於比較難繫結對應請求和中介軟體執行sql之間的關係,於是筆者就想著列出所有的異常情況,看看其時間點是否有規律,以排查一些批處理導致中介軟體效能下降的現象。下面是某幾條超時sql業務方給出的資訊:

業務開始時間執行sql的應用ip業務執行耗時(s)
2018-12-24 09:45:24xx.xx.xx.24711.75
2018-12-24 12:06:10xx.xx.xx.24010.77
2018-12-24 12:07:19xx.xx.xx.13813.71
2018-12-24 22:43:07xx.xx.xx.24710.77
2018-12-24 22:43:04xx.xx.xx.24513.71

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

注意到一個微小的規律

筆者觀察了一堆資料一段時間,終於發現了一點小規律,如下面兩條所示:

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

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

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

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

由上述規律導致的思考

筆者聯想到我們中介軟體有好多臺,假設是中介軟體那邊卡住的話,如果在那一瞬間,有兩臺sql同時落到同一臺的話,中介軟體先卡住,然後在中介軟體恢復的那一瞬間,以0.5ms的速度執行完再返回就會導致這種現象。如下圖所示: SQL執行速度慢?查查中介軟體
當然了還有另一種可能,就是sql先以0.5ms的速度執行完,然後中介軟體那邊卡住了,和上面的區別只是中介軟體卡的位置不同而已,另一種可能如下圖所示:
SQL執行速度慢?查查中介軟體

是否落到同一臺中介軟體

線上一共4臺中介軟體,在經歷了一堆複雜線上日誌撈取分析相對應之後,發現那兩條sql確實落在了同一臺中介軟體上。為了保證猜想無誤,又找了兩條符合此規律的sql,同樣的也落在同一臺中介軟體上面,而且這兩臺中介軟體並不是同一臺,排除某臺機器有問題。如下圖所示:
SQL執行速度慢?查查中介軟體

業務日誌和中介軟體日誌相對照

在上述發現的基礎上,又經歷了各種日誌分析對應之後,終於找到了耗時sql日誌和業務日誌對應的關聯。然後發現一個關鍵資訊。中介軟體在接收到sql時候會列印一條日誌,發現在應用發出sql到接收到sql還沒來得及做後面的路由邏輯之前就差了10s左右,然後sql執行到返回確是非常快速的,如下圖所示:
SQL執行速度慢?查查中介軟體

檢視對應中介軟體那個時間點其它sql有無異常

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

再從日誌中找資訊

在對當前中介軟體的日誌做了各種思考各種分析之後,又發現一個詭異的點,發現在1s之內,處理慢sql對應的NIO執行緒的處理sql數量遠遠小於其它NIO執行緒。更進一步,發現在這1s的某個時間點之前,慢sql所在的NIO執行緒完全不列印任何日誌,如下圖所示:
SQL執行速度慢?查查中介軟體
同時也發現兩條sql都落在對應的Reactor-Thread-2的執行緒裡面,再往前回溯,發現近10s內的執行緒都沒有列印任何資訊,好像什麼都沒處理。如下圖所示:
SQL執行速度慢?查查中介軟體
感覺離真相越來越近了。這邊就很明顯了,reactor執行緒被卡住了!

尋找reactor執行緒為何被卡住

筆者繼續順藤摸瓜,比較了一下幾個卡住的reactor執行緒最後列印的日誌,發現這幾條日誌對應的sql都很快返回了,沒什麼異常。然後又比較了一下幾個卡住的reactor執行緒恢復後列印出來的第一條sql,發現貌似它們透過路由解析起來都很慢,達到了1ms(正常是0.01ms),然後找出了其對應的sql,發現這幾條sql都是150K左右的大小,按正常思路,這消失的10s應該就是處理這150K的sql了,如下圖所示: 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到對應的資料庫,如下圖所示:
SQL執行速度慢?查查中介軟體

重新構造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的分析過程都是一次挑戰,解決問題最重要也是最困難的是定位問題。而定位問題需要的是在看到現象時候能夠浮現出的各種思路,然後透過日誌等資訊去一條條否決自己的思路,直至達到唯一的那個問題點。

轉自 | https://my.oschina.net/alchemystar/blog/2994406

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/31545814/viewspace-2636078/,如需轉載,請註明出處,否則將追究法律責任。

相關文章