接口频繁超时,难道又是JVM暂停问题在作祟?

2026-04-28 10:121阅读0评论SEO问题
  • 内容介绍
  • 文章标签
  • 相关推荐

本文共计2922个文字,预计阅读时间需要12分钟。

接口频繁超时,难道又是JVM暂停问题在作祟?

原创:扣钉日记(微信公众账号:codelogs)欢迎分享,转载请注明出处。

简介:上一次我们解决了JVM停止十几秒的问题后,我们的系统终于稳定了,再也不会无故重启了!这是之前的文章:

原创:扣钉日记(微信公众号ID:codelogs),欢迎分享,转载请保留出处。

简介

继上次我们JVM停顿十几秒的问题解决后,我们系统终于稳定了,再也不会无故重启了!
这是之前的文章:耗时几个月,终于找到了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,如下:

可以看到都是一些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,让我也有点怀疑它了,但如何证明呢?
提议链接:bugs.openjdk.org/browse/JDK-8233300。

async-profiler分析safepoint

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

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

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

# 下载async-profiler $ wget 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 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点:

  1. 调度延迟:一瞬间有大量线程需要运行,导致线程在CPU队列上等待时间过长。
  2. 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 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被限制的时间,于是我立马将运维的监控面板改了改,如下:

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

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

哎,分享传播了知识,同时也阻碍了知识传播!

总结

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

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

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

标签:原创

本文共计2922个文字,预计阅读时间需要12分钟。

接口频繁超时,难道又是JVM暂停问题在作祟?

原创:扣钉日记(微信公众账号:codelogs)欢迎分享,转载请注明出处。

简介:上一次我们解决了JVM停止十几秒的问题后,我们的系统终于稳定了,再也不会无故重启了!这是之前的文章:

原创:扣钉日记(微信公众号ID:codelogs),欢迎分享,转载请保留出处。

简介

继上次我们JVM停顿十几秒的问题解决后,我们系统终于稳定了,再也不会无故重启了!
这是之前的文章:耗时几个月,终于找到了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,如下:

可以看到都是一些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,让我也有点怀疑它了,但如何证明呢?
提议链接:bugs.openjdk.org/browse/JDK-8233300。

async-profiler分析safepoint

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

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

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

# 下载async-profiler $ wget 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 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点:

  1. 调度延迟:一瞬间有大量线程需要运行,导致线程在CPU队列上等待时间过长。
  2. 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 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被限制的时间,于是我立马将运维的监控面板改了改,如下:

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

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

哎,分享传播了知识,同时也阻碍了知识传播!

总结

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

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

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

标签:原创