作者丨安琪拉的博客

來源丨安琪拉的博客

問題

一個(gè)在普通不過的周末，安琪拉在家里玩安琪拉，蹲在草叢正準(zhǔn)備給妲己一頓暴擊，手機(jī)突然收到線上告警短信，嚇得我一激靈，二技能放空，被妲己一套帶走，趁著復(fù)活間隙，趕緊從床上爬起來打開電腦。

起因:  消息隊(duì)列積壓了十幾萬消息，第一反應(yīng)，什么情況。。

趕緊穿衣服，對待線上問題要嚴(yán)肅。

如下圖，“待處…” 那一列就是指隊(duì)列中“待處理的”消息。

消息積壓，指的是消息的消費(fèi)速度跟不上生產(chǎn)的速度，消息在消息隊(duì)列中。

可以看到有好幾個(gè)分區(qū)已經(jīng)積壓了上萬條消息；

問題排查

立即開始問題排查，遇到線上問題，一定是保證最快速度止血，降低對業(yè)務(wù)的影響，然后再是排查原因，當(dāng)然有的問題也需要快速找到原因。

第一反應(yīng)是不是入口流量太大，處理消息的線程池核心線程數(shù)滿了，任務(wù)都在排隊(duì)，但是看了入口流量并沒有尖刺。

看監(jiān)控的消息消費(fèi)任務(wù)耗時(shí)，如下圖：

可以看到耗時(shí)在不斷增加。那就需要看處理耗時(shí)增加原因了，為什么處理任務(wù)的耗時(shí)上漲了。

查看消息消費(fèi)日志，如下：

發(fā)現(xiàn)有很多網(wǎng)絡(luò)接口超時(shí)的。

大致得出結(jié)論：消息處理任務(wù)依賴下游系統(tǒng)接口，連接下游接口超時(shí)，連接下游接口設(shè)置的超時(shí)時(shí)間不算短，為什么下游接口如此多SocketTimeOut呢？

下游系統(tǒng)也是我負(fù)責(zé)的系統(tǒng)，那重點(diǎn)開始看下游的系統(tǒng)監(jiān)控，發(fā)現(xiàn)相關(guān)的接口調(diào)用的單機(jī)耗時(shí)時(shí)間極不規(guī)律，如下圖所示：

對比一下日常這個(gè)接口的耗時(shí)時(shí)間，如下圖，日常都沒有超過100ms的：

查看下游系統(tǒng)的監(jiān)控大盤，發(fā)現(xiàn)了問題：

老年代GC次數(shù)暴漲，而且gc耗時(shí)都到了秒級別，1分鐘5～10秒，太恐怖了。

分析GC問題

找一臺機(jī)器，把GC回收dump下來分析，使用mat查看，如下圖所示：

一共七百多M空間，一個(gè)對象就占了640M空間，找到原因了，有內(nèi)鬼（大對象）。

繼續(xù)往下，看這個(gè)對象為什么會這么大，從GC Roots最短路徑如下，MAT的使用，以及JVM相關(guān)分析，感興趣可以微信公眾號【安琪拉的博客】回復(fù)JVM，拉你進(jìn)JVM交流群。

解釋下，上面主要有三列，第一列是內(nèi)存對象的類，重點(diǎn)在2，3列，Shallow Heap指的是對象本身占據(jù)的內(nèi)存大小， Retained Heap = 本身本身占據(jù)內(nèi)存大小 + 當(dāng)前對象可直接或間接引用到的對象的大小總和，換句話說，就是當(dāng)前對象如果被回收，能夠回收的內(nèi)存大小。

繼續(xù)看，第一步，查看誰引用了這個(gè)對象，找到自己代碼中的類，

第二步，查看這個(gè)對象TaggedMetricRegistry都引用了誰，為什么會占用這么大的內(nèi)存空間，如下圖所示，

找到罪魁禍?zhǔn)琢耍琺etrics這個(gè) ConcurrentHashMap 占了671M內(nèi)存，現(xiàn)在開始可以看下代碼，找到 TaggedMetricRegistry繼承自MetricRegistry，metrics 是MetricRegistry的成員變量，如下圖：

那為什么這個(gè) ConcurrentHashMap 占了這么大的內(nèi)存空間，并且GC也回收不掉呢？

我們繼續(xù)看MAT，分析 ConcurrentHashMap 占有的詳細(xì)內(nèi)存分布：

發(fā)現(xiàn)ConcurrentHashMap有幾個(gè)Node節(jié)點(diǎn)尤其大，

追下去，繼續(xù)

看到這個(gè)key，對應(yīng)在代碼中的位置，

你們可能好奇這段代碼是干嘛的呢？

這個(gè)代碼的作用是統(tǒng)計(jì)接口每次的執(zhí)行時(shí)間，它內(nèi)部update的源碼如下：

這個(gè)方法是統(tǒng)計(jì)接口的耗時(shí)、調(diào)用次數(shù)的，它內(nèi)部有一個(gè)measurements 的跳躍表，存放時(shí)間戳和統(tǒng)計(jì)指標(biāo)（耗時(shí)、調(diào)用次數(shù)）的鍵值對，設(shè)置的時(shí)間窗口是1分鐘，也就是它會存放1分鐘的統(tǒng)計(jì)數(shù)據(jù)在內(nèi)存中，當(dāng)然這里面有個(gè)采樣比，不是1分鐘的全量數(shù)據(jù)，可以看到采樣比是COLLISION_BUFFER決定的，然后1分鐘上報(bào)一次內(nèi)存數(shù)據(jù)到遠(yuǎn)端。問題就出現(xiàn)在這，因?yàn)檫@個(gè)耗時(shí)統(tǒng)計(jì)的函數(shù)的QPS非常高，1分鐘有數(shù)據(jù)頻繁產(chǎn)生的時(shí)候，會導(dǎo)致在一個(gè)時(shí)間窗口（1分鐘）measurements極速增長，導(dǎo)致內(nèi)存占用快速增長，但是因?yàn)橛袕?qiáng)引用，GC的時(shí)候也不會把這個(gè)回收掉，所有才出現(xiàn)了上面的那個(gè)情況。