现象
前阵子线上发布了一些功能,主要是针对客户群做的社群网络,大数据这边针对用户的通讯录、通话记录、设备等信息,计算其对应的社群网络,然后根据社群对应的指标来判断用户的风险情况。当然新老用户的逻辑有所区分,这里就不再深入阐述了。功能上线后,出现了一个比较诡异的事情:系统CPU和内存都飙升,几乎都快把主机撑爆了。
定位最消耗资源的线程
因为发布是在凌晨,使用app的用户还是比较少的,经过沟通,我们建议运维暂时先不下线新功能。给我们几分钟时间定位问题。这时候我们首先想到要查看是哪个线程最消耗资源。(以下示例为事后线下复现,非当时线上真实资源消耗情况)
查看java进程
ps -ef | grep kafka-1.0 | grep -v grep
查看进程中最消耗资源的线程
在我们查看到进程号以后,可以通过top命令查看对应进程中的线程,以及cpu使用情况
top -Hp 100728
转换为十六进制
printf "%x\n" 130870
可见线程号为:1ff36
接下来我们就需要用到jstack来查看
jstack 100728 > 100728.jstack
这样我们就把线上应用的堆栈信息给dump下来了,接下来我们可以看看jstack导出的文件主要有哪些内容,以及线程号为:1ff36的线程当时正在进行什么操作。截止目前我们使用的上面的示例实际并不是当时线上的截图,而是后续为了说明当时的场景做的。当时jstack导出的文件我们保留下来了,对应的最占用CPU资源的前几个线程为GC线程。我们有理由认为是内存被撑爆导致的频繁GC,进而导致CPU居高不下。 查看GC情况
/usr/local/jdk1.8.0_11/bin/jstat -gcutil 100728 1000 100
我们发现FGC特别频繁,几秒钟就会进行一次,因为full gc会导致stop the world所以这必然是有问题的,而S0,S1几乎为0,eden区和old区都占满了,即使进行了FGC依然无法回收,由此我们怀疑是在程序运行中产生了大对象无法回收导致频繁FGC:
使用IBM的dump文件分析工具
我们先看下jstack下来的文件内容:
推荐大家一个工具:IBM Thread and Monitor Dump Analyzer for Java(点击下载),真的是线程dump文件的分析利器,看起来非常直观。
使用该工具打开dump文件
我们发现其中有大量的Waiting on condition等待,它们都是调用的sun.misc.Unsafe.park(Native Method)方法,再看看Thread Details都是hbase连接在获取数据
这里很可能是因为获取了大量的数据导致的内存占用居高不下。但是目前也只能提供一个方向性的参考,并没有定位到具体的开发代码,我们看了这么多wait和调用的方法大多也都是定位到了开发框架的源码。我们可以通过搜索对应项目中的包,看看截止当时应用程序都执行了那些代码,如我们项目中所有的代码都是com.maiya开头的,很幸运目前用户流量还不大,并且调用的程序代码并不复杂,我们发现了一个可疑的地方:
如上图所示,正是本次上线的代码,正在调用hbase的查询接口,那么是否就是hbase表的问题呢,难道如我们上面所猜想的,因为数据量过大导致的出现了大对象?我们count了下对应的表,发现表数据达到了惊人的2亿数据。而且一个用户下有多条重复数据,HBase中为什么会有重复数据呢?原来是因为key设计的问题,导致本该覆盖的记录,并没有覆盖,而是新增了。在数据重复统计多次以后,数据量猛增。最终导致了上面的问题。
至此已经定位出来原因了,程序并不需要进行修改,只要对HBase表进行重构,数据入库逻辑修改即可。数据修正后,程序重启后也正常了。 实际上我们也可以通过jmap查看程序中的class对象占用内存情况。不过dump出来的文件一般都比较大,大家要慎重。
使用java自带的jvisualvm,可以分析heap.hprof文件中的内容:
使用jstack只能复现当时线程的方法栈,是一个静态的场景,所以一般要多导出几次,分析对比,如果某个应用程序线程在多次的jstack文件中一直存在,那么可能就需要我们多加关注了。