案发情景

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

猜测剖析

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

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

猜测可能是：

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

2.如何去定位问题？

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

现场侦查

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

尝试进行整个案发现场的备份，即堆dump，但被告知堆内存太大，无法进行dump
尝试使用JMX连接目标JVM
以失败告终，JVisualVM长时间无法连接。(为什么无法连接成功，参考思考1)
SSH连接线上服务器，使用JDK自带工具尝试获取线索

1）ps -ef | grep java：找到目标jvm的pid；
2）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；
3）尝试jmap无果，接着尝试jstack：jstack 目标jvm的pid：一样以失败告终，提示基本同上。

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

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

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

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

监控信息

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

应用日志

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

GC日志

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

监控日志

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

监控平台matrix

monitor-matrix.zeus

线索分析

线索有以下内容：

一张jmap图
应用所有日志
GC日志
dkimi日志
监控平台图表
项目源码

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

1. 确定案发时间

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

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

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

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

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

3. 进入误区

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

发现大量的Zookeeper异常，正常机器上的日志上并没有这个异常。莫非是这里的问题？开始看这里的源码…结果并没有什么收获(这就是所谓的病急乱投医吧)。

在仔细思考后，小光觉得这个异常一定与堆内存泄漏相关，莫非是这个报错之前有其他操作导致了这个问题？

在查看该时间点附近相关日志后，发现了：

莫非是这个sessionTimeout导致了上面的error，超时时间30s，那么是否有什么操作导致整个zookeeper连接阻塞了将近30s，无法有效与zookeeper进行交互导致的？上面发现session timed out个WARN从24:59开始就有了，查看这段日志相关的源码。没有发现任何异常…那么从这个前面开始找…

突然小光注意到了日志的事件，在8:24:59之前，最近一条日志竟然是8:24:37，中间二十多秒的日志去哪儿了？

缺少的二十多秒的日志，不可能是应用二十多秒没有日志输出，那么可以做到这种事情的，只有JVM的Stop The World!查看GC日志，发现GC时间确实有二十多秒。

由此判断ERROR日志基本上可以确定为GC暂定导致的，又回归了线索的原点。

4. 结合监控尝试找出嫌疑人

既然无法从ERROR中得到嫌疑人的有效信息，那就回归最开始的猜想：不能快速返回的请求。

可以看到上面日志中，有个WebFilter日志，最后有耗费的时长，拉取这段时间所有WebFilter日志：

看了下时间，并没有发现较长的响应时间。莫非是非Web请求导致的问题？

通过结构化日志到数据库，分析是否有非web线程的日志，并与正常机器的日志线程做对比，观察线程不一致的日志。如何结构化请看归档2：

其中n1是log4j的一个token，n2是一次web请求的生命周期中唯一的id，使用ThreadLocal实现的。

查了下151的workflowMessageListenerContainer日志，并没有什么异常…

至此，通过查看web相关请求的响应时间，排除了web相关请求，通过两台机器对比线程，排除了非web相关请求。这样问题就死在这里了…

小光抬眼看了下时间，已经到了晚上，思路也渐渐的不清晰了，暂时休息，明天继续。

5. 第二天，根据不在场证明确定嫌疑人

第二天，小光早早的起了床，并立了一个Flag，今天肯定能查到原因。因为昨晚他突然想到，当一个请求很耗时，甚至都不返回成为死循环时，可能连日志都没有。

同时，WebFilter的日志打印，是在finally中，当请求无法返回时，当然不会打印日志，昨天确实是忽略了这个问题，走了个大的弯路。

可以看到，只有finally中打印了日志，请求之前并没有打印日志。

那么是否有before和after都打印了日志，只要分析一下有before但是没有after的请求，那么就可以定位到问题点了！

想到这里，小光立马兴奋了一起，打开代码，找寻其他切入点，果然找到了一个WebInterceptor：

这里的before和after都打印了日志，且日志可以通过上面的n2即日志id来关联，没有日志id的时候可以使用请求地址来做对比。

结构化该请求相关的日志：

最终竟然真的找到了一个，而且有且只有一个：

查看时间点，也确实与案发时间对的上。为增加确定性，搜索该时间点之后线程catalina-exec-19的相关日志，发现在该时间点之后，就没有与此线程相关的日志了。由此，根据各线程的不在场证明可以基本确定嫌疑人为线程catalina-exec-19。

查看该条日志，得到请求信息，内容为：

推理破案

上次讲到最终定位到了犯罪嫌疑人，但是犯罪嫌疑人也不是吃素的，证据又不足以定罪，小光继续进行分析推理：

1. 嫌疑人拒不认罪

嫌疑人catalina-exec-19表示，没有凶器与行凶方式，证据是不充足的，不能进行逮捕。小光说，既然已知嫌疑人，以及凶器的一点线索，找到凶器只是时间问题，接着便埋头开始推理。

凶器的线索在日志中已经提供：请求地址是http://xxx.com/apply。同时该线程日志id为25216485580601。通过请求处理逻辑，以及调用过程中整个的日志信息，要想得到确切的问题点不会太难。

查看了代码才发现，上面想的还是有点简单了，这个接口的处理逻辑使用了模板模式，在模板模式中又嵌套了模板模式…与25216485580601相关的日志有71条，多为DataPermissionInterceptor类的日志，该类拦截所有dao层调用。

同时可知，在最后一条日志打印出来之后，该线程就没有再打印日志了，既没有报错也没有终止，那么大概率是死循环到某处了。

2. 找出凶器

通过请求参数"docType":[“103014”]找到对应的处理类，又通过层层模拟调用，结合日志，最终确定了问题发生在这段代码之中：

第71条日志是在getNoworkDays方法中打印的，而在UserProcessUtil.partDocToDetails后面又肯定会有新的日志产生，那么问题就发生在getNoworkDays方法体内和UserProcessUtil.partDocToDetails方法体内。(中间还遇到了日志与调用过程不一致的情况，后发现是因为dao层有@Cacheable注解，导致dao层逻辑没有经过DataPermissionInterceptor拦截器)

大致浏览了一下getNoworkDays，发现其中并没有特殊的方法调用和循环，嫌疑对象指向了UserProcessUtil.partDocToDetails方法：

查看transferDayAttenceDoc方法，其中隐去简单调用方法：

看到这段代码时，突然一道光穿透了小光的两耳(此处配名侦探柯南发现真相图)。下面那个while (true)非常可疑！

分析代码，循环终止条件是end.equals(newend)。newend则是startDay每次循环加一的结果，那么就是在某种情况下无法触发循环结束条件。

把请求中参数的"docStartTime":[“2018-01-08 08:22:50”],“docEndTime”:[“2018-01-10 08:22:56”]作为参数传入方法调用后，直接死循环了…结果是因为判断条件是拿全部String做的equals。而newend是经过日期格式化的，只取日期那一部分的值，而end则不做任何变化，那么一个日期与一个日期时间，做字符串equals是肯定不会相等的，必然会死循环。

到这里，小光以为案件已破。但是仔细一想，这样的话岂不是所以进到这里的逻辑，都会直接触发死循环，这一点又解释不通。

查看调用该方法传入的参数，发现start和end其实是经过格式化的日期字符串：

继续分析equals条件，当传入参数start大于传入参数end时，就永远不会触发结束条件。什么情况下会start大于end呢。

此时，又一道光闪过小光的眼前！DateFormat是线程不安全的，当多个线程使用同一个DateFormat时，有可能导致格式化后的结果不是自己想要的！看DateUtil.formatDate的代码：

果然与猜想的一样，此处使用了一个静态的DEFAULT_DATE_FORMAT来格式化日期，当多线程操作时，会导致start变为其他线程正在操作的时间。若此时间正好比end大，那么就会触发死循环。关于DateFormat线程不安全，参考归档3.

再看死循环逻辑，往一个list中丢String对象，与最开始jmap结果也一致！

3. 还原作案手法

在多线程并发环境下，并发越高，上面的问题越容易重现。这也解释了之前到月底发生该问题的现象，月底考勤系统并发增加，问题出现概率增高。

通过构建多线程共用同一个DateFormat，开启500个线程同时Format日期2018.01.12，主线程调用两次Format，分别Format 2018.01.08和2018.01.10，之后作为参数传入getBetweenDates，尝试几次后，果然重现：

4. 真相大白

至此，凶器已被找到，证据确凿，嫌疑人也已无法狡辩，只得乖乖俯首认罪。而小光也说出了那就他早就想说的话：真相永远只有一个！

后记

思考上面问题出现的原因：

Util作者写了个方法，期望该方法的使用者，传入参数时，一定符合他的约定。

而使用者在使用该方法时，也都严格按照该约定进行传参。

但是中间杀出了个程咬金，多线程环境下结果的不确定性，最终导致了严重的堆内存泄漏问题。

案件已经侦破，那么各位针对上面的问题，有什么好的解决方法吗？当然直接换线程安全的日期格式化工具是非常有必要的，方法中做参数的必要性校验也是有必要的。

插曲

归档

1.JVisualVM长时间无法连接、工具Attach失败的原因：

首先要了解一下这些工具执行的原理，为何会报出Attach失败？

这些工具的执行原理都是基于Sun公司的Attach API。通过com.sun.tools.attach.VirtualMachine类，调用attach(pid)方法，attach到目标JVM上。

那么目标JVM又是怎么觉察到attach进来一个工具呢？通过线程Signal Dispatcher来实现。当attach时，会对目标线程发出一个信号量，该信号量交由该线程处理，信号量处理程序发现是attach信号，检测Attach Listener线程是否启动，如果没有启动则启动一个Attach Listener线程，attach的具体操作交由Attach Listener执行。

attach到目标虚拟机后，真正逻辑的执行是靠Java Platform Debugger Architecture(JPDA)来进行的。

所有真正的执行还是要依赖目标JVM的，所以当目标JVM堆内存不足，且长时间GC占用CPU时间片时，Attach是很难执行的。

要想获取更相信的信息，请参考：

1）Java调试那点事

2）JPDA 体系概览

3）JVM Attach机制实现

2.结构化日志方式

1）脚本语言：Python、Node.js

2）sed命令

3）awk命令

4）grep命令

【参考脚本】

3.DateFormat线程不安全的原因

说严禁点，其实是SimpleDateFormat的parse和format方法线程不安全。究其原因是因为其中使用了一个共享的calendar变量来进行日期与实时间的处理。在format时，先进行了一个calendar的setTime操作。这里就导致了多线程环境下，结果的不一致。

4.上面虽然引起了堆内存大量占用，但是并没有OOM，思考原因

上面说了堆内存被大量占用，且有个死循环一直分配内存。奇怪的是却一直没有报出OutOfMemmoryError。这里需要去了解一下抛出OutOfMemmoryError的时机，参考JVM源码分析之临门一脚的OutOfMemoryError完全解读。

个人猜测是因为，尝试分配内存时，发现内存不足，尝试进行GC，一次GC时间达到了半分钟。GC后，由于有其他线程可以释放一部分内存，又可以让死循环多分配点内存，最终持续进行分配与GC，始终达不到触发OOM错误的时机，故没有抛出OOM。

END

写在后面的话：

第一次尝试这种写作风格，欢迎各位提出意见与建议。如果觉得文章不错，欢迎关注和点赞哈，您的支持是我最大的动力。本地还有一些存货，有机会的话我会继续写这个系列，希望大家支持.

本文转载自公众号贝壳产品技术（ID：gh_9afeb423f390）。

原文链接：

https://mp.weixin.qq.com/s/fSrWF4PFZkvky7rkeCf46w

创作场景

侦探剧场：堆内存神秘溢出事件