百分百面试题:遇到过线上问题没有？

作者丨安琪拉的博客

来源丨安琪拉的博客

问题

一个在普通不过的周末，安琪拉在家里玩安琪拉，蹲在草丛正准备给妲己一顿暴击，手机突然收到线上告警短信，吓得我一激灵，二技能放空，被妲己一套带走，趁着复活间隙，赶紧从床上爬起来打开电脑。

起因:  消息队列积压了十几万消息，第一反应，什么情况。。

赶紧穿衣服，对待线上问题要严肃。

如下图，“待处…” 那一列就是指队列中“待处理的”消息。

消息积压，指的是消息的消费速度跟不上生产的速度，消息在消息队列中。

可以看到有好几个分区已经积压了上万条消息；

问题排查

立即开始问题排查，遇到线上问题，一定是保证最快速度止血，降低对业务的影响，然后再是排查原因，当然有的问题也需要快速找到原因。

第一反应是不是入口流量太大，处理消息的线程池核心线程数满了，任务都在排队，但是看了入口流量并没有尖刺。

看监控的消息消费任务耗时，如下图：

可以看到耗时在不断增加。那就需要看处理耗时增加原因了，为什么处理任务的耗时上涨了。

查看消息消费日志，如下：

发现有很多网络接口超时的。

大致得出结论：消息处理任务依赖下游系统接口，连接下游接口超时，连接下游接口设置的超时时间不算短，为什么下游接口如此多SocketTimeOut呢？

下游系统也是我负责的系统，那重点开始看下游的系统监控，发现相关的接口调用的单机耗时时间极不规律，如下图所示：

对比一下日常这个接口的耗时时间，如下图，日常都没有超过100ms的：

查看下游系统的监控大盘，发现了问题：

老年代GC次数暴涨，而且gc耗时都到了秒级别，1分钟5～10秒，太恐怖了。

分析GC问题

找一台机器，把GC回收dump下来分析，使用mat查看，如下图所示：

一共七百多M空间，一个对象就占了640M空间，找到原因了，有内鬼（大对象）。

继续往下，看这个对象为什么会这么大，从GC Roots最短路径如下，MAT的使用，以及JVM相关分析，感兴趣可以微信公众号【安琪拉的博客】回复JVM，拉你进JVM交流群。

解释下，上面主要有三列，第一列是内存对象的类，重点在2，3列，Shallow Heap指的是对象本身占据的内存大小， Retained Heap = 本身本身占据内存大小 + 当前对象可直接或间接引用到的对象的大小总和，换句话说，就是当前对象如果被回收，能够回收的内存大小。

继续看，第一步，查看谁引用了这个对象，找到自己代码中的类，

第二步，查看这个对象TaggedMetricRegistry都引用了谁，为什么会占用这么大的内存空间，如下图所示，

找到罪魁祸首了，metrics这个 ConcurrentHashMap 占了671M内存，现在开始可以看下代码，找到 TaggedMetricRegistry继承自MetricRegistry，metrics 是MetricRegistry的成员变量，如下图：

那为什么这个 ConcurrentHashMap 占了这么大的内存空间，并且GC也回收不掉呢？

我们继续看MAT，分析 ConcurrentHashMap 占有的详细内存分布：

发现ConcurrentHashMap有几个Node节点尤其大，

追下去，继续

看到这个key，对应在代码中的位置，

你们可能好奇这段代码是干嘛的呢？

这个代码的作用是统计接口每次的执行时间，它内部update的源码如下：

这个方法是统计接口的耗时、调用次数的，它内部有一个measurements 的跳跃表，存放时间戳和统计指标（耗时、调用次数）的键值对，设置的时间窗口是1分钟，也就是它会存放1分钟的统计数据在内存中，当然这里面有个采样比，不是1分钟的全量数据，可以看到采样比是COLLISION_BUFFER决定的，然后1分钟上报一次内存数据到远端。问题就出现在这，因为这个耗时统计的函数的QPS非常高，1分钟有数据频繁产生的时候，会导致在一个时间窗口（1分钟）measurements极速增长，导致内存占用快速增长，但是因为有强引用，GC的时候也不会把这个回收掉，所有才出现了上面的那个情况。