一次 Log4j2 日志停顿问题的排查

问题

之前的博文中说过最近在查一个问题，花费了近两个星期，问题算是有了一个小结，是时候总结一下了。

排查过程走了很多弯路，由于眼界和知识储备问题，也进入了一些思维误区，希望此问题能以后再查询此类问题时能有所警示和参考；而且很多排查方法和思路都来自于部门 leader 和 组里大神给的提示和启发，总结一下也能对这些知识有更深的理解。

这个问题出现在典型的高并发场景下，现象是某个接口会偶尔超时，查了几个 case 的日志，发现 httpClient 在请求某三方接口结束后输出一条日志时间为 A，方法返回后将请求结果解析成为 JSON 对象后，再输出的日志时间为 B， AB之间的时间差会特别大，100-700ms 不等，而 JSON 解析正常是特别快的，不应该超过 1ms。

转载随意，请注明来源地址：https://zhenbianshu.github.io

GC

首先考虑导致这种现象的可能：

• 应用上有锁导致方法被 block 住了，但 JSON 解析方法上并不存在锁，排除这种可能。
• JVM 上，GC 可能导致 STW。
• 系统上，如果系统负载很高，操作系统繁忙，线程调度出现问题可能会导致这种情况，但观察监控系统发现系统负载一直处于很低的水平，也排除了系统问题。

我们都知道 JVM 在 GC 时会导致 STW，进而导致所有线程都会暂停，接下来重点排查 GC 问题。

首先我们使用 jstat 命令查看了 GC 状态，发现 fullGC 并不频繁，系统运行了两天才有 100 来次，而 minorGC 也是几秒才会进行一次，且 gcTime 一直在正常范围。

由于我们的 JVM 在启动时添加了 -XX:+PrintGCApplicationStoppedTime 参数，而这个参数的名字跟它的意义并不是完全相对的，在启用此参数时，gclog 不仅会打印出 GC 导致的 STW，其他原因导致的 STW 也会被记录到 gclog 中，于是 gclog 就可以成为一个重要的排查工具。

查看 gclog 发现确实存在异常状况，如下图：

系统 STW 有时会非常频繁地发生，且持续时间也较长，其中间隔甚至不足 1ms，也就是说一次停顿持续了几十 ms 之后，系统还没有开始运行，又会进行第二次 STW，如上图的情况，系统应该会一次 hang 住 120ms，如果次数再频繁一些，确实有可能会导致接口超时。

安全点和偏向锁

安全点日志

那么这么频繁的 STW 是由什么产生的呢，minorGC 的频率都没有这么高。

我们知道，系统在 STW 前，会等待所有线程安全点，在 安全点 里，线程的状态是确定的，其引用的 heap 也是静止的，这样，JVM 才能安心地进行 GC 等操作。至于安全点的常见位置和安全点的实现方式网卡有很多文章介绍这里不再多提了，这里重点说一下安全点日志。

安全点日志是每次 JVM 在所有线程进入安全点 STW 后输出的日志，日志记录了进入安全点用了多久，STW 了多久，安全点内的时间都是被哪个步骤消耗的，通过它我们可以分析出 JVM STW 的原因。

服务启动时，使用 -XX:+UnlockDiagnosticVMOptions -XX:+PrintSafepointStatistics -XX:+LogVMOutput -XX:LogFile=./safepoint.log 参数，可以将安全点日志输出到 safepoint.log 中。

在安全点日志中，我发现有很多下图类似的日志输出：

从前面的 vmopt 列可以得知，进入安全点的原因是 RevokeBias ， 查资料得知，这是在释放 偏向锁 。

偏向锁

偏向锁是 JVM 对锁的一种优化，JVM 的开发人员统计发现绝大部分的锁都是由同一个线程获取，锁争抢的可能性很小，而系统调用一次加锁释放锁的开销相对很大，所以引入偏向锁默认锁不会被竞争，偏向锁中的 “偏向” 便指向第一个获取到锁的线程。在一个锁在被第一次获取后，JVM 并不需要用系统指令加锁，而是使用偏向锁来标志它，将对象头中 MarkWord 的偏向锁标识设置为1，将偏向线程设置为持续锁的线程 ID，这样，之后线程再次申请锁时如果发现这个锁已经 “偏向” 了当前线程，直接使用即可。而且持有偏向锁的线程不会主动释放锁，只有在出现锁竞争时，偏向锁才会释放，进而膨胀为更高级别的锁。

有利则有弊，偏向锁在单线程环境内确实能极大降低锁消耗，但在多线程高并发环境下，线程竞争频繁，而偏向锁在释放时，为了避免出现冲突，需要等到进入全局安全点才能进行，所以每次偏向锁释放会有更大的消耗。

明白了 JVM 为什么会频繁进行 STW，再修改服务启动参数，添加 -XX:-UseBiasedLocking 参数禁用偏向锁后，再观察服务运行。

发现停顿问题的频率下降了一半，但还是会出现，问题又回到原点。

Log4j

定位

这时候就需要猜想排查了。首先提出可能导致问题的点，再依次替换掉这些因素压测，看能否复现来确定问题点。

考虑到的问题点有 HttpClient、Hystrix、Log4j2 。使用固定数据替换了三方接口的返回值，删去了 Hystrix，甚至将逻辑代码都删掉，只要使用 Log4j2 输出大量日志，问题就可以复现，终于定位到了 Log4j2，原来是监守自盗啊。。

虽然定位到 Log4j2，但日志也不能不记啊，还是要查问题到底出在哪里。

使用 btrace 排查 log4j2 内的锁性能。

首先考虑 Log4j2 代码里的锁，怀疑是由于锁冲突，导致输出 log 时被 block 住了。

查看源码，统计存在锁的地方有三处：

• rollover() 方法，在检测到日志文件需要切换时会锁住进行日志文件的切分。
• encodeText() 方法，日志输出需要将各种字符集的日志都转换为 byte 数组，在进行大日志输出时，需要分块进行。为了避免多线程块之间的乱序，使用 synchronized 关键字对方法加锁。
• flush() 方法，同样是为了避免不同日志之间的穿插乱序，需要对此方法加锁。

具体是哪一处代码出现了问题呢，我使用 btrace 这一 Java 性能排查利器进行了排查。

使用 btrace 分别在这三个方法前后都注入代码，将方法每次的执行时间输出，然后进行压测，等待问题发生，最终找到了执行慢的方法: encodeText() 。

排查代码并未发现 encodeText 方法的异常（千锤百炼的代码，当然看不出什么问题）。

使用 jmc 分析问题

这时，组内大神建议我使用 jmc 来捕捉异常事件。 给 docker-compose 添加以下参数来启用环境的 JFR。

environment:
   - JFR=true
   - JMX_PORT=port
   - JMX_HOST=ip
   - JMX_LOGIN=user:pwd

在记录内查找停顿时间附近的异常事件，发现耗时统计内有一项长耗时引人注目，调用 RandomAccessFile.write() 方法竟然耗时 1063 ms，而这个时间段和线程 ID 则完全匹配。

查看这个耗时长的方法，它调用的是 native 方法 write() 。。。

native 方法再查下去就是系统问题了，不过我比较怀疑是 docker 的问题，会再接着排查，等有结论了再更新。

解决

问题总是要解决的，其实也很简单：

• 服务少记一些日志，日志太多的话才会导致这个问题。
• 使用 Log4j2 的异步日志，虽然有可能会在缓冲区满或服务重启时丢日志。

小结

查问题的过程确实学习到了很多知识，让我更熟悉了 Java 的生态，但我觉得更重要的是排查问题的思路，于是我总结了一个排查问题的一般步骤，当作以后排查此类问题的 checkList。

1. 尽量分析更多的问题 case。找出他们的共性，避免盯错问题点。比如此次问题排查开始时，如果多看几个 case 就会发现，日志停顿在任何日志点都会出现，由此就可以直接排除掉 HttpClient 和 Hystrix 的影响。
2. 在可控的环境复现问题。在测试环境复现问题可能帮助我们随时调整排查策略，极大地缩短排查周期。当然还需要注意的是一定要跟线上环境保持一致，不一致的环境很可能把你的思路带歪，比如我在压测复现问题时，由于堆内存设置得太小，导致频繁发生 GC，让我错认为是 GC 原因导致的停顿。
3. 对比变化，提出猜想。在服务出现问题时，我们总是先问最近上线了什么内容，程序是有惯性的，如果没有变化，系统一般会一直正常运行。当然变化不止是时间维度上的，我们还可以在多个服务之间对比差异。
4. 排除法定位问题。一般我们会提出多个导致问题的可能性，排查时，保持一个变量在变化，再对比问题的发生，从而总结出变量对问题的影响。
5. 解决。当我们定位到问题之后，问题的解决一般都很简单，可能只需要改一行代码。

当然还有一个非常重要的点，贯穿始末，那就是 数据支持 ，排查过程中一定要有数据作为支持。通过总量、百分比数据的前后对比来说服其他人相信你的理论，也就是用数据说话。

关于本文有什么疑问可以在下面留言交流，如果您觉得本文对您有帮助，欢迎关注我的微博 或 GitHub 。