[JVM]一次線上頻繁GC的問題解決


起因:周末測試發現線上mq消息積壓了十幾萬的消息,如下圖所示

每個隊列幾萬的消息,立即采取緊急措施,將隊列下線重新上線。

處理積壓消息的量,調用量起來了,很快消息積壓解決了。開始事件復盤。

首先分析是否是消息消費能力跟不上消息產生原因,看入口消息,QPS是29.6

消息消費QPS如下

事后開始分析原因,發現隊列積壓有如下異常:

 

 

超時時間設置的很長,大致分析出消息處理線程等待下游接口超時,連接下游接口設置的超時時間很長,為什么下游接口如此多SocketTimeOut呢?

 然后查看具體的超時接口,調用的下游站點發生SocketTimeout

查看下游站點接口的Cat,發現調用時間極不規律,如下圖所示

看日常的調用時間如下圖所示,都不超過100ms的:

再看部分機器的GC內存回收,驚呆了,因為這個站點有幾個月沒有重新發過版本,發現GC如下圖,壓根沒有年輕代的事,新申請的對象都需要在老年代申請,所以導致老年代一直回收。

找一台機器,把GC回收dump下來分析,使用mat查看,如下圖所示:

一共七百多M空間,一個對象就占了640M空間,找到原因了,繼續往下,看這個對象為什么會這么大,從GC Roots最短路徑如下,解釋下

Shallow Heap指的是對象本身占據的內存大小  Retained Heap = 本身本身占據內存大小 + 當前對象可直接或間接引用到的對象的大小總和,

換句話說,就是當前對象如果被回收,能夠回收的內存大小。

繼續看,第一步,查看誰引用了這個對象,找到自己代碼中的類,

第二步,查看這個對象TaggedMetricRegistry都引用了誰,為什么會占用這么大的內存空間,如下圖所示,

找到罪魁禍首了, 現在開始可以看下代碼,如下所示:

發現 TaggedMetricRegistry繼承自MetricRegistry,如下圖

metrics是個Map,MetricRegistry的成員變量,繼續回來看mat,看內部內存占用

如下圖所示,發現Map的有幾個Node節點尤其大,

追下去,繼續

看到這個key,對應在代碼中的位置,

 

開始代碼分析,這個代碼的作用是統計接口每次的執行時間,統計窗口是1分鍾,問題就出現在這,因為這個函數的QPS非常高,在update的源碼如下:

private final ConcurrentSkipListMap<Long, Long> measurements; 

@Override
public void update(long value) { if (count.incrementAndGet() % TRIM_THRESHOLD == 0) { trim(); } measurements.put(getTick(), value); }
private long getTick() {
for (; ; ) {
final long oldTick = lastTick.get();
final long tick = clock.getTick() * COLLISION_BUFFER;
// ensure the tick is strictly incrementing even if there are duplicate ticks
final long newTick = tick > oldTick ? tick : oldTick + 1;
if (lastTick.compareAndSet(oldTick, newTick)) {
return newTick;
}
}
private void trim() {
measurements.headMap(getTick() - window).clear();
}

 measurements是一個跳躍表,在1分鍾有數據頻繁產生的時候,會導致在一個時間窗口(1分鍾)measurements極速增長,導致內存快速增長,所以產生頻繁Yong GC,把這個Metric統計取消,問題Fixed。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM