[[392745]]

前言

duubo在互聯(lián)網(wǎng)技術(shù)中是中的非常廣泛的，從我實(shí)習(xí)到現(xiàn)在我所在的公司，都是使用的dubbo做rpc框架，所以這也導(dǎo)致了我們需要更加深入的去了解這門(mén)技術(shù)，因?yàn)槲覀兊挠龅降膯?wèn)題無(wú)時(shí)無(wú)刻都會(huì)存在，本次我就跟大家講講我的一次線(xiàn)上dubbo線(xiàn)程池耗盡的事故排查思路。

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

Dubbo

• 高性能NIO框架-Netty
• Netty常見(jiàn)面試題總結(jié)
• 敖丙RPC的超時(shí)設(shè)置，一不小心搞了線(xiàn)上事故
• 敖丙找出Dubbo源碼BUG，三歪夸了我一天
• Dubbo基礎(chǔ)
• Dubbo的服務(wù)暴露過(guò)程
• Dubbo的服務(wù)引用過(guò)程
• Dubbo服務(wù)調(diào)用過(guò)程
• Dubbo的SPI機(jī)制是啥?
• Dubbo集群容錯(cuò)負(fù)載均衡
• Dubbo面試題
• RPC實(shí)踐
• Netty

問(wèn)題

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

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

以下就是當(dāng)時(shí)的告警信息：

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

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

A：我們?cè)谂挪閱?wèn)題的時(shí)候一定要有一種必須查出因果關(guān)系的思想才能對(duì)自己有一定的提升，憑借著這種思想我們一步一步向下揭開(kāi)謎底。

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

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

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

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

• 這里我說(shuō)明一個(gè)點(diǎn)，不是線(xiàn)程池配置的越大就越好，這個(gè)是授我們系統(tǒng)層面，以及配置JVM參數(shù)相關(guān)的。一般我們都是默認(rèn)配置200 大致可以從這幾方面去做考慮：
• 1.JVM參數(shù)：-Xms 初始堆大小 -Xmx 最大堆大小 -Xss 每個(gè)線(xiàn)程棧大小2.系統(tǒng)層面1.系統(tǒng)最大可創(chuàng)建的線(xiàn)程 2.公式線(xiàn)：程數(shù)量 = (機(jī)器本身可用內(nèi)存 - (JVM分配的堆內(nèi)存+JVM元數(shù)據(jù)區(qū))) / Xss的值

言歸正傳我們開(kāi)始看下擼點(diǎn)源碼，這里我們以 2.7.19的版本為例

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

在dubbo中ThreadPool有4個(gè)實(shí)現(xiàn)類(lèi)

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

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

3.LimitedThreadPool 可伸縮線(xiàn)程池，線(xiàn)程只增長(zhǎng)不收縮。

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

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

異常處理機(jī)制

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

dubbo線(xiàn)程池采用jdk的ThreadPoolExecutor，默認(rèn)threads數(shù)為200，并且默認(rèn)采用了SynchronousQueue隊(duì)列，而如果用戶(hù)配置的隊(duì)列長(zhǎng)度大于0時(shí)，則會(huì)采用LinkedBlockingQueue隊(duì)列。

如果某個(gè)線(xiàn)程因?yàn)閳?zhí)行異常而結(jié)束，那么線(xiàn)程池會(huì)添加一個(gè)新的線(xiàn)程。

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

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

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

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

排查思路

第一階段：

由于10.33.xx.xxx這臺(tái)機(jī)器出現(xiàn)線(xiàn)程池耗盡的時(shí)候，伴隨出現(xiàn)了一次時(shí)間比較久的ygc;所以懷疑是因?yàn)閥gc時(shí)間較長(zhǎng)，導(dǎo)致了機(jī)器資源緊張，從而拖垮了線(xiàn)程池;

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時(shí)間這么長(zhǎng)：

這里給大家簡(jiǎn)單說(shuō)明下為什么IO高會(huì)導(dǎo)致GC時(shí)間長(zhǎng)

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

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

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

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

(1)標(biāo)記-標(biāo)記出來(lái)活著的對(duì)象 ----> (2) 將對(duì)象從eden區(qū)復(fù)制到survior區(qū) -----> (3)清理eden區(qū)

理論上來(lái)說(shuō)第三步的時(shí)間是一定的，那可能時(shí)間會(huì)比較久的要么在第一步，要么在第二步

如果是第一步標(biāo)記時(shí)間過(guò)長(zhǎng)，就意味著本次GC之前，eden區(qū)存在大量的小對(duì)象(因?yàn)閑den區(qū)大小是一定的)，量級(jí)應(yīng)該是正常的對(duì)象數(shù)量的數(shù)十倍

如果是第二步時(shí)間過(guò)長(zhǎng)的話(huà)，那么存在以下可能：

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

2.標(biāo)記完之后仍然有大量碎片化的小對(duì)象存在

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

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

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

在我們無(wú)法驗(yàn)證的時(shí)候，第二臺(tái)機(jī)器出現(xiàn)了同樣的問(wèn)題，準(zhǔn)備再次jump日志的時(shí)候，回過(guò)頭來(lái)看了一下GC日志，發(fā)現(xiàn)GC正常。所以推翻階段一結(jié)論

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

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

比如使用top常見(jiàn)分析步奏：

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

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

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

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

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

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

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

開(kāi)啟階段二的排查：

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

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

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

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

那就是在報(bào)警時(shí)間段，cpu，cpu_iowait, 指標(biāo)會(huì)飆升，磁盤(pán)IO則呈現(xiàn)不間斷鋸齒狀，其余指標(biāo)基本不存在波動(dòng)

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

因此似乎得到了答案磁盤(pán)IO較高，導(dǎo)致cpu_iowait變高，cpu等IO，瞬間分配不到時(shí)間片，rt就會(huì)抖動(dòng)。

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

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

接下來(lái)我們看下trace 他到底是怎么工作的。

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

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

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

總結(jié)

其實(shí)我們?cè)谂挪閱?wèn)題的時(shí)候，我們很容易會(huì)被一些其他的表象給迷惑了，認(rèn)為本來(lái)是果的關(guān)系變成了因，但是這個(gè)本來(lái)也就是一個(gè)復(fù)雜的過(guò)程，只能是通過(guò)自己不斷的積累，不斷的學(xué)習(xí)過(guò)程，所以寫(xiě)下這篇文章希望能對(duì)大家有一定的幫助.

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

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

做一行愛(ài)一行嘛，我是敖丙，你知道的越多，你不知道的越多，我們下期見(jiàn)。