深入的安全点机制
在上面的安全点日志中，spin 和 block 是等待线程进入安全点的耗时，而 vmop 是需要在安全点执行的耗时的 JVM 操作。可惜，虽然网上有很多关于safepoint的文章，但基本上都没有把block stage和spin stage的区别解释清楚！
没办法，只能看JVM里面safepoint的实现代码。看了safepoint.cpp，对spin和block的区别有了一个大概的了解，如下：
实际上，jvm中存在三种主要的线程状态：thread_in_Java、thread_in_vm、thread_in_native。当线程执行jvm控制之外的代码（如内核代码）时，线程状态会变成thread_in_native，jvm会认为自己已经在安全区，所以不需要等待它到达安全点，当它从 thread_in_native 状态返回时，它会自行挂起。当一个线程执行java代码时，线程状态为thread_in_Java。这种线程jvm需要等待它执行到安全点，然后挂起或者自行挂起。当线程执行jvm的内部代码时，线程状态为thread_in_vm。例如，线程执行 System.arraycopy。由于安全点没有放在jvm内部，
自旋阶段实际上是在做两件事。一种是去掉thread_in_native状态的线程，不会花太多时间。另一种是轮询线程状态，等待thread_in_Java状态的线程改变到另一个状态（比如到达安全点），这也是计数循环代码导致自旋阶段耗时较长的原因，因为它在thread_in_Java 状态。
阻塞阶段实际上是在等待thread_in_vm状态的线程到达安全点。与自旋不同的是，安全点线程在到达安全点后会挂起自己以等待最后一个 thread_in_vm 线程唤醒。
如果你看了我的描述还是看不懂，强烈建议你自己阅读safepoint的源码。大致了解一下上下文并不难，网上的文章可以用来了解一些基础知识，所以不需要看太多。
安全点源代码：
主要方法：SafepointSynchronize::begin、SafepointSynchronize::block、SafepointSynchronize::end
回到我们之前遇到的问题，block阶段需要很长时间，就是等待thread_in_vm状态的线程到达安全点，而thread_in_vm状态的线程表示线程正在运行的内部代码JVM。
是否有任何代码使用导致线程在 jvm 内执行时间过长？特别是在jvm社区发现了一个提议在System.arraycopy中添加一个safepoint，这让我有点怀疑，但是如何证明呢？
建议链接：.
async-profiler 分析安全点
经过一段时间的了解，我发现目前分析safepoint的主流工具有以下几种：
JFR：由oracle提供，仅在jdk11中完全可用。由于我们是jdk8，所以放弃了。async-profiler：一个开源的JVM分析工具，提供分析safepoint的选项，选择它！
async-profiler 提供了 –ttsp 选项来分析安全点事件，如下：
# 下载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墙选项，所以这也会抓取处于等待状态的线程堆栈，而当安全点出现时，大部分线程都会等待，所以火焰图包含了太多的无效信息。
所以，我调整为使用 –all-user 选项，它只会抓取 CPU 上运行的线程堆栈，并将 –ttsp 调整为 –begin SafepointSynchronize::print_safepoint_timeout –end RuntimeService::record_safepoint_synchronized 以使异步-profiler 只在超时安全点发生时收集线程堆栈，因为当安全点超时时，它会调用 SafepointSynchronize::print_safepoint_timeout 方法来打印引入超时时尚未到达安全点的线程的日志。
调整后捕捉到的火焰图如下：
发现没有到达安全点的线程正在执行getLoadAverage方法。这是java集成的prometheus监控组件，用于获取机器负载。这有什么问题？
我还发现最后到达安全点的线程会调用 Monitor::notify_all 来唤醒安全点协调线程，所以 -e Monitor::notify_all 捕获的线程堆栈会更准确，如下：
如上，到达安全点的最后一个线程确实在执行 getLoadAverage 方法，但是这个方法有什么问题呢？我用strace看了一下，这个方法只是从/proc/loadavg伪文件中读取负载信息。
柳树与花
问题一直没查出来，有一天突然发现，当一个容器上的jvm出现safepoint timeout问题时，每隔几个小时就会不规律的出现，同时没有问题的容器会很稳定。有一批！
显然，这个问题很可能与底层主机有关。怀疑是同一台主机上部署的其他容器抢了CPU，但是当我询问运维主机的时候，运维一直说主机正常，不知道他们有没有认真看！
隔了半天，有一次和下群的同事聊天，发现他们也遇到了超时问题，说是为了降低机器成本，主机上部署的容器越来越多！
再次出现问题后，我直接去运维要求监控主机，只好自己确认，如下：
可以发现，在11:00到12:00之间，主机负载飙升了100多次，而我们JVM暂停的时间也基本一致。
至此，问题的原因已经找到。线程无法到达安全点，因为它无法获得 CPU。它与thread_in_vm的状态无关，与getLoadAverage无关。停在任何地方！
但我有一个想法。如果运维说宿主机没有问题，不去监控，我们容器里能有证据证明宿主机有问题吗？
于是，我再次尝试在容器中寻找证据！
调度延迟和内存不足
Linux可以无形中减慢线程运行速度的主要有两点：
调度延迟：大量线程需要瞬间运行，导致线程在CPU队列上等待时间过长。direct reclaim：分配内存时直接回收内存。一般Linux都是通过kswapd异步回收内存，但是当kswapd没有及时回收时，会在分配的时候直接回收，但是如果回收过程中涉及到page swap out和dirty page writeback，就会回收内存。阻塞当前线程。
直接回收可以通过 cat /proc/vmstat|grep -E “pageoutrun|allocstall” 来衡量，其中 allocstall 是直接回收发生的次数。
并且可以通过/proc/观察到线程调度延迟
/task//schedstat 来衡量，如下：
$ cat /proc/1/task/1/schedstat
55363216 1157776 75
解释如下：
由于需要对整个进程进行分析，以上信息是针对单线程的，所以我写了一个脚本，汇总各个线程的调度数据，收集进程调度延迟信息。执行效果如下：
$ 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。
当再次出现超时安全点问题时，我查看了相关日志如下：
我发现问题发生的时候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 解释如下：
所以，我写了一个小脚本来收集这些数据，如下：
$ nohup bash -c 'while sleep 1;do echo `date +%FT%T` `cat /sys/fs/cgroup/cpu,cpuacct/cpu.stat`;done' cpustat > cpustat.log &
当出现安全点超时问题时，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受限的时间，于是我立即改了运维监控面板，如下：
可以看出，时间点基本一致，只是这个值要小很多。如果你知道原因，你可以告诉我。
另外，我也搜过类似问题的文章： ，可以看到很多次，遇到的问题都遇到过，也被别人分享过了。关键是这类文章已经被大量低质量文章淹没了。在发现问题之前，你根本找不到！
哎，分享传播了知识，但也阻碍了知识的传播！
总结
在排查这个问题的过程中，我学到了很多新知识和新方法，总结如下：
safepoint的原理是什么，long spin和block阶段代表什么？使用 async-profiler 分析安全点的方法。容器可以通过 /proc/ 访问
/task//schedstat 测量进程调度延迟。在容器中，可以通过/sys/fs/cgroup/cpu、cpuacct/cpu.stat来测量容器的CPU限制。过去的内容
时隔数月，终于找到JVM停顿十多秒的原因
密码学概论
神秘的积压参数和TCP连接队列
MySQL时间戳会有时区问题吗？
真正理解可重复读事务隔离级别
字符编码谜题
暂无评论内容