记一次线上CPU使用率飙升排查过程

前两天线上出了个CPU使用率飙升的问题。虽然最后是排查出来的,但排查时间太长了,思路还是有待提高。排查过程中用到非常多的JVM知识,一些是原来就会的,一些是边搞边学的(这就是慢的原因)。记录一下,下次遇到类似情况,整个时长应该可以缩短80%。

现象

相同的问题一共发生过两次。第一次发生在周二,当时看到的一个现象是CPU使用率飙升,另一个现象是rabbitmq的连接异常。当时第二个现象是一个很大的干扰项,我们怀疑的是rabbitmq中间件出问题了,后来中间件团队的人告诉我们,这个消息的q很久没有改动了,追查就断了。当时是用重启解决问题的。

第二次出现是周五,这时没有报任何异常,只是偶然的发现所有节点的CPU使用率都到了20%:

Alt

第二点是cms的GC时间突然上升:

Alt

然后开始根据这个现象逐步追查下去。

找出在使用CPU的线程

遇到事故的第一个反应当然是:最近有没有发布?没有。最近一次发布是一个礼拜前了,而且那次改动绝不可能导致这个问题。

想到的第一件要做的事是:找出正在使用CPU的线程。SOP:

  • top 或者 jps找到jvm实例的pid。
  • top -Hp pid 找到线程的pid
  • 将线程的pid转成16进制,用jstack就可以找到线程,然后可看到线程在跑什么代码。

这时因为我没有在生产环境跑jstack的权限,最后一步竟然扰攘了很久。最后找运维拉了jstack下来,定位到使用CPU的线程都是GC线程:

Alt

和第二个现象吻合:说明jvm正在进行大量的GC回收。

GC log

这时候登录到其中一个服务器看GC log,发现CMS的gc log不停地刷出来:说明jvm在不间断的执行full GC!

jstat没权限,于是这时又分析了一轮GC log,因为之前不熟悉这部分内容,所以很多信息都是边看边查。没查出个什么所以然。

推断出是内存泄漏

这时思路有点停滞了。回到监控页面再看集群的监控曲线,看看有没有别的线索。

这时看到堆内存的曲线不对:

Alt

图中表示的时间点也就是事故发生的时间点:正常情况下,一次full GC应该会回收大量内存,所以 正常的堆内存曲线应该是呈锯齿形。但在这一次full之后,堆内存再也没有下降。

于是推断: 堆中有大量不能回收的对象且在不停膨胀,使堆的使用占比超过full GC的触发阈值,但又回收不掉,导致full GC一直执行。

推断出是内存泄漏问题了,于是jmap走一波吧。

用MAT分析内存泄漏原因

dump下来的内存快照是7g的对象…由于之前没处理过这么大的对快照,所以又耽误了一些时间。

最后,成功拉到MAT里,罪魁祸首一下就原形毕露了:

Alt

堆内存使用了3.8G,有一个3.1G的大对象占了82%的容量!

在查看这个对象究竟是什么:是hibernate的queryPlanCache:

Alt

里面是一个巨型的hashmap:

Alt

找到关键词了:queryPlanCache。google一下,很快定位到原因:http://stackoverflow.com/questions/31557076/spring-hibernate-query-plan-cache-memory-usage

定位root cause

这事还没完,queryPlanCache里缓存了什么?到底是哪些sql语句被缓存了导致泄漏的?

MAT里支持OCL这种查询语法,找到了这个对象大量缓存的是什么:

Alt

根据sql语句,搜索一下代码,很容找到root cause了。

问题是之前为什么没有这个问题呢?

因为最近都没有发布,之前为什么没有这个问题呢?看了一下代码,原来是某个代码的错误逻辑:sql语句的生成依赖es的搜索结果,前几天es和db不同步,导致生成了这种in 几千个id的sql语句。

这个系统的qps很低,所以出问题了不是性能出现瓶颈,而是这个诡异的问题。

这问题最快的定位方法是什么?

写起来思路很清晰,但实际上整个过程花费了大半天的时间,其实排查的过程中,有很多关键点没有抓到,有很多现象,是可以凭经验条件反射的推断出原因的:

  1. 看到cpu使用率上涨,用jstack看使用cpu的线程,以及该线程在跑什么代码。
  2. 找到是gc线程,然后看gc曲线是否正常。
  3. 看堆内存曲线,正常的曲线是锯齿形的,如果不是,一次full GC之后内存没有明显下降,那基本可以推断发生内存泄漏了。
  4. 怀疑是内存泄漏的问题,可以跑jmap,然后拉到MAT分析。
  5. 第四步比较耗时的话,可以同时跑这个命令:jmap -histo pid。看看有没有线索。

如果在思路清晰的情况下,这几步可以缩短到10分钟以内甚至更快。

总结

这一次掌握的排查问题的思路:

  • 问题出现的时候有很多现象,要分清楚哪些现象是因,哪些现象是果,也就是说哪些导致问题出现,哪些现象是问题出现后带出来的。这点需要经验和冷静的推理。
  • jvm的一些工具:jstack、jmap、jstat、jhat。包括可视化工具:MAT、jvisualvm,一定要掌握,并且要会看。
  • 拿到进程状态,节点状态的SOP:找运维。

然后是在代码层面提高系统可用性的经验:

  • 主流程应对外部依赖尽量少,比如es,能直接用db完成主流程的场景,不要依赖其他存储。

参考

  • http://www.cnblogs.com/zhangxiaoguang/p/5792468.html
  • http://stackoverflow.com/questions/31557076/spring-hibernate-query-plan-cache-memory-usage