[[392745]]

前言

duubo在互聯(lián)網技術中是中的非常廣泛的，從我實習到現(xiàn)在我所在的公司，都是使用的dubbo做rpc框架，所以這也導致了我們需要更加深入的去了解這門技術，因為我們的遇到的問題無時無刻都會存在，本次我就跟大家講講我的一次線上dubbo線程池耗盡的事故排查思路。

我寫過dubbo系列的文章，大家看完這章后想了解更多dubbo細節(jié)可以查看往起文章：

Dubbo

• 高性能NIO框架-Netty
• Netty常見面試題總結
• 敖丙RPC的超時設置，一不小心搞了線上事故
• 敖丙找出Dubbo源碼BUG，三歪夸了我一天
• Dubbo基礎
• Dubbo的服務暴露過程
• Dubbo的服務引用過程
• Dubbo服務調用過程
• Dubbo的SPI機制是啥?
• Dubbo集群容錯負載均衡
• Dubbo面試題
• RPC實踐
• Netty

問題

在一天早上突然手機收到公司服務告警短信，線程池耗盡了?在去公司的路上首先回想的就是最近公司有活動?流量突增?大早上就有人在發(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：我們在排查問題的時候一定要有一種必須查出因果關系的思想才能對自己有一定的提升，憑借著這種思想我們一步一步向下揭開謎底。

帶著問題，接下來我們去查看dubbo的代碼配置，了解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}" /> 

從拋出的異常上我們已經設置的線程池的大小為300了

• 這里我說明一個點，不是線程池配置的越大就越好，這個是授我們系統(tǒng)層面，以及配置JVM參數(shù)相關的。一般我們都是默認配置200 大致可以從這幾方面去做考慮：
• 1.JVM參數(shù)：-Xms 初始堆大小 -Xmx 最大堆大小 -Xss 每個線程棧大小2.系統(tǒng)層面1.系統(tǒng)最大可創(chuàng)建的線程 2.公式線：程數(shù)量 = (機器本身可用內存 - (JVM分配的堆內存+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)建新線程，而不是將任務放入阻塞隊列。這個使用自己隊列TaskQueue。

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

異常處理機制

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

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

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

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

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

• corePoolSize - 池中所保存的線程數(shù)，包括空閑線程。
• maximumPoolSize-池中允許的最大線程數(shù)。
• keepAliveTime - 當線程數(shù)大于核心時，此為終止前多余的空閑線程等待新任務的最長時間。
• unit - keepAliveTime 參數(shù)的時間單位。
• workQueue - 執(zhí)行前用于保持任務的隊列。此隊列僅保持由 execute方法提交的 Runnable任務。
• threadFactory - 執(zhí)行程序創(chuàng)建新線程時使用的工廠。
• handler 由于超出線程范圍和隊列容量而使執(zhí)行被阻塞時所使用的處理程序。ThreadPoolExecutor是Executors類的底層實現(xiàn)。

好，看了這么多源碼，從上面我們已經了解這個異常來的來源了，那是什么原因導致我遇到的這次的線程池耗盡呢?

排查思路

第一階段：

由于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] 

所以就一直在思考什么原因導致YGC時間這么長：

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

使用jmap查看內存情況，并分析是否存在內存泄露。

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

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

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

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

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

開啟階段二的排查：

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

所以又再次去查詢什么原因導致我們的redis查詢超時呢?

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

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

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

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

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

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

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

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

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

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

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

總結

其實我們在排查問題的時候，我們很容易會被一些其他的表象給迷惑了，認為本來是果的關系變成了因，但是這個本來也就是一個復雜的過程，只能是通過自己不斷的積累，不斷的學習過程，所以寫下這篇文章希望能對大家有一定的幫助.

最后還是要強調一下大家遇到問題不要稀里糊涂解決了就好了，這樣下次問題復現(xiàn)你還是稀里糊涂解決不知道什么原因，這樣長期下來你的個人成長是很局限的，對一個技術的理解往往是從問題發(fā)現(xiàn)到解決理解這中間得到提升的。

我身邊的大佬遇到這樣的情況都是選擇先解決問題(遇到任何線上問題都是優(yōu)先恢復再考慮查找原因)，然后刨根問底找到答案才罷休的，比如我老東家的leader在遇到一個內存溢出問題時，dump下數(shù)據(jù)從中午分析到大半夜，分析出來，寫了滿滿一大頁的wiki吧過程沉淀下來才回家，我看到的時候是由衷的佩服。

做一行愛一行嘛，我是敖丙，你知道的越多，你不知道的越多，我們下期見。