block阶段与spin阶段的区别的几种区别?

深入的安全点机制

在上面的安全点日志中,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时间戳会有时区问题吗?

真正理解可重复读事务隔离级别

字符编码谜题

© 版权声明
THE END
喜欢就支持一下吧
点赞215 分享
评论 抢沙发
头像
欢迎您留下宝贵的见解!
提交
头像

昵称

取消
昵称表情代码图片