关于jvm:接口偶尔超时竟又是JVM停顿的锅

原创：扣钉日记（微信公众号 ID：codelogs），欢送分享，转载请保留出处。

继上次咱们 JVM 进展十几秒的问题解决后，咱们零碎终于稳固了，再也不会无端重启了！
这是之前的文章：耗时几个月，终于找到了 JVM 进展十几秒的起因

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

有了上次 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 机制：
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/jd…
次要办法：SafepointSynchronize::begin, SafepointSynchronize::block,SafepointSynchronize::end

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

难道咱们什么代码用法，导致线程在 jvm 外部执行耗时过长？特地是在 jvm 社区找到一个提议，即倡议在 System.arraycopy 中增加 safepoint，让我也有点狐疑它了，但如何证实呢？
提议链接：https://bugs.openjdk.org/brow…。

通过一段时间理解，发现目前剖析 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 队列上，也就是说线程基本没有被调度！它要么在睡眠，要么被限度调度！

联想到咱们 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/1…，可见很多时候，遇到的问题，他人早就遇到过并分享了，要害是这种文章被大量低质量文章给吞没了，没找到问题前，你基本搜寻不到！

哎，分享流传了常识，同时也妨碍了常识流传！

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

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

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

关于jvm:接口偶尔超时竟又是JVM停顿的锅

简介

查看 safepoint 日志

深刻 safepoint 机制

async-profiler 剖析 safepoint

柳暗花明

调度提早与内存不足

cgroup 机制

总结

往期内容