案发

小光是一名私家侦探，是小光侦探事务所的负责人。这天，他正在事务所中喝茶，突然接到警官M的电话，说接到线上总共三台机器，有一台机器报警，Java堆内存占用超过95%，无法正常得到服务器的响应。小光安排警官M保留好现场，急匆匆的赶往了现场…

路上

在前往现场的路上，小光思考了以下几个问题：

1. 什么情况下会出现堆内存

   猜测可能是：

   • 瞬时并发数增大，且不能快速返回。这种情况需要一些线程的调用栈中，引用了大量的实例才可以占满堆内存。
   • 程序中有bug，导致死循环，在循环体中一直有分配内存的操作，且不是临时变量。

   关键是分配大量内存，且无法被有效GC。

2. 如何去定位问题
   • 最直接的方式，堆dump，使用MAT或者JVisualVm来分析dump文件，找出是哪里占用了大量的堆内存。
   • 当1无法执行时，可以使用jdk自带的一些工具，如jmap来分析内存。堆有可能是dump不出来的，因为线上堆大小是8G，且同一台物理机有多个服务在运行，可能会影响其他服务。
   • 内存作为主要分析对象，基于上述猜测1，还需要使用jstack导出线程栈信息。

现场

到达现场后，小光立即着手从现场找到有用的线索，分别在案发现场(问题JVM)做了以下几件事

1. 尝试进行整个案发现场的备份，即堆dump，但被告知堆内存太大，无法进行dump
2. 尝试使用JMX连接目标JVM

   以失败告终，JVisualVM长时间无法连接。(为什么无法连接成功，参考思考1)

3. SSH连接线上服务器，使用JDK自带工具尝试获取线索
   • ps -ef | grep java：找到目标jvm的pid
   • jmap -histo 目标jvm的pid | head -20：查看Class与对应实例占用情况。但是以失败告终，提示： Attaching to process ID 3991, please wait…
     Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can’t attach to the process
   • 尝试jmap无果，接着尝试jstack：jstack 目标jvm的pid：一样以失败告终，提示基本同上

   可能是当前用户无权限导致的。但是jmx应该不是，思考失败原因，参考归档1

   好在警官M在之前已经jmap出来一部分有效信息了，参考如下图：

   

   但是，根据这个线索，只能定位到是String导致堆内存占满的，并没有其他有效的信息，而String对象是整个程序运行期间处处都有使用的，很难去直接定位到问题所在…

至此，现场勘查基本完成，但是并没有什么收获有效的可一次定位问题的信息。只能清理现场、重启服务，以防止影响后续服务。

现场监控信息

现场已经被清理了，但是现场还有一些监控信息。同时询问大致案发时间，是八点三十分左右，对部分内容取8-9点之间的信息，包括有以下内容：

1. 应用日志

   请求M警官协助，拉取了问题机当天的所有日志，一起另外一台没有问题的机器的所有日志，方便做差异分析。

2. GC日志

   在堆内存几乎占满时，GC时间也变的很长，GC日志有一定的参考价值。

3. 监控日志

   查看应用日志目录，发现有dkimi目录，看了下里面大致内容，发现是dkimi这个agent层的一些日志，也包括了一些有用信息，但是文件较大没有拉出来，有需要的时候自己去服务器上查看。

4. 监控平台matrix

   monitor-matrix.zeus 

线索分析

线索有以下内容：

1. 一张jmap图
2. 应用所有日志
3. GC日志
4. dkimi日志
5. 监控平台图表
6. 项目源码

直接从1、3、4、5中并不能直接分析出问题所在，但是可以根据这些信息得出一个非常有价值的线索：案发时间

1. 确定案发时间

由图4可知，案发时间在8:24分左右，但不确定该监控平台的监控间隔，以及时间的准确性。通过检查dkimi日志，发现每隔30s会自动上报当前jvm状态json数据，状态中包括了jvm:gc:ParNew:time，即gc时间。

cat dkimi-agent.2018-01-10.log | grep '2018-01-10 08:2[2-5]:.*HeartB.*jvm:gc:ParNew:time'

2018-01-10 08:22:26 - jvm:gc:ParNew:time:2107
2018-01-10 08:22:56 - jvm:gc:ParNew:time:2107
2018-01-10 08:23:26 - jvm:gc:ParNew:time:2128
2018-01-10 08:23:56 - jvm:gc:ParNew:time:9462
2018-01-10 08:24:28 - jvm:gc:ParNew:time:19735
2018-01-10 08:24:59 - jvm:gc:ParNew:time:21332
2018-01-10 08:25:44 - jvm:gc:ParNew:time:22556

取22分到25分的数据，大致定位了时间为23-24分钟之间。

2. 取案发时间区间监控日志

cat all_is_well.log | grep '20180110-08:2[3-4]'

在拉取日志后，小光的智商突然下线…通过通读两台机器这一分钟的所有日志后，没有发现任何异常，所以也就没有得到任何结论…

在漫无目的的查看日志没有结果之后，开始怀疑起了日志区间，从此开始进入了误区…

3. 进入误区

先从日志中报error的地方入手，虽然error不会导致堆内存溢出，但是或许会有一些有用的信息。