起因:周末測試發現線上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。