Dubbo線程池事故排查的方法步驟

這篇文章主要介紹“Dubbo線程池事故排查的方法步驟”，在日常操作中，相信很多人在Dubbo線程池事故排查的方法步驟問題上存在疑惑，小編查閱了各式資料，整理出簡單好用的操作方法，希望對大家解答”Dubbo線程池事故排查的方法步驟”的疑惑有所幫助！接下來，請跟著小編一起來學習吧！

問題

在一天早上突然手機收到公司服務(wù)告警短信，線程池耗盡了?在去公司的路上首先回想的就是最近公司有活動?流量突增?大早上就有人在發(fā)布系統(tǒng)?還是某歪趁我不在又點壞了我的系統(tǒng)?

懷著種種思考在公司的群里看著同步信息，以上種種可能都被反駁!!!

以下就是當時的告警信息：

RejectedExecutionException:Thread pool is EXHAUSTED （線程池耗盡了）! Thread Name: DubboServerHandler-xx.xx.xxx:2201, Pool Size: 300 (active: 283, core: 300, max: 300, largest: 300)

Q：這個問題怎么出現(xiàn)的呢?是不是我們擴大線程池就能解決問題呢?dubbo里面線程池默認實現(xiàn)是什么呢?

A：我們在排查問題的時候一定要有一種必須查出因果關(guān)系的思想才能對自己有一定的提升，憑借著這種思想我們一步一步向下揭開謎底。

帶著問題，接下來我們?nèi)ゲ榭磀ubbo的代碼配置，了解dubbo底層實現(xiàn)，只有了解底層實現(xiàn)我們才能更加準確的發(fā)現(xiàn)問題，處理問題，提升自己......

首先我們看下我們代碼配置：

<dubbo:protocol name="dubbo" port="${service.protocol.dubbo.port}" threads="${service.protocol.dubbo.threads}" register="${service.protocol.dubbo.register}" />

從拋出的異常上我們已經(jīng)設(shè)置的線程池的大小為300了

• 這里我說明一個點，不是線程池配置的越大就越好，這個是授我們系統(tǒng)層面，以及配置JVM參數(shù)相關(guān)的。一般我們都是默認配置200  大致可以從這幾方面去做考慮：

• 1.JVM參數(shù)：-Xms 初始堆大小 -Xmx 最大堆大小 -Xss 每個線程棧大小2.系統(tǒng)層面1.系統(tǒng)最大可創(chuàng)建的線程 2.公式線：程數(shù)量 =  (機器本身可用內(nèi)存 - (JVM分配的堆內(nèi)存+JVM元數(shù)據(jù)區(qū))) / Xss的值

言歸正傳我們開始看下擼點源碼，這里我們以 2.7.19的版本為例

我們可以看到ThreadPool接口是個擴展點，然后默認實現(xiàn)是fixed，然后里面有個getExecutor方法，被@Adaptive注解修飾。

在dubbo中ThreadPool有4個實現(xiàn)類

1.CachedThreadPool 緩存線程池，超過keepAliveTime時間刪除，使用的時候再創(chuàng)建

2.FixedThreadPool 固定線程數(shù)量線程池，一旦建立，一直持有。

3.LimitedThreadPool 可伸縮線程池，線程只增長不收縮。

4.EagerThreadPool 當core線程數(shù)忙的時候，創(chuàng)建新線程，而不是將任務(wù)放入阻塞隊列。這個使用自己隊列TaskQueue。

這里我們就直接看默認實現(xiàn)FixedThreadPool

異常處理機制

從代碼中我們可以發(fā)現(xiàn)：

dubbo線程池采用jdk的ThreadPoolExecutor，默認threads數(shù)為200，并且默認采用了SynchronousQueue隊列，而如果用戶配置的隊列長度大于0時，則會采用LinkedBlockingQueue隊列。

如果某個線程因為執(zhí)行異常而結(jié)束，那么線程池會添加一個新的線程。

所以由于dubbo默認采用了直接提交的SynchronousQueue工作隊列，所以，所有的task會直接提交給線程池中的某一worker線程，如果沒有可用線程，那么會拒絕任務(wù)的處理然后拋出我們當前現(xiàn)在遇到的問題

以下說明下我們創(chuàng)建一個線程池的必要參數(shù) ：

• corePoolSize - 池中所保存的線程數(shù)，包括空閑線程。

• maximumPoolSize-池中允許的最大線程數(shù)。

• keepAliveTime - 當線程數(shù)大于核心時，此為終止前多余的空閑線程等待新任務(wù)的最長時間。

• unit - keepAliveTime 參數(shù)的時間單位。

• workQueue - 執(zhí)行前用于保持任務(wù)的隊列。此隊列僅保持由 execute方法提交的 Runnable任務(wù)。

• threadFactory - 執(zhí)行程序創(chuàng)建新線程時使用的工廠。

• handler 由于超出線程范圍和隊列容量而使執(zhí)行被阻塞時所使用的處理程序。ThreadPoolExecutor是Executors類的底層實現(xiàn)。

好，看了這么多源碼，從上面我們已經(jīng)了解這個異常來的來源了，那是什么原因?qū)е挛矣龅降倪@次的線程池耗盡呢?

排查思路

第一階段：

由于10.33.xx.xxx這臺機器出現(xiàn)線程池耗盡的時候，伴隨出現(xiàn)了一次時間比較久的ygc;所以懷疑是因為ygc時間較長，導致了機器資源緊張，從而拖垮了線程池;

2021-03-26T10:14:45.476+0800: 64922.846: [GC (Allocation Failure) 2021-02-24T11:17:45.477+0800: 64922.847: [ParNew: 1708298K->39822K(1887488K), 3.9215459 secs] 4189242K->2521094K(5033216K), 3.9225545 secs] [Times: user=12.77 sys=0.00, real=3.92 secs]

所以就一直在思考什么原因?qū)е耏GC時間這么長：

這里給大家簡單說明下為什么IO高會導致GC時間長

1.JVM GC需要通過發(fā)起系統(tǒng)調(diào)用write()，來記錄GC行為。

2.write()調(diào)用可以被后臺磁盤IO所阻塞。

3.記錄GC日志屬于JVM停頓的一部分，因此write()調(diào)用的時間也會被計算在JVM STW的停頓時間內(nèi)。

通過GC日志可以看到新生代在進行垃圾回收的時候停頓時間是在3.92s;對于新生代空間在1.8G左右的顯然是不正常的;ParNew收集器的工作過程中會出現(xiàn)以下步驟：

(1)標記-標記出來活著的對象 ----> (2) 將對象從eden區(qū)復(fù)制到survior區(qū) -----> (3)清理eden區(qū)

理論上來說第三步的時間是一定的，那可能時間會比較久的要么在第一步，要么在第二步

如果是第一步標記時間過長，就意味著本次GC之前，eden區(qū)存在大量的小對象(因為eden區(qū)大小是一定的)，量級應(yīng)該是正常的對象數(shù)量的數(shù)十倍

如果是第二步時間過長的話，那么存在以下可能：

1.標記完之后，eden區(qū)還有大量的對象(表現(xiàn)是回收之后新生代的對象占用內(nèi)存仍然很大)，這個從gclog可以排除(回收之后新生代的大小還有39M)

2.標記完之后仍然有大量碎片化的小對象存在

3.YGC出發(fā)了fullGC，但是我們沒有查看到有關(guān)日志

此時以上的情況都指向一種可能，那就是新生代存在大量的碎片化的小對象;

為了驗證這個論據(jù)，那就只有一種辦法就是去分析一下堆快照，但是我們那個時候剛好機器被重起，無法查明原因

在我們無法驗證的時候，第二臺機器出現(xiàn)了同樣的問題，準備再次jump日志的時候，回過頭來看了一下GC日志，發(fā)現(xiàn)GC正常。所以推翻階段一結(jié)論

這里給大家介紹一些我們常用的服務(wù)器命令：

top : 這是最常用的，也是展示信息最全的，可以看到負載，內(nèi)存，cpu等很多東西

比如使用top常見分析步奏：

1.top -Hp命令，查看具體是哪個線程占用率較高 2.使用printf命令查看這個線程的16進制  3.使用jstack命令查看當前線程正在執(zhí)行的方法

使用jmap查看內(nèi)存情況，并分析是否存在內(nèi)存泄露。

jmap -heap 3331：查看java 堆(heap)使用情況

jmap -histo 3331：查看堆內(nèi)存(histogram)中的對象數(shù)量及大小

jmap -histo:live 3331：JVM會先觸發(fā)gc，然后再統(tǒng)計信息

jmap -dump:format=b,file=heapDump 3331：將內(nèi)存使用的詳細情況輸出到文件

當然還有很多其他的命令比如 jstack,jinfo，uptime 等等很多命令。。。

開啟階段二的排查：

第二次出現(xiàn)異常的機器伴隨著各種redis查詢超時，從而導致所有的查詢 都走到了DB，從而導致數(shù)據(jù)庫壓力大增，慢SQl告警等等。

所以又再次去查詢什么原因?qū)е挛覀兊膔edis查詢超時呢?

第一步肯定都是去查看redis服務(wù)的各項性能指標是不是出現(xiàn)異常，結(jié)果也沒有很大的變化，那么問題肯定是在服務(wù)器本身.

查看本身指標發(fā)現(xiàn)：

那就是在報警時間段，cpu，cpu_iowait, 指標會飆升，磁盤IO則呈現(xiàn)不間斷鋸齒狀，其余指標基本不存在波動

但是什么原因引起的CPU波動呢?cpu波動跟線程池耗盡之間又有什么因果關(guān)系呢?

因此似乎得到了答案磁盤IO較高，導致cpu_iowait變高，cpu等IO，瞬間分配不到時間片，rt就會抖動。

最后我們發(fā)現(xiàn)跟我們的磁盤IO較高的原因時又跟我們的日志采集系統(tǒng)有關(guān)，相信現(xiàn)在很大一部分的公司都會用TRACE作為服務(wù)的全程鏈路最終管理。

再采用異步方式把記錄在內(nèi)存中trace日志一次性寫入磁盤，所以會出現(xiàn)IO抖動。

接下來我們看下trace 他到底是怎么工作的。

• trace 是類似 strace 的動態(tài)跟蹤工具，屬于問題診斷和調(diào)試工具 1.trace 包括兩部分：收集跟蹤日志和解析跟蹤日志。2.trace  收集跟蹤日志實質(zhì)上是運行跟蹤模塊時記錄的控制流信息的日志

重點： trace 模塊將上述信息組織成二進制格式寫入內(nèi)存中，直到停止 trace 跟蹤，才將上述內(nèi)存中的信息導出為二進制文件

這個只是給大家提供一個思路，每個人遇到問題或者場景都不一樣那得到的結(jié)論也都不一樣，只能是給大家作為一個參考吧!!!

到此，關(guān)于“Dubbo線程池事故排查的方法步驟”的學習就結(jié)束了，希望能夠解決大家的疑惑。理論與實踐的搭配能更好的幫助大家學習，快去試試吧！若想繼續(xù)學習更多相關(guān)知識，請繼續(xù)關(guān)注億速云網(wǎng)站，小編會繼續(xù)努力為大家?guī)砀鄬嵱玫奈恼拢?/p>