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

案发情景

小光是一名私家侦探，是小光侦探事务所的负责人。这天，他正在事务所中喝茶，突然接到警官 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