阿里面试原题:如何排查定位线上问题？

不知道你们经历过这种问题没有&＃xff0c;比如问你遇到过线上性能问题没有&＃xff0c;GC频繁&＃xff0c;CPU飙高&＃xff0c;任务队列积压&＃xff0c;线程池任务拒绝等等&＃xff0c;对于看重项目经验的面试官&＃xff0c;这种问题基本是标配&＃xff0c;问线上问题处理的经过&＃xff0c;问题定位&＃xff0c;排查的思路&＃xff0c;怎么做的业务快速止血。一方面考察候选人项目的真实性&＃xff0c;一般遇到线上问题大部分时候是系统主要负责人着手处理的&＃xff0c;所以如果你处理过线上问题&＃xff0c;也从侧面反映你的重要性。另外还能知道面试者是不是真的从原理上掌握了问题的根本原因&＃xff0c;对技术的热忱等。另外建议大家处理完线上问题&＃xff0c;排查了原因之后不要停&＃xff0c;把排查过程和问题原因记录下来&＃xff0c;一方面以后遇到类似问题可以基于已有的经验快速反应&＃xff0c;另外就是一定让自己的知识体系化&＃xff0c;怎么体系化呢? 就需要把日常的技术问题做归类总结。

这篇文章主要是给大家一个参考&＃xff0c;讲讲安琪拉在上家公司遇到的线上问题以及排查思路&＃xff0c;你们可能会好奇为什么不讲在阿里遇到的线上问题&＃xff0c;这个我也会讲&＃xff0c;但是因为很多数据要脱敏&＃xff08;马赛克&＃xff09;&＃xff0c;所以暂时先讲之前的&＃xff0c;这篇是很早之前写的了&＃xff0c;发布在博客园上。

铺垫太长了&＃xff0c;下面进入正题。

问题

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

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

赶紧穿衣服&＃xff0c;对待线上问题要严肃。

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

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

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

问题排查

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

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

看监控的消息消费任务耗时&＃xff0c;如下图&＃xff1a;

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

查看消息消费日志&＃xff0c;如下&＃xff1a;

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

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

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

对比一下日常这个接口的耗时时间&＃xff0c;如下图&＃xff0c;日常都没有超过100ms的&＃xff1a;

查看下游系统的监控大盘&＃xff0c;发现了问题&＃xff1a;

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

分析GC问题

找一台机器&＃xff0c;把GC回收dump下来分析&＃xff0c;使用mat查看&＃xff0c;如下图所示&＃xff1a;

一共七百多M空间&＃xff0c;一个对象就占了640M空间&＃xff0c;找到原因了&＃xff0c;有内鬼&＃xff08;大对象&＃xff09;。

继续往下&＃xff0c;看这个对象为什么会这么大

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

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

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

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

那为什么这个 ConcurrentHashMap 占了这么大的内存空间&＃xff0c;并且GC也回收不掉呢&＃xff1f;

我们继续看MAT&＃xff0c;分析 ConcurrentHashMap 占有的详细内存分布&＃xff1a;

发现ConcurrentHashMap有几个Node节点尤其大&＃xff0c;

追下去&＃xff0c;继续

看到这个key&＃xff0c;对应在代码中的位置&＃xff0c;

你们可能好奇这段代码是干嘛的呢&＃xff1f;

这个代码的作用是统计接口每次的执行时间&＃xff0c;它内部update的源码如下&＃xff1a;

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

如果大家对线上性能排查感兴趣的可以加我微信&＃xff0c;geekoftaste&＃xff0c;拉你进交流群。