从应用到内核查接口超时（上）

时间 2019-11-06

标签应用核查接口超时繁體版

原文原文链接

问题

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

排查过程走了不少弯路，因为眼界和知识储备问题，也进入了一些思惟误区，但愿此问题能之后再查询此类问题时能有所警示和参考；并且不少排查方法和思路都来自于部门 leader 和组里大神给的提示和启发，总结一下也能对这些知识有更深的理解。github

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

转载随意，文章会持续修订，请注明来源地址：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 就能够成为一个重要的排查工具。dom

查看 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。

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

固然还有一个很是重要的点，贯穿始末，那就是 数据支持，排查过程当中必定要有数据做为支持。经过总量、百分比数据的先后对比来讲服其余人相信你的理论，也就是用数听说话。

关于本文有什么疑问能够在下面留言交流，若是您以为本文对您有帮助，欢迎关注个人微博或 GitHub 。您也能够在个人博客REPO 右上角点击 Watch 并选择 Releases only 项来 订阅 个人博客，有新文章发布会第一时间通知您。