[转帖]接口偶尔超时，竟又是JVM停顿的锅！

接口,偶尔,超时,jvm,停顿 · 浏览次数 : 0

小编点评

**内容摘要** * safepoint原理是什么？ * spin与block阶段耗时长代表了什么？ * 使用async-profiler分析safepoint的方法。 * 容器内可通过/proc/<pid>/task/<tid>/schedstat测量进程调度延迟。 * 容器内可通过/sys/fs/cgroup/cpu,cpuacct/cpu.stat测量容器CPU受限情况。 * 往期内容#耗时几个月，终于找到了JVM停顿十几秒的原因密码学入门神秘的backlog参数与TCP连接队列mysql的timestamp会存在时区问题？真正理解可重复读事务隔离级别字符编码解惑。 * 生成内容时需要带简单的排版

正文

https://www.cnblogs.com/codelogs/p/16391159.html

简介#

继上次我们JVM停顿十几秒的问题解决后，我们系统终于稳定了，再也不会无故重启了！
这是之前的文章：耗时几个月，终于找到了JVM停顿十几秒的原因

但有点奇怪的是，每隔一段时间，我们服务接口就会有一小波499超时，经过查看gc日志，又发现JVM停顿了好几秒！

查看safepoint日志#

有了上次JVM停顿排查经验后，我马上就检查了gc日志与safepoint日志，发现如下日志：

$ cat gc-*.log | awk '/application threads were stopped/ && $(NF-6)>1'|tail
2022-05-08T16:40:53.886+0800: 78328.993: Total time for which application threads were stopped: 9.4917471 seconds, Stopping threads took: 9.3473059 seconds
2022-05-08T17:40:32.574+0800: 81907.681: Total time for which application threads were stopped: 3.9786219 seconds, Stopping threads took: 3.9038683 seconds
2022-05-08T17:41:00.063+0800: 81935.170: Total time for which application threads were stopped: 1.2607608 seconds, Stopping threads took: 1.1258499 seconds

$ cat safepoint.log | awk '/vmop/{title=$0;getline;if($(NF-2)+$(NF-4)>1000){print title;print $0}}'
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
78319.500: G1IncCollectionPause             [     428          0              2    ]      [     0  9347  9347     7   137    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
81903.703: G1IncCollectionPause             [     428          0              4    ]      [     0  3903  3903    14    60    ]  0
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
81933.906: G1IncCollectionPause             [     442          0              1    ]      [     0  1125  1125     8   126    ]  0

从日志上可以看到，JVM停顿也是由safepoint导致的，而safepoint耗时主要在block阶段！

通过添加JVM参数-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=1000后，可打印出哪些线程超过1000ms没有到达safepoint，如下：

可以看到都是一些http或grpc的worker线程没走到safepoint，但为啥没到达safepoint，看不出关键，只好又去网上搜索了。

深入safepoint机制#

safepoint机制：
JVM在做某些特殊操作时(如gc、jmap等)，需要看到一致的内存状态，而线程运行过程中会一直修改内存，所以JVM做这些特殊操作前，需要等待这些线程停下来，而停下来的机制就是safepoint。

在上面的safepoint日志中，spin与block都是等待线程进入safepoint的耗时，而vmop就是需要在安全点执行的JVM操作耗时，遗憾的是，网上讲safepoint的文章虽多，但基本没有将block阶段与spin阶段区别讲清楚的！

没办法，只能去看看JVM内部safepoint的实现代码了，在阅读了safepoint.cpp后，对spin与block的区别也大致有点理解了，如下：

jvm中其实线程状态主要有3种thread_in_Java、thread_in_vm、thread_in_native。
线程执行到jvm管控以外的代码时(如内核代码)，线程状态会变为thread_in_native，jvm会认为它已经在安全区域(Safe Region)，故不需要等待其到达safepoint，当它从thread_in_native状态返回时，会自行挂起。
线程在执行java代码时，线程状态是thread_in_Java，这种线程jvm需要等待它执行到safepoint后，将其挂起或自行挂起。
线程在执行jvm内部代码时，线程状态是thread_in_vm，比如线程执行System.arraycopy，由于jvm内部并没有放置safepoint，jvm必须等待其转换到thread_in_native或thread_in_Java才能将其挂起或自行挂起。

而spin阶段实际在做两件事情，一是将thread_in_native状态的线程刨除掉，这并不会太耗时，二是轮询各线程状态，等待thread_in_Java状态的线程变为其它状态(如走到了safepoint)，这也是为什么counted loop这种代码会导致spin阶段耗时高，因为它是thread_in_Java状态的。

而block阶段实际就是在等待thread_in_vm状态的线程走到safepoint，与spin不同的是，safepoint线程将自己挂起，以等待最后一个thread_in_vm线程到达safepoint后将其唤醒。

如果看完我的描述，还是无法理解，强烈建议大家自己去阅读下safepoint源码，要看懂大概脉络还是不难的，而网上文章用来了解一些基础知识即可，不必费力看太多。
safepoint源码：http://hg.openjdk.java.net/jdk8u/jdk8u/hotspot/file/818b1963f7a2/src/share/vm/runtime/safepoint.cpp
主要方法：SafepointSynchronize::begin, SafepointSynchronize::block,SafepointSynchronize::end

回到之前遇到的问题，我们是block阶段耗时长，这是在等待thread_in_vm状态的线程到达safepoint，而线程处于thread_in_vm状态则说明线程在运行JVM内部代码。

难道我们什么代码用法，导致线程在jvm内部执行耗时过长？特别是在jvm社区找到一个提议，即建议在System.arraycopy中添加safepoint，让我也有点怀疑它了，但如何证明呢？
提议链接：https://bugs.openjdk.org/browse/JDK-8233300。

async-profiler分析safepoint#

经过一段时间了解，发现目前分析safepoint主流工具如下：

JFR：由oracle提供，在jdk11才完全可用，由于我们是jdk8，故放弃之。
async-profiler：一款开源的JVM分析工具，提供了分析safepoint的选项，选它！

async-profiler提供了--ttsp的选项，用来分析safepoint事件，如下：

# 下载async-profiler
$ wget https://github.com/jvm-profiling-tools/async-profiler/releases/download/v2.8/async-profiler-2.8-linux-x64.tar.gz && tar xvf async* && cd async*

# 启动async-profiler采集safepoint时的线程栈
$ ./profiler.sh start -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jps

# 发现safepoint问题产生后，停止采集并导出线程栈
$ ./profiler.sh stop  -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jps

# 线程栈转换为火焰图工具
$ wget https://github.com/jvm-profiling-tools/async-profiler/releases/download/v2.8/converter.jar
$ java -cp converter.jar FlameGraph /tmp/tts.collapsed tts.html

最开始，抓到的火焰图是这样的，如下：

由于我使用的是-e wall选项，这会把等待状态的线程栈也抓取下来，而safepoint发生时，大多数线程都会等待，所以火焰图中包含了太多无效信息。

于是，我调整为使用--all-user选项，这会只抓取在CPU上跑着的线程栈，同时将--ttsp调整为--begin SafepointSynchronize::print_safepoint_timeout --end RuntimeService::record_safepoint_synchronized，以使得async-profiler仅在发生超时safepoint时才采集线程栈，因为safepoint超时的时候会调用SafepointSynchronize::print_safepoint_timeout方法打印上面介绍过的超时未到safepoint线程的日志。

调整后，抓到的火焰图是这样的，如下：

发现没有到达safepoint的线程在执行getLoadAverage方法，这是java集成的prometheus监控组件，用来获取机器负载的，这能有什么问题？

我又发现，最后一个到达safepoint的线程会调用Monitor::notify_all唤醒safepoint协调线程，那使用-e Monitor::notify_all抓取的线程栈会更加准确，如下：

如上，最后一个到达safepoint的线程，确实就在执行getLoadAverage方法，可这个方法能有什么问题呢？我用strace看了一下，这个方法也就是从/proc/loadavg伪文件中读取负载信息而已。

柳暗花明#

问题一直没有排查出来，直到有一天，我突然发现，当一台容器上的jvm出现safepoint超时问题后，会不固定的每隔几小时出现一次，而同时间里，不出现问题的容器则稳得一批！

很显然，这个问题大概率和底层宿主机有关，我怀疑是部署在同一宿主机上的其它容器抢占了cpu导致，但在我询问运维宿主机情况时，运维一直说宿主机正常，也不知道他们是否认真看了！

又过了很久，有一次和隔壁组同事聊天，发现他们也遇到了超时问题，说是运维为了降机器成本，在宿主机上部署的容器越来越多！

再次出现问题后，我直接找运维要了宿主机的监控，我要自己确认，如下：

可以发现宿主机负载在11点到12点之间，多次飙升到100以上，而我们JVM发生暂停的时间与之基本吻合。

至此，问题原因已经找到，线程到不了safepoint，是因为它得不到CPU啊，和thread_in_vm状态无关，和getLoadAverage也无关，他们只是凑巧或运行频率较高而已，得不到CPU资源时，线程能停在任何位置上！

可是我有一个想法，如果运维死活说宿主机没有问题，不给监控，那在容器中的我们，是否能有证据证明问题在宿主机呢？

于是，我又尝试在容器内找证据了！

调度延迟与内存不足#

在Linux中可以无形拖慢线程运行速度的地方，主要有2点：

调度延迟：一瞬间有大量线程需要运行，导致线程在CPU队列上等待时间过长。
direct reclaim：分配内存时直接回收内存，一般情况下，Linux通过kswapd异步回收内存，但当kswapd回收来不及时，会在分配时直接回收，但如果回收过程涉及page swap out、dirty page writeback时，会阻塞当前线程。

direct reclaim可以通过cat /proc/vmstat|grep -E "pageoutrun|allocstall"来测量，其中allocstall就是direct reclaim发生的次数。
而线程调度延迟可以通过观测/proc/<pid>/task/<tid>/schedstat来测量，如下：

$ cat /proc/1/task/1/schedstat 
55363216 1157776 75

解释如下：

第一列：线程在CPU上执行的时间，单位纳秒(ns)
第二列：线程在CPU运行队列上等待的时间，单位纳秒(ns)
第三列：线程的上下文切换次数。

而由于我需要分析整个进程，上述信息是单个线程的，于是我写了一个脚本，汇总了各个线程的调度数据，以采集进程调度延迟信息，执行效果如下：

$ python -u <(curl -sS https://gitee.com/fmer/shell/raw/master/diagnosis/pidsched.py) `pgrep -n java`
2022-06-11T15:13:47  pid:1 total:1016.941ms idle:0.000ms    oncpu:( 1003.000ms max:51.000ms   cs:105  tid:23004  ) sched_delay:( 120.000ms  max:18.000ms   cs:36   tid:217    )
2022-06-11T15:13:48  pid:1 total:1017.327ms idle:415.327ms  oncpu:( 596.000ms  max:54.000ms   cs:89   tid:215    ) sched_delay:( 6.000ms    max:0.000ms    cs:255  tid:153    )
2022-06-11T15:13:49  pid:1 total:1017.054ms idle:223.054ms  oncpu:( 786.000ms  max:46.000ms   cs:117  tid:14917  ) sched_delay:( 8.000ms    max:0.000ms    cs:160  tid:63     )
2022-06-11T15:13:50  pid:1 total:1016.791ms idle:232.791ms  oncpu:( 767.000ms  max:75.000ms   cs:120  tid:9290   ) sched_delay:( 17.000ms   max:5.000ms    cs:290  tid:153    )

可以发现，正常情况下，调度延迟在10ms以下。

等到再次发生超时safepoint问题时，我检查了相关日志，如下：

我发现，在问题发生时，oncpu与sched_delay都是0，即线程即不在CPU上，也不在CPU队列上，也就是说线程根本没有被调度！它要么在睡眠，要么被限制调度！

cgroup机制#

联想到我们JVM是在容器中运行，而容器会通过cgroup机制限制进程的CPU使用量，经过一番了解，我发现在容器中，可以通过/sys/fs/cgroup/cpu,cpuacct/cpu.stat来了解进程被限制的情况，如下：

# cgroup周期的时间长度，一个周期是100ms
$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_period_us 
100000

# 容器分配的时间配额，由于我们是4核容器，所以这里是400ms
$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_quota_us 
400000

$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.stat
nr_periods 3216521
nr_throttled 1131
throttled_time 166214531184

cpu.stat解释如下：

nr_periods：经历的cgroup周期数
nr_throttled：容器发生调度限制的次数
throttled_time：容器被限制调度的时间，单位纳秒(ns)

于是，我写了一个小脚本来采集这个数据，如下：

$ nohup bash -c 'while sleep 1;do echo `date +%FT%T` `cat /sys/fs/cgroup/cpu,cpuacct/cpu.stat`;done' cpustat > cpustat.log &

再等到safepoint超时问题发生时，gc日志如下：

$ ps h -o pid --sort=-pmem -C java|head -n1|xargs -i ls -l /proc/{}/fd|awk '/gc-.*.log/{print $NF}'|xargs cat|awk '/application threads were stopped/ && $(NF-6)>1'|tail
2022-06-10T14:00:45.334+0800: 192736.429: Total time for which application threads were stopped: 1.1018709 seconds, Stopping threads took: 1.0070313 seconds
2022-06-10T14:11:12.449+0800: 193363.544: Total time for which application threads were stopped: 1.0257833 seconds, Stopping threads took: 0.9586368 seconds

cpustat.log如下：

cat cpustat.log |awk '{if(!pre)pre=$NF;delta=($NF-pre)/1000000;print delta,$0;pre=$NF}'|less

可以发现，在JVM停顿发生的时间点，容器被限制调度多次，总共限制的时间超3000ms！

在找到问题后，我通过cgroup与jvm stw关键字在google上搜索，发现在k8s中，container_cpu_cfs_throttled_seconds_total指标也代表了容器CPU被限制的时间，于是我立马将运维的监控面板改了改，如下：

可见时间点也基本吻合，只是这个数值偏小很多，有知道原因的可以告知下。

此外我也搜索到了问题类似的文章：https://heapdump.cn/article/1930426 ，可见很多时候，遇到的问题，别人早就遇到过并分享了，关键是这种文章被大量低质量文章给淹没了，没找到问题前，你根本搜索不到！

哎，分享传播了知识，同时也阻碍了知识传播！

总结#

排查这个问题的过程中，学到了不少新知识与新方法，总结如下：

safepoint原理是什么，spin与block阶段耗时长代表了什么。
使用async-profiler分析safepoint的方法。
容器内可通过/proc/<pid>/task/<tid>/schedstat测量进程调度延迟。
容器内可通过/sys/fs/cgroup/cpu,cpuacct/cpu.stat测量容器CPU受限情况。

往期内容#

耗时几个月，终于找到了JVM停顿十几秒的原因
 密码学入门
 神秘的backlog参数与TCP连接队列
 mysql的timestamp会存在时区问题？
真正理解可重复读事务隔离级别
 字符编码解惑