SQL運(yùn)行速度慢？查查中間件-創(chuàng)新互聯(lián)

前言

專注于為中小企業(yè)提供成都網(wǎng)站建設(shè)、成都網(wǎng)站制作服務(wù),電腦端+手機(jī)端+微信端的三站合一,更高效的管理,為中小企業(yè)綏寧免費(fèi)做網(wǎng)站提供優(yōu)質(zhì)的服務(wù)。我們立足成都，凝聚了一批互聯(lián)網(wǎng)行業(yè)人才，有力地推動(dòng)了上千多家企業(yè)的穩(wěn)健成長(zhǎng)，幫助中小企業(yè)通過(guò)網(wǎng)站建設(shè)實(shí)現(xiàn)規(guī)模擴(kuò)充和轉(zhuǎn)變。

最近發(fā)現(xiàn)線上出現(xiàn)一個(gè)奇葩的問(wèn)題，這問(wèn)題讓筆者定位了好長(zhǎng)時(shí)間，期間排查問(wèn)題的過(guò)程還是挺有意思的，正好博客也好久不更新了，就以此為素材寫(xiě)出了本篇文章。

Bug現(xiàn)場(chǎng)

我們的分庫(kù)分表中間件在經(jīng)過(guò)一年的沉淀之后，已經(jīng)到了比較穩(wěn)定的階段。而且經(jīng)過(guò)線上壓測(cè)的檢驗(yàn)，單臺(tái)每秒能夠執(zhí)行1.7W條sql。但線上情況還是有出乎我們意料的情況。有一個(gè)業(yè)務(wù)線反映，每天有幾條sql有長(zhǎng)達(dá)十幾秒的超時(shí)。而且sql是主鍵更新或主鍵查詢，更奇怪的是出現(xiàn)超時(shí)的是不同的sql,似乎毫無(wú)規(guī)律可尋,如下圖所示: 
一個(gè)值得注意的點(diǎn)，就是此業(yè)務(wù)只有一部分流量走我們的中間件，另一部分還是直接走數(shù)據(jù)庫(kù)的，而超時(shí)的sql只會(huì)在連中間件的時(shí)候出現(xiàn)，如下圖所示:

很明顯，是引入了中間件之后導(dǎo)致的問(wèn)題。

排查是否sql確實(shí)慢

由于數(shù)據(jù)庫(kù)中間件只關(guān)心sql,并沒(méi)有記錄對(duì)應(yīng)應(yīng)用的traceId,所以很難將對(duì)應(yīng)的請(qǐng)求和sql對(duì)應(yīng)起來(lái)。在這里，我們先粗略的統(tǒng)計(jì)了在應(yīng)用端超時(shí)的sql的類型是否會(huì)有超時(shí)的情況。 分析了日志，發(fā)現(xiàn)那段時(shí)間所有的sql在往后端數(shù)據(jù)執(zhí)行的時(shí)候都只有0.5ms,非常的快。如下圖所示:

看來(lái)是中間件和數(shù)據(jù)庫(kù)之間的交互是正常的，那么繼續(xù)排查線索。

尋找超時(shí)規(guī)律

由于比較難綁定對(duì)應(yīng)請(qǐng)求和中間件執(zhí)行sql之間的關(guān)系，于是筆者就想著列出所有的異常情況，看看其時(shí)間點(diǎn)是否有規(guī)律，以排查一些批處理導(dǎo)致中間件性能下降的現(xiàn)象。下面是某幾條超時(shí)sql業(yè)務(wù)方給出的信息:

業(yè)務(wù)開(kāi)始時(shí)間	執(zhí)行sql的應(yīng)用ip	業(yè)務(wù)執(zhí)行耗時(shí)(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

看上去貌似沒(méi)什么規(guī)律，慢sql存在于不同的應(yīng)用ip之上，排除某臺(tái)應(yīng)用出問(wèn)題的可能。 超時(shí)時(shí)間從早上9點(diǎn)到晚上22點(diǎn)都有發(fā)現(xiàn)超時(shí)，排除了某個(gè)點(diǎn)集中性能下降的可能。

注意到一個(gè)微小的規(guī)律

筆者觀察了一堆數(shù)據(jù)一段時(shí)間，終于發(fā)現(xiàn)了一點(diǎn)小規(guī)律，如下面兩條所示:

業(yè)務(wù)開(kāi)始時(shí)間	執(zhí)行sql的應(yīng)用ip	業(yè)務(wù)執(zhí)行耗時(shí)(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超時(shí)對(duì)應(yīng)的時(shí)間點(diǎn)挺接近的，一個(gè)是22:43:07,一個(gè)是22:43:04,中間只差了3s,然后與后面的業(yè)務(wù)執(zhí)行耗時(shí)相加，發(fā)現(xiàn)更接近了,讓我們重新整理下:

業(yè)務(wù)開(kāi)始時(shí)間	執(zhí)行sql的應(yīng)用ip	業(yè)務(wù)執(zhí)行耗時(shí)(s)	業(yè)務(wù)完成時(shí)間(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

發(fā)現(xiàn)這兩筆業(yè)務(wù)雖然開(kāi)始時(shí)間不同，但確是同時(shí)完成的，這可能是個(gè)巧合，也可能是bug出現(xiàn)導(dǎo)致的結(jié)果。于是繼續(xù)看下是否有這些規(guī)律的慢sql,讓業(yè)務(wù)又提供了最近的慢sql,發(fā)現(xiàn)這種現(xiàn)象雖然少，但是確實(shí)發(fā)生了不止一次。筆者突然感覺(jué)到，這絕對(duì)不是巧合。

由上述規(guī)律導(dǎo)致的思考

筆者聯(lián)想到我們中間件有好多臺(tái)，假設(shè)是中間件那邊卡住的話，如果在那一瞬間，有兩臺(tái)sql同時(shí)落到同一臺(tái)的話，中間件先卡住，然后在中間件恢復(fù)的那一瞬間，以0.5ms的速度執(zhí)行完再返回就會(huì)導(dǎo)致這種現(xiàn)象。如下圖所示: 
當(dāng)然了還有另一種可能，就是sql先以0.5ms的速度執(zhí)行完，然后中間件那邊卡住了，和上面的區(qū)別只是中間件卡的位置不同而已，另一種可能如下圖所示:

是否落到同一臺(tái)中間件

線上一共4臺(tái)中間件,在經(jīng)歷了一堆復(fù)雜線上日志撈取分析相對(duì)應(yīng)之后，發(fā)現(xiàn)那兩條sql確實(shí)落在了同一臺(tái)中間件上。為了保證猜想無(wú)誤，又找了兩條符合此規(guī)律的sql,同樣的也落在同一臺(tái)中間件上面，而且這兩臺(tái)中間件并不是同一臺(tái)，排除某臺(tái)機(jī)器有問(wèn)題。如下圖所示:

業(yè)務(wù)日志和中間件日志相對(duì)照

在上述發(fā)現(xiàn)的基礎(chǔ)上，又經(jīng)歷了各種日志分析對(duì)應(yīng)之后，終于找到了耗時(shí)sql日志和業(yè)務(wù)日志對(duì)應(yīng)的關(guān)聯(lián)。然后發(fā)現(xiàn)一個(gè)關(guān)鍵信息。中間件在接收到sql時(shí)候會(huì)打印一條日志，發(fā)現(xiàn)在應(yīng)用發(fā)出sql到接收到sql還沒(méi)來(lái)得及做后面的路由邏輯之前就差了10s左右，然后sql執(zhí)行到返回確是非?？焖俚?，如下圖所示:

查看對(duì)應(yīng)中間件那個(gè)時(shí)間點(diǎn)其它sql有無(wú)異常

筆者撈取了那個(gè)時(shí)間點(diǎn)中間件的日志，發(fā)現(xiàn)除了這兩條sql之外，其它sql都很正常，整體耗時(shí)都在1ms左右，這又讓筆者陷入了思考之中。

再?gòu)娜罩局姓倚畔?/strong>

在對(duì)當(dāng)前中間件的日志做了各種思考各種分析之后，又發(fā)現(xiàn)一個(gè)詭異的點(diǎn)，發(fā)現(xiàn)在1s之內(nèi)，處理慢sql對(duì)應(yīng)的NIO線程的處理sql數(shù)量遠(yuǎn)遠(yuǎn)小于其它NIO線程。更進(jìn)一步，發(fā)現(xiàn)在這1s的某個(gè)時(shí)間點(diǎn)之前，慢sql所在的NIO線程完全不打印任何日志,如下圖所示:

同時(shí)也發(fā)現(xiàn)兩條sql都落在對(duì)應(yīng)的Reactor-Thread-2的線程里面，再往前回溯，發(fā)現(xiàn)近10s內(nèi)的線程都沒(méi)有打印任何信息，好像什么都沒(méi)處理。如下圖所示:

感覺(jué)離真相越來(lái)越近了。這邊就很明顯了，reactor線程被卡住了！

尋找reactor線程為何被卡住

筆者繼續(xù)順藤摸瓜，比較了一下幾個(gè)卡住的reactor線程最后打印的日志，發(fā)現(xiàn)這幾條日志對(duì)應(yīng)的sql都很快返回了，沒(méi)什么異常。然后又比較了一下幾個(gè)卡住的reactor線程恢復(fù)后打印出來(lái)的第一條sql，發(fā)現(xiàn)貌似它們通過(guò)路由解析起來(lái)都很慢,達(dá)到了1ms(正常是0.01ms)，然后找出了其對(duì)應(yīng)的sql,發(fā)現(xiàn)這幾條sql都是150K左右的大小,按正常思路，這消失的10s應(yīng)該就是處理這150K的sql了，如下圖所示: 

為何處理150K的sql會(huì)耗時(shí)10s

排查是否是網(wǎng)絡(luò)問(wèn)題

首先，這條sql在接入中間件之前就有，也就耗時(shí)0.5ms左右。而且中間件在往數(shù)據(jù)庫(kù)發(fā)送sql的過(guò)程中也是差不多的時(shí)間。如果說(shuō)網(wǎng)絡(luò)有問(wèn)題的話，那么這段時(shí)間應(yīng)該會(huì)變長(zhǎng),此種情況暫不考慮。

排查是否是nio網(wǎng)絡(luò)處理代碼的問(wèn)題

筆者鑒于可能是中間件nio處理代碼的問(wèn)題，構(gòu)造了同樣的sql在線下進(jìn)行復(fù)現(xiàn)，發(fā)現(xiàn)執(zhí)行很快毫無(wú)壓力。筆者一度懷疑是線上環(huán)境的問(wèn)題,traceroute了一下發(fā)現(xiàn)網(wǎng)絡(luò)基本和線下搭建的環(huán)境一樣，都是APP機(jī)器直連中間件機(jī)器，MTU都是1500，中間也沒(méi)任何路由。思路一下又陷入了停滯。

柳暗花明

思考良久無(wú)果之后。筆者覺(jué)得排查一下是否是構(gòu)造的場(chǎng)景有問(wèn)題，突然發(fā)現(xiàn)，線上是用的prepareStatement,而筆者在命令行里面用的是statement,兩者是有區(qū)別的，prepare是按照select ?,?,?帶參數(shù)的形式而statement直接是select 1,2,3這樣的形式。

而在我們的中間件中，由于后端的數(shù)據(jù)庫(kù)對(duì)使用prepareStatement的sql具有較大的性能提升，我們也支持了prepareStatement。而且為了能夠復(fù)用原來(lái)的sql解析代碼，我們會(huì)在接收到對(duì)應(yīng)的sql和參數(shù)之后將其還原成不帶?的sql算出路由到的數(shù)據(jù)庫(kù)節(jié)點(diǎn)后，再將原始的帶?的sql和參數(shù)prepare到對(duì)應(yīng)的數(shù)據(jù)庫(kù)，如下圖所示:

重新構(gòu)造prepareStatement場(chǎng)景

筆者重新構(gòu)造了prepareStatement場(chǎng)景之后，發(fā)現(xiàn)在150K的sql下，確實(shí)耗時(shí)達(dá)到了10s,感覺(jué)終于見(jiàn)到曙光了。

最終原因字符串拼接

由于是線下，在各種地方打日志之后，終于發(fā)現(xiàn)耗時(shí)就是在這個(gè)將帶?的sql渲染為不帶問(wèn)號(hào)的sql上面。下面是代碼示意:

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

這個(gè)replaceFirst在字符串特別大，需要替換的字符頻率出現(xiàn)的特別多的時(shí)候方面有巨大的性能消耗。之前就發(fā)現(xiàn)replaceFirst這個(gè)操作里面有正則的操作導(dǎo)致特殊符號(hào)不能正確渲染sql(另外參數(shù)里面帶?也不能正確渲染)，于是其改成了用split ?的方式進(jìn)行sql的渲染。但是這個(gè)版本并沒(méi)有在此應(yīng)用對(duì)應(yīng)的集群上使用。可能也正是這些額外的正則操作導(dǎo)致了這個(gè)replaceFirst性能在這種情況下特別差。

對(duì)應(yīng)優(yōu)化

將其改成新版本后，新代碼如下所示:

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;

這個(gè)解析時(shí)間從10s下降至2s，但感覺(jué)還是不夠滿意。
經(jīng)同事提醒，試下StringBuilder。由于此應(yīng)用使用的是jdk1.8，筆者一直覺(jué)得jdk1.8已經(jīng)可以直接用原生的字符串拼接不需要用StringBuilder了。但還是試了一試，發(fā)現(xiàn)從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();

筆者查了下資料，發(fā)現(xiàn)jdk 1.8雖然做了優(yōu)化，但是每做一次拼接還是新建了一個(gè)StringBuilder，所以在大字符串頻繁拼接的場(chǎng)景還是需要用一個(gè)StringBuilder，以避免額外的性能損耗。

總結(jié)

IO線程不能做任何耗時(shí)的操作，這樣會(huì)導(dǎo)致整個(gè)吞吐量急劇下降，對(duì)應(yīng)分庫(kù)分表這種基礎(chǔ)組件在編寫(xiě)代碼的時(shí)候必須要仔細(xì)評(píng)估，連java原生的replaceFirst也會(huì)在特定情況下出現(xiàn)巨大的性能問(wèn)題，不能遺漏任何一個(gè)點(diǎn),否則就是下一個(gè)坑。
每一次復(fù)雜Bug的分析過(guò)程都是一次挑戰(zhàn)，解決問(wèn)題最重要也是最困難的是定位問(wèn)題。而定位問(wèn)題需要的是在看到現(xiàn)象時(shí)候能夠浮現(xiàn)出的各種思路，然后通過(guò)日志等信息去一條條否決自己的思路，直至達(dá)到唯一的那個(gè)問(wèn)題點(diǎn)。

轉(zhuǎn)自 | https://my.oschina.net/alchemystar/blog/2994406

本文題目：SQL運(yùn)行速度慢？查查中間件-創(chuàng)新互聯(lián)
網(wǎng)頁(yè)地址：http://muchs.cn/article24/spgce.html

成都網(wǎng)站建設(shè)公司_創(chuàng)新互聯(lián)，為您提供微信小程序、商城網(wǎng)站、關(guān)鍵詞優(yōu)化、品牌網(wǎng)站建設(shè)、外貿(mào)建站、建站公司

廣告

聲明：本網(wǎng)站發(fā)布的內(nèi)容（圖片、視頻和文字）以用戶投稿、用戶轉(zhuǎn)載內(nèi)容為主，如果涉及侵權(quán)請(qǐng)盡快告知，我們將會(huì)在第一時(shí)間刪除。文章觀點(diǎn)不代表本網(wǎng)站立場(chǎng)，如需處理請(qǐng)聯(lián)系客服。電話：028-86922220；郵箱：631063699@qq.com。內(nèi)容未經(jīng)允許不得轉(zhuǎn)載，或轉(zhuǎn)載時(shí)需注明來(lái)源： 創(chuàng)新互聯(lián)