原创：扣钉日记(微信公众号ID: codelogs)，欢迎个人分享，转载请保守出处。

最近，我们的系统出现了一些奇怪的现象。每隔几周，系统会在半夜重新启动。分析过程花了很长时间，所以我想在这里记录下来。

简介

重启后进程字段信息丢失，很难排除此问题。常规的jstack、jmap和arthas不能工作。只有机器监控数据和日志可用。

当我们查看机器监视器时，我们发现CPU和磁盘io使用率在重新启动时增加了，但我们很快就确认了这个信息没有帮助，因为jvm启动会由于类加载、GIT编译等原因导致CPU和磁盘io增加，所以增加是由重新启动本身引起的，而不是问题的原因。

然后分析业务日志和内核日志。经过一段时间的分析，得出以下结论：

重启时，系统流量增加不明显。在dmesg日志中没有发现oom-killer的痕迹，尽管这通常是进程莫名其妙地重新启动的原因。由于部署平台也可以终止进程(当它们不响应运行状况检查请求时)，我们还怀疑它们要对终止进程负责，但操作专业的学生不认为这是可能的。这个问题没有进一步的进展。由于现场没有流程，我开发了一个脚本来排除问题。主要逻辑是监视CPU和内存使用情况，并在达到阈值时自动收集jstack和jmap信息。

部署脚本几个小时后，进程重新启动，但这次不是在半夜，而是在白天，故障排除过程又开始了……

在这个调查的过程中，我突然发现我之前错过了gc日志检查，所以我迅速打开gc日志并阅读它，发现如下输出：

GC调用后堆=15036 (full 0):垃圾优先堆总10485760K，已使用1457203K [0x0000000540800000,0x0000000540c05000,0x00000007c0800000)区域大小4096K, 9个年轻(36864K)， 9个幸存者(36864K)元空间已使用185408K，容量211096K，已提交214016K，预留1236992K类空间已使用21493K，容量25808K，已提交26368K，预留1048576K} [Times: user=0.15 sys=0.04, real=0.06 secs] 2021-03-06T09:49:25.564+ 080:914773.820:应用程序线程被停止的总时间：0.0585911秒，停止线程花费：0.0001795秒2021-03-06 t09:49:25.564+ 080:914773.820: [GC concurrent-string-deduplication, 7304.0B-3080.0B(4224.0B)， avg 52.0%， 0.0000975 secs]2021-03-06T09:50:31.544+0800: 914839.800:应用程序线程被停止的总时间：18.9777012秒，停止线程花费：914839.800:应用程序线程停止的总时间：18.9777012秒，停止线程花了：18.9721235秒这意味着什么，jvm挂起了18秒，但看看上面的gc，它只花了0.06秒。

我不知道日志应用程序线程被停止的具体含义：18.9777012秒，所以我不得不在互联网上搜索日志。结论如下：

这一行表示jvm中的18秒暂停，通常称为STW。是这一行的日志，因为- XX: XX: + PrintGCApplicationStoppedTime - + PrintGCDetails两者之间的JVM参数。这18秒不是由gc引起的。除了gc之外，还有一些安全点机制允许jvm进入STW。jstack和jmap等操作触发安全点机制，使所有线程进入安全点等待操作完成。一般来说，如果STW是由gc引起的，会出现这样的一行[Times: user=0.15 sys=0.04, real=0.06 secs]，所以可以看到上面由gc引起的STW实际上是0.0585911秒，四舍五入到0.06秒。简单地说，当JVM执行一些特殊操作时，所有线程都必须暂停，因此设计了安全点机制。当JVM执行这些特殊操作(如Full GC、jstack、jmap等)时，所有线程都将进入安全点和块。这些操作完成后，线程可以恢复运行。此外，jvm将把安全点埋在以下线程有机会停止的位置：

安全点将在方法调用返回时被隐藏。计数循环(无界循环)，即while(true)的无限循环，将在每次循环反弹之前被埋没。例如，循环变量的类型是long并且有safepoint，循环变量的类型是int。我们需要添加-XX:+UseCountedLoopSafepoints来拥有safepoint。经过一段时间的调查和思考，我们确认这次STW是由我自己开发的脚本引起的!随着jvm的运行时间越来越长，old age的使用率会越来越高，但是Full GC之后使用率会下降。但是，我的脚本在old age利用率大于90%时直接检测jmap，触发jvm的safepoint机制，使所有线程等待jmap完成，导致进程没有响应请求。然后，部署平台终止该流程。

事实上，只有在脚本监控逻辑发现Full GC之后内存使用率仍然很高之后，才能将其视为内存异常情况。

在了解safepoint之后，我在网上搜索了很多文章，主要提到了5组jvm参数，如下：

#打开安全点日志，日志将输出到JVM进程的标准输出-XX:+ PrintSafepointStatistics -XX: PrintSafepointStatisticsCount=1 #当一个线程进入安全点超过2000毫秒，safepoint -XX:+ SafepointTimeout-XX:SafepointTimeoutDelay=2000 #此选项不可用。JIT编译器可能会在for循环结束时优化安全点，以便线程直到循环结束才进入安全点。有了这个参数，for循环每次都可以进入安全点。建议在高并发应用程序中添加这个选项-XX:+UseCountedLoopSafepoints #，偏见锁定不会提高性能，而且会触发许多不必要的安全点。建议您包括这个选项来关闭偏向锁-XX: - usebiasedlocking #来防止jvm对安全点进行计时，因为安全点在vm操作操作中的领导是jvm计时触发器安全点-XX: + UnlockDiagnosticVMOptions -XX: GuaranteedSafepointInterval=0注意：默认情况下，jvm会将安全点日志添加到标准输出流中。由于我们的树脂服务器具有看门狗机制，安全点日志被写入看门狗进程$/log/jvm-app-0.log。

此外，我发现有很多由-XX:+UseCountedLoopSafepoints和-XX:-UseBiasedLocking引起的长时间STW的情况。当时我几乎以为加入这两个参数后问题就解决了。

因此，我没有进一步优化监视脚本，而是删除了它，只添加了这些jvm参数。

添加以上jvm参数后，以如下格式查看safepoint日志：

减少jvm - app - 0.美元日志vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count24.692: ForceSafepoint [77 0 1] [0 0 0 0 0] 0 vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count25.607: G1IncCollectionPause [77 0 0] [0 0 0 0 418) 0 vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count26.947:Deoptimize [77 0 0] [0 0 0 0 1] 0 vmop[线程：total initially_running wait_to_block][时间：spin block同步清理vmop] page_trap_count27.136: ForceSafepoint [77 0 1] [0 0 0 0 0 0] 0 vmop[线程：total initially_running wait_to_block][时间：spin block同步清理vmop] page_trap_count28.137: no vm operation[77 0 1][0 0 0 0 0 0] 0其中：

第一列是打印日志的当前时间点，它与进程启动后的秒数有关。第二列包含触发安全点机制的操作，例如G1IncCollectionPause，其名称称为引起暂停的G1GC操作。第三列是发生STW时当前jvm的线程数。initially_running:发生STW时仍在运行的线程数。这是Spin阶段的时间来源，wait_to_block: STW要阻塞的线程数，这是块阶段的来源，第四列是安全点阶段的Spin:由于当jvm决定进入全局安全点时，一些线程处于安全点，而另一些不在安全点，因此该阶段是等待不在安全点的线程进入安全点所花费的时间。阻塞：即使在进入安全点后，一些后来进入安全点的线程可能仍然处于运行状态，这是它们阻塞所需的时间。同步：等于旋转+块+其他活动时间，gc STW log最后停止线程花费等于旋转+块。清理：这个阶段是JVM的内部清理。vmop:花在实际安全点操作上的时间，例如G1IncCollectionPause,Deoptimize,RevokeBias, PrintThreads(jstack)， GC_HeapInspection(jmap-histo)， heapdump (jmap-dump)。几周后，问题又出现了。下一步是检查gc和safepoint日志。查看日志，发现STW很长，不是gc引起的，如下所示：

首先检查gc日志，发现超过16s的STW，并且不是由gc引起的，如下所示：STW$less gc-*。logHeap after GC调用=1 (full 0):垃圾优先堆total 10485760K, used 21971K [0x0000000540800000,0x0000000540c05000,0x00000007c0800000) region size 4096K, 6 young (24576K)， 6 survivors (24576K) Metaspace used 25664K, capacity 26034K, committed 26496K, reserved 1073152K class space used 3506K, capacity 3651K, committed 3712K, reserved 1048576K} [Times: user=0.13sys=0.02, real=0.04 secs] 2021-04-02T00:00:00.192+ 080:384896.192:应用程序线程被停止的总时间：0.0423070秒，停止线程的总时间：0.0423070秒，停止线程的总时间：0.0000684 seconds21-04-02t00:00:193 +0800: 384896.193:应用程序线程被停止的总时间：0.0000684 seconds21-04-02t00:00:00:193 +0800: 384896.193:应用程序线程被停止的总时间：0.0006532秒，停止线程的总时间：0.0000582 seconds2021-04-02t00:00:00:193 + 008:384896.193:0.0006532 seconds, stopped threads took:应用程序线程被停止的总时间：0.0007572 seconds, stopped threads took:应用程序线程被停止的总时间：0.0007572 seconds, stopped threads took: 0.0000582 Seconds2021-04-02t00:00:194 +0800: 384896.194:应用程序线程被停止的总时间：0.0000582 Seconds2021-04-02t00:00:194 +0800: 384896.194:应用程序线程被停止的总时间：0.0006226秒，停止线程的时间：0.0000665秒，停止线程的时间：0.0000665秒，停止线程的时间：0.1240032秒，停止线程的时间：0.1240032秒0.0000535 seconds2021-04-02T00:00:00.442+ 080:384896.442:应用程序线程停止的总时间：0.0000535 seconds2021-04-02T00:00:00.442+ 080:384896.442:应用程序线程停止的总时间：0.1240013秒，stopped threads took: 0.0007532 seconds2021-04-02T00:00:16.544+ 080:384912.544:应用程序线程停止的总时间：16.1020012秒，stopped threads took:应用程序线程停止的总时间：16.1020012 seconds, stopped threads took: 0.0000465 Seconds2021-04-02t13:04:48.545+0800: 384912.545: Total time for which application threads were stopped: 0.0000465 Seconds2021-04-02t13:04:48.545+0800: 384912.545: Total time for which application threads were stopped: 0.0007232 seconds, stopped threads took: 0.0000462 seconds to view the safepoint log，发现有16 s safepoint operations，触发事件为HeapWalkOperation，

如下：# safepoint日志还发现16 s HeapWalkOperation少jvm - app - 0.美元日志vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count384896.193: FindDeadlocks [96 0 0] [0 0 0 0 0] 0 vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count384896.193: ForceSafepoint [98 0 0] [0 0 0 0 0] 0 vmop(线程：总initially_running wait_to_block][时间：旋转块同步清理vmop] page_trap_count384896.194: ThreadDump [98 0 0] [0 0 0 0 124) 0 vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count384896.318: ThreadDump [98 0 0] [0 0 0 0 124) 0 vmop(线程：总initially_running wait_to_block][时间：自旋阻塞同步清理vmop] page_trap_count384896.442: HeapWalkOperation [98 0 0] [0 0 0 0 16102) 0 vmop(线程：总initially_running wait_to_block][时间：spin block sync cleanup vmop] page_trap_count384912.545: no vm operation[98 0 0][0 0 0 0 0] 0对比两条日志的时间点，发现时间点一致，如下所示：查看进程启动时间点$lstart ps h - o - C Java | xargs -i date - d '+' % F % T 13:05:04 # 2021-03-28 #看门狗进程这是服务进程#，因为safepoint记录的时间点相对于进程启动的秒数，而HeapWalkOperation对应的秒数384896.442#添加时间的秒数与日期，

在00:00:00，可以发现gc log中的STW是2021-04-02T00:00:16，而safepoint中的STW是2021-04-02 00:00:00，两者只有16秒的差异。时间差正好等于STW时间，因为gc日志记录的是发生STW之后的时间。安全点日志记录了发生STW之前的时间，因此两个日志时间点是一致的。STW为16s是由HeapWalkOperation引起的。

从名称上看，我好像在做一个堆内存遍历，类似于jmap，但是我的脚本已经删除了，没有jmap操作，机器上除了树脂服务器进程之外没有其他进程。

说到这里，已经找到了一部分原因，却不知道如何引起，苦苦寻找根本原因……

第一次排查

记不住检查的次数，反正这个问题出现了好几次，但这次我们找到了根本原因，过程如下：

检查gc日志和安全点日志如下：STW$less gc-*. log21005-16t00:00:14 .634+ 080:324412.634:应用程序线程被停止的总时间：14.1570012秒，停止线程花费：应用程序线程被停止的总时间：14.1570012秒，停止线程花费：0.0000672秒#安全点日志与相同的14秒HeapWalkOperation $less jvm-app-0.log vmop[线程：Total initially_running wait_to_block][时间：spin block sync cleanup vmop] page_trap_count324398.477: HeapWalkOperation[98 0 0][0 0 0 0 14157] 0现象和以前完全一样，现在的关键是不知道是什么原因导致HeapWalkOperation。

由于最近一直在学习Linux命令，总结grep的用法，我递归地grep resin目录下的heap一词，如下：# -i大小写不区分search # -r递归搜索，在当前目录/子目录/子目录下的所有文件中搜索heap# -n，并打印出匹配的行号$grep -irn heap我意外地发现resin中有一个与HeapDump相关的配置。某种树脂的健康检查机制。

在访问树脂官网后，确认树脂有各种健康检查机制。例如，在每周的0点，会生成一个pdf报告。本报告的数据来源于jstack、jmap等操作，但通过调用jdk的一些方法实现。树脂健康检查机制介绍：http://www.caucho.com/resin-4.0/admin/health-checking.xtp

health:PdfReport path$/doc/admin/pdf-gen.php/path reportSummary/report period7D/period snapshot/mail-to$/mail-to - mail-from$/mail-from !——profile-time60s/profile-time——health:IfCron value='0 0 * * 0'//health:PdfReport该机制在$/log目录下生成pdf报告，如下所示：

$ ls -l-rw-r——r——1 work work 2539860 2021年05月02日00:00:26 app-0-Summary-20210502T0000.pdf-rw-rw-r——1 work work 3383712 2021年05月09日00:00:11 app-0- summary - 20210509t0000 .pdf因为堆遍历操作，时间完全与当时jvm的内存使用情况相关，高内存遍历时间长，低内存遍历时间短，因此，有时暂停时间会触发部署平台kill进程时间阈值，有时不会。所以我们的重启现象不是每周0点，所以我们没有注意到0点的时间规律。

因此，我直接找到了树脂的health.xml，关闭了所有相关的健康检查机制，如下所示：

health:ActionSequence health:IfHealthCritical time='2m'/health: failsaferstart timeout='10m'/health:DumpJmx/!——健康：DumpThreads/——!——注释出来——健康状况：scoreboarreport /!血量：DumpHeap/——!——把这个注释掉——!——健康：DumpHeap hprof='true' hprof-path='$/堆。Hprof '/——!——注释出来——health:StartProfiler active-time='2m' wait='true'/health:Restart//health:ActionSequencehealth:MemoryTenuredHealthCheck enabledfalse/enabled !-添加这个- memory - free - min1m/memory - free - min/health: MemoryTenuredHealthCheck health: MemoryPermGenHealthCheck enabledfalse/enabled !-增加这个- memory - free - min1m/memory - free - min/health: MemoryPermGenHealthCheck health: CpuHealthCheck enabledfalse/enabled !——添加这个——warning-threshold95/warning-threshold!——critical-threshold99/critical-threshold——/health:CpuHealthCheckhealth:DumpThreads health:Or health:IfHealthWarning healthCheck='$' time='2m'/!——health:IfHealthEvent regexp='caucho. '线程'/——!这个事件是由health定义的：AnomalyAnalyzer——/health:Or health:IfNotRecent time='15m'//health: dumpthreadhealth:JvmDeadlockHealthCheck enabledfalse/enabled !-添加这个- health: JvmDeadlockHealthCheck/health: DumpJmx async='true'!—删除此节点—health: OnStart//health: DumpJmxhealth: the Snapshot!-删除此节点- health: OnAbnormalStop//health: snapshothealhealth: AnomalyAnalyzer!——删除此节点——health:PdfReport!删除该节点。在进行此配置2个月后，没有发生重新启动，这确认问题已经解决。

第二次排查

这个问题调查已经有了一定的想法，但最终的根本原因的机会，还是有点像机缘巧合，自己随机grep找到了线索，只是不知道下次还会不会遇到这种运气。

经过思考，解决这个问题的通常方法是挂起脚本，运行perf和bpftrace等跟踪程序，并将探针探针添加到jvm执行的safepoint操作的入口函数中。当发现安全点操作时间过长时，只需打印相应的jvm本机调用堆栈和java调用堆栈。以前介绍过跟踪工具。如果你对此感兴趣，请阅读：

Linux命令拾取-动态跟踪工具

Linux命令拾取分析工具