从应用到内核查接口超时(上)

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

排查过程走了很多弯路,由于眼界和知识储备问题,也进入了一些思维误区,希望此问题能以后再查询此类问题时能有所警示和参考;而且很多排查方法和思路都来自于部门 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 定位

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

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/wppdxg.html