來(lái)源于公眾號(hào)Java藝術(shù) ，

作者wujiuye

兩耳不聞窗外事，一心只讀圣賢書。又是一個(gè)美好的周末，一覺(jué)睡到自然醒，寫寫文章看看書！這周原計(jì)劃是寫Dubbo注冊(cè)中心的，但這周先說(shuō)故事。

上次服務(wù)雪崩還是一個(gè)月前的事情，雖然上次雪崩事件之后加了熔斷器，但這次服務(wù)崩潰原因并未達(dá)到限流的QPS值。由于前一次雪崩后做了些參數(shù)上的調(diào)整，比如取消dubbo重試機(jī)制，減小超時(shí)時(shí)間，添加mock機(jī)制等，不至于服務(wù)完全癱瘓，但請(qǐng)求平均耗時(shí)異常彪升，超出臨界值的請(qǐng)求全部處理異常。

項(xiàng)目不斷新增需求，難免不會(huì)出現(xiàn)問(wèn)題，特別是近期新增的增加請(qǐng)求處理耗時(shí)的需求。以及一些配置的修改而忽略掉的問(wèn)題，如dubbo工作線程數(shù)調(diào)增時(shí)，忽略了redis連接池的修改。由于redis可用連接遠(yuǎn)小于工作線程數(shù)，就會(huì)出現(xiàn)多個(gè)線程競(jìng)爭(zhēng)redis連接，影響性能。

在發(fā)現(xiàn)請(qǐng)求平均耗時(shí)超出異常，而并發(fā)量卻未有異常突增時(shí)，查看服務(wù)器日記發(fā)現(xiàn)日記打印了密密麻麻的遠(yuǎn)程調(diào)用超時(shí)異常，看日記就能很清楚的知道是哪個(gè)服務(wù)哪個(gè)接口調(diào)用超時(shí)。日記內(nèi)容大致如下，詳細(xì)信息能夠看到調(diào)用的類、方法名以及參數(shù)。

org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer.

對(duì)外服務(wù)(下文統(tǒng)稱服務(wù)A)處理終端一次請(qǐng)求的平均耗時(shí)在25ms左右，正常情況下并發(fā)量突增到服務(wù)所能承受的最高點(diǎn)時(shí)，最大耗時(shí)也在200ms以內(nèi)，而一次請(qǐng)求中調(diào)用某個(gè)服務(wù)(下文統(tǒng)稱服務(wù)B)的耗時(shí)必然會(huì)小于一次請(qǐng)求的處理耗時(shí)，所以我把服務(wù)A調(diào)用服務(wù)B的rpc調(diào)用超時(shí)設(shè)置為500ms，避免因調(diào)用阻塞等待導(dǎo)致請(qǐng)求堆積問(wèn)題，所以本次服務(wù)崩潰并未看到文件句柄數(shù)達(dá)上限的異常，也因如此，只會(huì)有部分請(qǐng)求處理失敗，不止于整個(gè)服務(wù)完全不可用。

看到請(qǐng)求處理耗時(shí)，首先想到的是redis，但通過(guò)redis-cli工具排除了redis性能問(wèn)題。通過(guò)SSH連上到服務(wù)B的某個(gè)節(jié)點(diǎn)，也并未發(fā)現(xiàn)jedis連接超時(shí)或是查詢超時(shí)異常，暫時(shí)排除redis性能問(wèn)題。最后通過(guò)htop命令，發(fā)現(xiàn)cpu使用率一直居高不下，根據(jù)經(jīng)驗(yàn)判斷，要么程序中出現(xiàn)什么死循環(huán)，要么就是代碼執(zhí)行計(jì)算任務(wù)耗時(shí)，非IO操作，比如大量for循環(huán)計(jì)算。

從日記中已經(jīng)能定位到服務(wù)B的某個(gè)接口執(zhí)行耗時(shí)，但接口的實(shí)現(xiàn)很復(fù)雜。通過(guò)過(guò)濾器鏈封裝了具體調(diào)用邏輯，而過(guò)濾器鏈中大概有六七個(gè)過(guò)濾器，過(guò)濾器鏈按照注冊(cè)順序調(diào)用過(guò)濾器的filter方法，當(dāng)某個(gè)過(guò)濾器返回true時(shí)，后面的過(guò)濾器就不會(huì)執(zhí)行。

如果項(xiàng)目中加入分布式系統(tǒng)調(diào)用鏈追蹤系統(tǒng)，比如Zipkin+Brave+Elasticsearch，那么排查問(wèn)題就會(huì)非常簡(jiǎn)單，但需要為此花費(fèi)大日記存儲(chǔ)的費(fèi)用，因此我們項(xiàng)目中并未使用。除此之外，要定位到線上問(wèn)題，找出哪個(gè)方法耗時(shí)，或者都有哪些方法比較耗時(shí)，就需要借助一些Agent工具，監(jiān)控或取樣每個(gè)方法的執(zhí)行耗時(shí)，從而定位到具體的過(guò)濾器具體的某個(gè)方法，比如Jprofile、Arthas。

Jprofile對(duì)線上高并發(fā)服務(wù)影響比較大，且需要在本地使用Jprofile應(yīng)用遠(yuǎn)程連接。關(guān)于Jprofile的介紹以及使用可以查看我的歷史文章：使用Jprofiler遠(yuǎn)程監(jiān)控線上服務(wù)。Arthas在線文檔https://alibaba.github.io/arthas/watch.html。

在此次問(wèn)題排除過(guò)程中，watch、monitor、trace這三個(gè)命令都起了很大的作用。

首先使用watch監(jiān)控服務(wù)B對(duì)外提供服務(wù)(provider)的接口處理耗時(shí)，通過(guò)'#cost>500'輸出耗時(shí)大于500ms的調(diào)用日記， -x 指定參數(shù)和返回打印的深度，在不關(guān)心方法具體參數(shù)內(nèi)容時(shí)，也可去掉“{params,returnObj}”。

通過(guò)watch命令發(fā)現(xiàn)，服務(wù)B暴露給其它服務(wù)調(diào)用的接口，調(diào)用耗時(shí)大于500ms的非常多，因此，根據(jù)代碼層面的理解，大概定位到會(huì)出現(xiàn)耗時(shí)如此高的過(guò)濾器。繼續(xù)使用watch監(jiān)控具體某個(gè)過(guò)濾器的過(guò)濾方法的耗時(shí)。

在監(jiān)控某個(gè)過(guò)濾器的方法執(zhí)行耗時(shí)上找到了答案。arthas頻繁打印記錄，單個(gè)過(guò)濾器的一個(gè)過(guò)濾方法執(zhí)行耗時(shí)就超過(guò)1000ms，將'#cost'降到到500ms后更多。

繼續(xù)使用monitor命令監(jiān)控某個(gè)方法的執(zhí)行信息，包括執(zhí)行總數(shù)、執(zhí)行成功次數(shù)、異常失敗次數(shù)、平均耗時(shí)、失敗率等，通過(guò) -c 1 指定統(tǒng)計(jì)周期為1s。

當(dāng)前服務(wù)B配置的Dubbo工作線程池的大小為256，圖中接口的平均耗時(shí)最大達(dá)到1s，圖中最大QPS為300，此時(shí)CPU使用率接近百分百，假設(shè)該服務(wù)部署兩個(gè)節(jié)點(diǎn)，以此估算最大QPS為600。

當(dāng)服務(wù)A并發(fā)數(shù)達(dá)到11w每分鐘時(shí)，三個(gè)節(jié)點(diǎn)，轉(zhuǎn)為QPS就是每節(jié)點(diǎn)每秒處理611個(gè)請(qǐng)求，剛好就是服務(wù)B的QPS，所以當(dāng)服務(wù)A并發(fā)量超過(guò)11w/min的閾值時(shí)，服務(wù)就變得不可用，大量請(qǐng)求得不到處理，平均耗時(shí)異常飆升。

由于之前根據(jù)每請(qǐng)求耗時(shí)最大25ms計(jì)算的QPS，設(shè)置限流規(guī)則，而當(dāng)前rpc遠(yuǎn)程調(diào)用并未達(dá)到限流的條件，遠(yuǎn)端沒(méi)有空閑線程能夠處理rpc調(diào)用，所以consumer端就會(huì)收到provider端線程池已滿無(wú)法處理請(qǐng)求的異常，以及大量的rpc遠(yuǎn)程調(diào)用超時(shí)異常。

我們還可以使用Arthas的trace命令輸出方法調(diào)用棧上的每個(gè)方法執(zhí)行耗時(shí)。--skipJDKMethod true指定跳過(guò)jdk的函數(shù)調(diào)用，"#cost>100"指定只會(huì)展示耗時(shí)大于100ms的調(diào)用路徑。

使用--skipJDKMethod true跳過(guò)jdk方法在此處會(huì)有問(wèn)題。因?yàn)槲矣胘dk的List存放過(guò)濾器，通過(guò)遍歷List來(lái)順序調(diào)用過(guò)濾器鏈，過(guò)濾了jdk方法調(diào)用鏈就斷開(kāi)了。

Dubbo處理遠(yuǎn)程調(diào)用配置使用固定線程池，當(dāng)所有線程都處于工作狀態(tài)時(shí)，并不會(huì)將新請(qǐng)求放入阻塞隊(duì)列，而是放棄請(qǐng)求，拋出異常。解決方案有三，一是優(yōu)化代碼，如果代碼實(shí)在優(yōu)化不了，那就方案二，改用非固定線程池或增加線程數(shù)，但200個(gè)線程已經(jīng)讓cpu處于百分百的使用率，且增加線程也并不能解決耗時(shí)問(wèn)題，反而耗時(shí)會(huì)上漲，那么，最后就只剩方法三，橫向擴(kuò)展節(jié)點(diǎn)。

此次代碼層面的優(yōu)化包括，使用zcount替換redis的hgetall優(yōu)化了業(yè)務(wù)邏輯，以及以內(nèi)存換性能，在redis緩存上再加一層內(nèi)存緩存，內(nèi)存緩存緩存方法返回結(jié)果，在redis數(shù)據(jù)更新時(shí)移除內(nèi)存記錄。優(yōu)化后，服務(wù)B的QPS有了顯著的提升，像極了牙膏，擠擠又省幾臺(tái)機(jī)器。

上圖是我在服務(wù)達(dá)到同樣并發(fā)量的條件下，用arthas驗(yàn)證調(diào)優(yōu)后的效果截圖。可以看到，請(qǐng)求平均耗時(shí)降低了100倍，QPS上去了。但是，事情并未結(jié)束，好戲才剛剛開(kāi)始。

墨菲定律，每到下班時(shí)間準(zhǔn)沒(méi)好事，果然，服務(wù)又崩潰了。但這次內(nèi)部服務(wù)都正常，cpu使用率在正常范圍內(nèi)，各個(gè)服務(wù)都沒(méi)有任何異常日記，服務(wù)A的rpc遠(yuǎn)程調(diào)用超時(shí)問(wèn)題也不存在了?？煞?wù)A打印的每個(gè)請(qǐng)求的處理耗時(shí)都超過(guò)500ms，明顯的非常不正常，于是又是一波Arthas操作。

終于找到問(wèn)題，所以我說(shuō)，這次Arthas是大功臣。在調(diào)用IP庫(kù)服務(wù)提供的restful接口出了問(wèn)題，耗時(shí)全在這里。最后的優(yōu)化是把IP位置信息的查詢由調(diào)用接口改為直接依賴封裝的組件從redis緩存中查，問(wèn)題得以解決。關(guān)于IP庫(kù)可看我往期文章：基于Redis實(shí)現(xiàn)范圍查詢的IP庫(kù)緩存設(shè)計(jì)方案。

我們一直忽略了一個(gè)問(wèn)題，就是并發(fā)量上升時(shí)，只考慮為接收外部請(qǐng)求的服務(wù)A添加節(jié)點(diǎn)，卻忘了大部分業(yè)務(wù)邏輯都是由內(nèi)部的兩個(gè)服務(wù)去處理的，解決內(nèi)部服務(wù)的性能問(wèn)題才是提高對(duì)外服務(wù)A的QPS的關(guān)鍵。加節(jié)點(diǎn)應(yīng)該先看各各服務(wù)的狀態(tài)，給最需要加節(jié)點(diǎn)的服務(wù)添加節(jié)點(diǎn)才是重中之重。否者服務(wù)A加的節(jié)點(diǎn)越多，接收的請(qǐng)求越多，越容易打垮內(nèi)部服務(wù)。

也因此得出，現(xiàn)在我們的服務(wù)部署方案是有問(wèn)題的。太關(guān)注對(duì)外服務(wù)A的處理能力而忽略了內(nèi)部提供業(yè)務(wù)支持的服務(wù)。但這結(jié)論也會(huì)隨著外部服務(wù)不斷添加新需求的情況下被推翻，定期檢查各服務(wù)狀態(tài)將變得非常有必要。

排查項(xiàng)目性能瓶頸需要考慮到各方面，一是緩存redis的性能瓶頸，二是外部服務(wù)性能瓶頸，三是內(nèi)部各服務(wù)的性能瓶頸，最后數(shù)據(jù)庫(kù)性能瓶頸。調(diào)優(yōu)包括：業(yè)務(wù)邏輯優(yōu)化、代碼調(diào)優(yōu)、緩存調(diào)優(yōu)、SQL調(diào)優(yōu)、JVM調(diào)優(yōu)。遇到問(wèn)題一定要去找到問(wèn)題的根源，只通過(guò)加機(jī)器處理問(wèn)題，問(wèn)題將會(huì)惡化得越來(lái)越嚴(yán)重，因?yàn)槎玖鲆恢倍荚?#xff01;

總結(jié)

以上是生活随笔為你收集整理的某个软件调用目标异常_线上RPC远程调用频繁超时问题排查，大功臣Arthas的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。