地址：联系地址联系地址联系地址
电话：020-123456789
传真：020-123456789
邮箱：admin@aa.com
原创 ：扣钉日记（微信公众号ID ：codelogs），接口竟又欢迎分享，接口竟又转载请保留出处 。接口竟又
继上次我们JVM停顿十几秒的接口竟又问题解决后 ，我们系统终于稳定了 ，接口竟又再也不会无故重启了
！接口竟又
这是接口竟又之前的文章 ：耗时几个月 ，终于找到了JVM停顿十几秒的接口竟又原因
但有点奇怪的是 ，每隔一段时间 ，接口竟又我们服务接口就会有一小波499超时 ，接口竟又经过查看gc日志 ，接口竟又又发现JVM停顿了好几秒 ！接口竟又
有了上次JVM停顿排查经验后 ，接口竟又我马上就检查了gc日志与safepoint日志，接口竟又发现如下日志 ：
$ cat gc-*.log | awk '/application threads were stopped/ && $(NF-6)>1'|tailn2022-05-08T16:40:53.886+0800: 78328.993: Total time for which application threads were stopped: 9.4917471 seconds,接口竟又 Stopping threads took: 9.3473059 secondsn2022-05-08T17:40:32.574+0800: 81907.681: Total time for which application threads were stopped: 3.9786219 seconds, Stopping threads took: 3.9038683 secondsn2022-05-08T17:41:00.063+0800: 81935.170: Total time for which application threads were stopped: 1.2607608 seconds, Stopping threads took: 1.1258499 secondsnn$ cat safepoint.log | awk '/vmop/{ title=$0;getline;if($(NF-2)+$(NF-4)>1000){ print title;print $0}}'n vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_countn78319.500: G1IncCollectionPause [ 428 0 2 ] [ 0 9347 9347 7 137 ] 0n vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_countn81903.703: G1IncCollectionPause [ 428 0 4 ] [ 0 3903 3903 14 60 ] 0n vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_countn81933.906: G1IncCollectionPause [ 442 0 1 ] [ 0 1125 1125 8 126 ] 0n
从日志上可以看到 ，JVM停顿也是由safepoint导致的 ，而safepoint耗时主要在block阶段 ！
通过添加JVM参数-XX:+SafepointTimeout -XX:SafepointTimeoutDelay=1000后 ，可打印出哪些线程超过1000ms没有到达safepoint，如下 ：
可以看到都是一些http或grpc的worker线程没走到safepoint ，但为啥没到达safepoint ，看不出关键 ，只好又去网上搜索了。
在上面的safepoint日志中 ，spin与block都是等待线程进入safepoint的耗时 ，而vmop就是需要在安全点执行的JVM操作耗时 ，遗憾的是 ，网上讲safepoint的文章虽多 ，但基本没有将block阶段与spin阶段区别讲清楚的 ！
没办法 ，只能去看看JVM内部safepoint的实现代码了 ，在阅读了safepoint.cpp后 ，对spin与block的区别也大致有点理解了 ，如下：
而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
。
经过一段时间了解，发现目前分析safepoint主流工具如下 ：
async-profiler提供了--ttsp的选项 ，用来分析safepoint事件 ，如下 ：
# 下载async-profilern$ 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*nn# 启动async-profiler采集safepoint时的线程栈n$ ./profiler.sh start -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jpsnn# 发现safepoint问题产生后 ，停止采集并导出线程栈n$ ./profiler.sh stop -e wall -t -o collapsed -f /tmp/tts.collased --ttsp jpsnn# 线程栈转换为火焰图工具n$ wget https://github.com/jvm-profiling-tools/async-profiler/releases/download/v2.8/converter.jarn$ java -cp converter.jar FlameGraph /tmp/tts.collapsed tts.htmln
最开始 ，抓到的火焰图是这样的 ，如下 ：
由于我使用的是-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点 ：
direct reclaim可以通过cat /proc/vmstat|grep -E "pageoutrun|allocstall"来测量 ，其中allocstall就是direct reclaim发生的次数
。
而线程调度延迟可以通过观测/proc/<pid>/task/<tid>/schedstat来测量 ，如下 ：
$ cat /proc/1/task/1/schedstat n55363216 1157776 75n
解释如下 ：
而由于我需要分析整个进程 ，上述信息是单个线程的 ，于是我写了一个脚本 ，汇总了各个线程的调度数据，以采集进程调度延迟信息 ，执行效果如下 ：
$ python -u <(curl -sS https://gitee.com/fmer/shell/raw/master/diagnosis/pidsched.py) `pgrep -n java`n2022-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 )n2022-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 )n2022-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 )n2022-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 )n
可以发现 ，正常情况下 ，调度延迟在10ms以下 。
等到再次发生超时safepoint问题时 ，我检查了相关日志 ，如下 ：
我发现 ，在问题发生时 ，oncpu与sched_delay都是0 ，即线程即不在CPU上 ，也不在CPU队列上 ，也就是说线程根本没有被调度
！它要么在睡眠 ，要么被限制调度 ！
联想到我们JVM是在容器中运行 ，而容器会通过cgroup机制限制进程的CPU使用量 ，经过一番了解 ，我发现在容器中 ，可以通过/sys/fs/cgroup/cpu,cpuacct/cpu.stat来了解进程被限制的情况 ，如下：
# cgroup周期的时间长度 ，一个周期是100msn$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_period_us n100000nn# 容器分配的时间配额，由于我们是4核容器 ，所以这里是400msn$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.cfs_quota_us n400000nn$ cat /sys/fs/cgroup/cpu,cpuacct/cpu.statnnr_periods 3216521nnr_throttled 1131nthrottled_time 166214531184n
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 &n
再等到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'|tailn2022-06-10T14:00:45.334+0800: 192736.429: Total time for which application threads were stopped: 1.1018709 seconds, Stopping threads took: 1.0070313 secondsn2022-06-10T14:11:12.449+0800: 193363.544: Total time for which application threads were stopped: 1.0257833 seconds, Stopping threads took: 0.9586368 secondsn
cpustat.log如下 ：
cat cpustat.log |awk '{ if(!pre)pre=$NF;delta=($NF-pre)/1000000;print delta,$0;pre=$NF}'|lessn
可以发现 ，在JVM停顿发生的时间点 ，容器被限制调度多次
，总共限制的时间超3000ms ！
在找到问题后 ，我通过cgroup与jvm stw关键字在google上搜索 ，发现在k8s中 ，container_cpu_cfs_throttled_seconds_total指标也代表了容器CPU被限制的时间 ，于是我立马将运维的监控面板改了改 ，如下：
可见时间点也基本吻合 ，只是这个数值偏小很多，有知道原因的可以告知下
。
此外我也搜索到了问题类似的文章：https://heapdump.cn/article/1930426 ，可见很多时候 ，遇到的问题 ，别人早就遇到过并分享了 ，关键是这种文章被大量低质量文章给淹没了 ，没找到问题前 ，你根本搜索不到 ！
哎 ，分享传播了知识 ，同时也阻碍了知识传播 ！
排查这个问题的过程中 ，学到了不少新知识与新方法 ，总结如下 ：
地址：联系地址联系地址联系地址
电话：020-123456789
传真：020-123456789
邮箱：admin@aa.com
0.2015
