简介 最近我们系统出现了一些奇怪的现象，系统每隔几个星期会在大半夜重启一次，分析过程花费了很长时间，令人印象深刻，故在此记录一下。第一次排查 由于重启后，进程现场信息都丢失了，所以这个问题非常难以排查，像常规的jstack、jmap、arthas等都派不上用场，能用得上的只有机器监控数据与日志。 在看机器监控时，发现重启时间点的CPU、磁盘io使用都会升高，但很快我们就确认了这个信息无任何帮助，因为jvm启动会由于类加载、GIT编译等导致CPU、磁盘io升高，所以这个升高是重启本身导致的，并不是导致问题的原因。 然后就是分析业务日志、内核日志，经过一段时间分析，结论如下：在重启的时间点，系统流量并没有明显上升。在dmesg日志中并没有找到oomkiller的痕迹，虽然这经常是导致进程莫名重启的原因。由于部署平台也可能会kill掉进程（当进程不响应健康检查请求时），我们也怀疑是它们的误杀，但运维同学认为不可能误杀。 问题没有任何进一步的进展了，由于没有任何进程现场，为了排查问题，我开发了一个脚本，主要逻辑就是监控CPU、内存使用率，达到一个阈值后自动收集jstack、jmap信息，脚本部署之后就没继续排查了。第二次排查 部署了脚本之后，过了几个小时，进程又重启了，但这次不是在大半夜，而是白天，又开始了排查的过程。。。 在这次排查过程中，我突然发现之前漏掉了对gc日志的检查，我赶紧打开gc日志看了起来，发现了下面这种输出：HeapafterGCinvocations15036（full0）：garbagefirstheaptotal10485760K，used1457203K〔0x0000000540800000，0x0000000540c05000，0x00000007c0800000）regionsize4096K，9young（36864K），9survivors（36864K）Metaspaceused185408K，capacity211096K，committed214016K，reserved1236992Kclassspaceused21493K，capacity25808K，committed26368K，reserved1048576K｝〔Times：user0。15sys0。04，real0。06secs〕20210306T09：49：25。5640800：914773。820：Totaltimeforwhichapplicationthreadswerestopped：0。0585911seconds，Stoppingthreadstook：0。0001795seconds20210306T09：49：25。5640800：914773。820：〔GCconcurrentstringdeduplication，7304。0B3080。0B（4224。0B），avg52。0，0。0000975secs〕20210306T09：50：31。5440800：914839。800：Totaltimeforwhichapplicationthreadswerestopped：18。9777012seconds，Stoppingthreadstook：18。9721235seconds复制代码 啥，这代表什么意思，jvm暂停了18秒？但看上面那次gc只花了0。06秒呀！ 不知道applicationthreadswerestopped：18。9777012seconds这个日志的具体含义，只好去网上搜索了，结论如下：这行日志确实代表了jvm暂停了18秒，即常说的STW。之所以会有这行日志，是因为有XX：PrintGCApplicationStoppedTimeXX：PrintGCDetails这两个jvm参数。这个18秒并不是由gc造成的，在jvm中除了gc，还有safepoint机制会让jvm进入STW，比如jstack、jmap等操作就会触发safepoint机制，使得所有线程进入safepoint等待操作完成。一般来说，如果是gc造成的STW，会在上面有〔Times：user0。15sys0。04，real0。06secs〕这样一行，所以你看上面那个gc造成的STW实际是0。0585911秒，四舍五入成了0。06秒。什么是safepoint机制 简单来说，就是JVM在做某些特殊操作时，必须要所有线程都暂停起来，所以设计了safepoint这个机制，当JVM做这些特殊操作时（如FullGC、jstack、jmap等），会让所有线程都进入安全点阻塞住，待这些操作执行完成后，线程才可恢复运行。 并且，jvm会在如下位置埋下safepoint，这是线程有机会停下来的地方：方法调用返回处会埋safepoint非countedloop（非有界循环），即while（true）死循环这种，每次循环回跳之前会埋safepoint有界循环，如循环变量是long类型，有safepoint，循环变量是int类型，需要添加XX：UseCountedLoopSafepoints才有safepoint 经过一段时间的排查与思考，确认了这次STW是我自己开发的脚本导致的！因为随着jvm运行时间越来越长，老年代使用率会越来越高，但会在FullGC后降下来，而我的脚本直接检测老年代占用大于90就jmap，导致触发了jvm的safepoint机制使所有线程需等待jmap完成，导致进程不响应请求，进而部署平台kill了进程。 其实脚本监控逻辑应该是在FullGC后，发现内存占用还是很高，才算内存异常case。 在了解到safepoint这个知识点后，在网上搜索了大量文章，主要提到了5组jvm参数，如下：打开safepointahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a，ahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a会输出到jvm进程的标准输出里XX：PrintSafepointStatisticsXX：PrintSafepointStatisticsCount1当有线程进入Safepoint超过2000毫秒时，会认为进入Safepoint超时了，这时会打印哪些线程没有进入SafepointXX：SafepointTimeoutXX：SafepointTimeoutDelay2000没有这个选项，JIT编译器可能会优化掉for循环处的safepoint，那么直到循环结束线程才能进入safepoint，而加了这个参数后，每次for循环都能进入safepoint了，建议加上此选项XX：UseCountedLoopSafepoints在高并发应用中，偏向锁并不能带来性能提升，反而会触发很多没必要的Safepoint，建议加上此选项关闭偏向锁XX：UseBiasedLocking避免jvm定时进入safepoint，就如safepoint中的novmoperation操作就是jvm定时触发的safepointXX：UnlockDiagnosticVMOptionsXX：GuaranteedSafepointInterval0复制代码 注：默认情况下，jvm将safepoint日志加到标准输出流里，由于我们使用的resin服务器，它有watchdog机制，导致safepoint日志写到了watchdog进程的｛RESINHOME｝logjvmapp0。log中。 并且我发现网上有很多关于XX：UseCountedLoopSafepoints与XX：UseBiasedLocking导致长时间STW的问题案例，我当时几乎都觉得我加上这2个参数后，问题就解决了。 于是我并没有进一步去优化监控脚本，而是下掉了它，直接加上了这些jvm参数。safepoint日志格式 加入以上jvm参数后，立即查看safepoint日志，格式如下：lessjvmapp0。logvmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount24。692：ForceSafepoint〔7701〕〔00000〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount25。607：G1IncCollectionPause〔7700〕〔0000418〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount26。947：Deoptimize〔7700〕〔00001〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount27。136：ForceSafepoint〔7701〕〔00000〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount28。137：novmoperation〔7701〕〔00000〕0复制代码 其中：第一列是当前打印日志时间点，它是相对于进程启动后经过的秒数。第二列是触发safepoint机制的操作，比如G1IncCollectionPause，看名称就知道是G1GC操作导致的暂停。第三列是当前jvm线程情况 total：STW发生时，当前jvm的线程数量 initiallyrunning：STW发生时，仍在运行的线程数，这项是Spin阶段的时间来源 waittoblock：STW需要阻塞的线程数目，这项是block阶段的时间来源第四列是safepoint各阶段的耗时 Spin：因为jvm在决定进入全局safepoint的时候，有的线程在安全点上，而有的线程不在安全点上，这个阶段是等待未在安全点上的线程进入安全点的时间。 Block：即使进入safepoint，后进入safepoint的部分线程可能仍然是running状态，这是等待它们阻塞起来花费的时间。 Sync：等于SpinBlock其它活动耗时，gc的STW日志最后的Stoppingthreadstook等于SpinBlock。 Cleanup：这个阶段是JVM做的一些内部的清理工作。 vmop：实际safepoint操作花费的时间，如G1IncCollectionPause（GC暂停），Deoptimize（代码反优化），RevokeBias（偏向锁撤销），PrintThreads（jstack），GCHeapInspection（jmaphisto），HeapDumper（jmapdump）。第三次排查 过了几个星期后，问题又出现了，接下来就是检查gc与safepoint日志了，一看日志发现，果然有很长时间的STW，且不是gc造成的，如下：首先查看gc日志，发现有超过16s的STW，并且不是gc造成的，如下：发现有16s的STWlessgc。logHeapafterGCinvocations1（full0）：garbagefirstheaptotal10485760K，used21971K〔0x0000000540800000，0x0000000540c05000，0x00000007c0800000）regionsize4096K，6young（24576K），6survivors（24576K）Metaspaceused25664K，capacity26034K，committed26496K，reserved1073152Kclassspaceused3506K，capacity3651K，committed3712K，reserved1048576K｝〔Times：user0。13sys0。02，real0。04secs〕20210402T00：00：00。1920800：384896。192：Totaltimeforwhichapplicationthreadswerestopped：0。0423070seconds，Stoppingthreadstook：0。0000684seconds20210402T00：00：00。1930800：384896。193：Totaltimeforwhichapplicationthreadswerestopped：0。0006532seconds，Stoppingthreadstook：0。0000582seconds20210402T00：00：00。1930800：384896。193：Totaltimeforwhichapplicationthreadswerestopped：0。0007572seconds，Stoppingthreadstook：0。0000582seconds20210402T00：00：00。1940800：384896。194：Totaltimeforwhichapplicationthreadswerestopped：0。0006226seconds，Stoppingthreadstook：0。0000665seconds20210402T00：00：00。3180800：384896。318：Totaltimeforwhichapplicationthreadswerestopped：0。1240032seconds，Stoppingthreadstook：0。0000535seconds20210402T00：00：00。4420800：384896。442：Totaltimeforwhichapplicationthreadswerestopped：0。1240013seconds，Stoppingthreadstook：0。0007532seconds20210402T00：00：16。5440800：384912。544：Totaltimeforwhichapplicationthreadswerestopped：16。1020012seconds，Stoppingthreadstook：0。0000465seconds20210402T13：04：48。5450800：384912。545：Totaltimeforwhichapplicationthreadswerestopped：0。0007232seconds，Stoppingthreadstook：0。0000462seconds复制代码再查看safepoint日志，发现有16s的safepoint操作，触发事件是HeapWalkOperation，如下：safepointahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a也发现16s的HeapWalkOperation操作lessjvmapp0。logvmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384896。193：FindDeadlocks〔9600〕〔00000〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384896。193：ForceSafepoint〔9800〕〔00000〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384896。194：ThreadDump〔9800〕〔0000124〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384896。318：ThreadDump〔9800〕〔0000124〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384896。442：HeapWalkOperation〔9800〕〔000016102〕0vmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount384912。545：novmoperation〔9800〕〔00000〕0复制代码对比两个日志的时间点，发现时间点是吻合的，如下：查看进程启动时间点psholstartCjavaxargsidated｛｝FT2021032813：05：03watchdog进程2021032813：05：04这个才是服务进程由于safepoint记录的时间点是相对于进程启动的秒数，而HeapWalkOperation对应的秒数是384896。442用date给时间加上秒数，减的话用xxsecondsagodated2021032813：05：04384896secondsFT2021040200：00：00复制代码 可以发现gc日志中STW是20210402T00：00：16，而safepoint中是2021040200：00：00，刚好差了16s，时间差值刚好等于STW时间，这是由于gc日志记录的是STW发生之后的时间，而safepoint日志记录的是STW发生之前的时间，所以这两个日志时间点是吻合的，16s的STW正是由HeapWalkOperation导致的。 从名称看起来像是在执行堆内存遍历操作，类似jmap那种，但我的脚本已经下掉了呀，不可能还有jmap操作呀，机器上除了我的resin服务器进程，也没有其它的进程了呀！ 到这里，已经找到了一部分原因，但不知道是怎么造成的，苦苦寻找根因中。。。第N次排查 已经记不得是第几次排查了，反正问题又出现了好几次，但这次咱把根因给找到了，过程如下：还是如上面过程一样，检查gc日志、safepoint日志，如下：gcahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a中发现14s的STWlessgc。log20210516T00：00：14。6340800：324412。634：Totaltimeforwhichapplicationthreadswerestopped：14。1570012seconds，Stoppingthreadstook：0。0000672secondssafepointahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a中同样有14s的HeapWalkOperation操作lessjvmapp0。logvmop〔threads：totalinitiallyrunningwaittoblock〕〔time：spinblocksynccleanupvmop〕pagetrapcount324398。477：HeapWalkOperation〔9800〕〔000014157〕0复制代码 现象和之前一模一样，现在的关键还是不知道HeapWalkOperation是由什么原因导致的。源于最近一直在学习Linux命令，并且正在总结grep的用法，我随手在resin目录递归的grep了一下heap这个词，如下：i忽略大小写搜索r递归的搜索，在当前目录子目录子子目录的所有文件中搜索heapn打印出匹配行的行号grepirnheap复制代码 我竟意外发现，resin中有HeapDump相关的配置，好像是resin中的一些健康检查的机制。 经过一翻resin官网的学习，确认了resin有各种健康检查机制，比如，每个星期的0点，会生成一份pdf报告，这个报告的数据就来源于类似jstack、jmap这样的操作，只是它是通过调用jdk的某些方法实现的。 resin健康检查机制的介绍：www。caucho。comresin4。0ahealth：PdfReportpath｛resin。root｝docadminpdfgen。phppathreportSummaryreportperiod7Dperiodsnapshotmailto｛email｝mailtomailfrom｛emailfrom｝mailfrom！profiletime60sprofiletimehealth：IfCronvalue000health：PdfReport复制代码 此机制会在｛RESINHOME｝log目录下生成pdf报告，如下：lslrwrr1workwork25398602021050200：00：26app0Summary20210502T0000。pdfrwrwr1workwork33837122021050900：00：11app0Summary20210509T0000。pdfrwrwr1workwork18142962021051600：00：16app0Summary20210516T0000。pdf复制代码 由于堆遍历这样的操作，耗时时间完全和当时jvm的内存占用情况有关，内存占用高遍历时间长，占用低则遍历时间短，因此有时暂停时间会触发部署平台kill进程的时间阈值，有时又不会，所以我们的重启现象也不是每周的0点，使得没有注意到0点的这个时间规律。 于是我直接找到resin的health。xml，将健康检查相关机制全关闭了，如下：health：ActionSequencehealth：IfHealthCriticaltime2mhealth：FailSafeRestarttimeout10mhealth：DumpJmx！health：DumpThreads！注释掉这个health：ScoreboardReport！health：DumpHeap！注释掉这个！health：DumpHeaphproftruehprofpath｛resin。logDirectory｝heap。hprof！注释掉这个health：StartProfileractivetime2mwaittruehealth：Restarthealth：ActionSequencehealth：MemoryTenuredHealthCheckenabledfalseenabled！添加这个memoryfreemin1mmemoryfreeminhealth：MemoryTenuredHealthCheckhealth：MemoryPermGenHealthCheckenabledfalseenabled！添加这个memoryfreemin1mmemoryfreeminhealth：MemoryPermGenHealthCheckhealth：CpuHealthCheckenabledfalseenabled！添加这个warningthreshold95warningthreshold！criticalthreshold99criticalthresholdhealth：CpuHealthCheckhealth：DumpThreadshealth：Orhealth：IfHealthWarninghealthCheck｛cpuHealthCheck｝time2m！health：IfHealthEventregexpcaucho。thread！注释掉这个，这个event由health：AnomalyAnalyzer定义health：Orhealth：IfNotRecenttime15mhealth：DumpThreadshealth：JvmDeadlockHealthCheckenabledfalseenabled！添加这个health：JvmDeadlockHealthCheckhealth：DumpJmxasynctrue！删除这种节点health：OnStarthealth：DumpJmxhealth：Snapshot！删除这种节点health：OnAbnormalStophealth：Snapshothealth：AnomalyAnalyzer！删除这种节点health：PdfReport！删除这种节点复制代码 这样配置以后，过了2个月，再也没出现重启现象了，确认了问题已解决。总结 这次问题排查有一定的思路，但最后排查出根因的契机，还是有点像撞大运似的，自己随机grep了一把发现线索，但下次就不知道会不会碰到这种运气了。 作者：打码日记 链接：https：juejin。cnpost7068858769706319879
麦克米兰整场我们的大个子都在攻击禁区下半场防守做得更好了直播吧1月26日讯NBA常规赛，老鹰客场137132战胜雷霆。赛后老鹰主帅麦克米兰接受了采访。麦克米兰说道：很高兴我们迎来了奥孔武的回归，整场比赛我们的大个子都在攻击对手……联赛质量持续下滑，中超已无保持18队必要？俱乐部高层10队就1月25日，运营了14年的武汉长江队宣布不再参加职业联赛，成为2023年第一支解散的球队。而这只是开始，三级联赛还有多支球队半只脚踏进了鬼门关。包括深圳队、广州城在内的几家中超……成都逗人的太阳云衡微语成都的太阳，在冬天气质这块上很是逗人，热乎乎的，冷飕飕的，让人欢喜让人忧。或许是成都市井文化的原因，亦或是川西坝子冬天难得一见的阳光，一旦出太阳，人们总是那……推特文件余波未平？马斯克父亲担心儿子的安全一个月前，环球时报曾经报道，马斯克在收购推特后，公布了一系列文件。该系列文件表明，每家美国社交媒体公司都在美国政府的主导下进行了严格审查。此外，美国政府有时还会向这些公司……为什么过年没有年味了？是我们长大了，还是被智能手机改变的？文科技V力2023年兔年春节就要到了，这是很多中国人心中份量最重的节日，买年货、看春晚、拜大年、走亲戚都是往年春节必不可少的年味记忆，不过随着互联网和智能手机的不断普及，……历史上臭名昭著的几个人，为何被电视剧美化成了好人相信大家都喜欢看古装剧，像《还珠格格》、《康熙王朝》、《包青天》等这样称得上是良心电视剧给我们童年带来了无数的快乐和回忆。纵观现在的影视古装剧市场，很多都良莠不齐，好的电视剧可……中炬高新两位副总涉嫌严重违法被留置调查，姚老板又该头疼了文翠鸟资本姚老板的公司，又出事了！姚振华实控的中炬高新（600872。SH）2月20日晚发布公告称，公司于2月17日晚收到中山市监察委员会的两份《留置通知书》，公司……中大纺织商圈城中村工厂面临搬迁，30万制衣工何去何从春节后，广州几个城中村内的制衣工人和老板们每天除了感叹招工难、生意难做等问题外，最近大家都在议论搬迁到清远的事宜。广州市海珠区的鹭江村、康乐村、大塘村等城中村，位于著名的……正确掌握强化物的使用，自闭症干预才会进步都说自闭症儿童训练难，要么听不懂，要么不配合，注意力和关注度差等等，家长经常处于疲惫不堪和难于应对的境地，根本没有精力顾及训练和引导。自闭症儿童本身就属于特殊儿童，在学习能力和……白酒度数怎么选？酿酒大师道出实情，提醒新老酒友们，弄懂再喝作为我国传统文化的一大重要组成部分，白酒文化流传至今也已经有几千年的历史了。同时伴随着时代的发展，白酒在口感、香型、度数等不同方面也出现了各种不同类型的全新选择。今天咱们……春节假期10款必玩游戏，方块方舟玩家能自制爆竹打年兽春节假期游戏荒了怎么办？不要慌，可以看看这10款必玩游戏，每款都是不一样的风格，相信会给玩家不一样的惊喜。《方块方舟》《方块方舟》是Steam少见的采取恐龙题材的沙……神界被破，我被他亲手投入轮回，转生台上他捏着我的残魄笑得痴狂神女怜悯众生，为何不能怜悯我。他说这话时，眼眸里带着几分破碎的恨意。彼时我还是没有六欲七情的神女，看不懂他眼底的情与怨，只是念叨着平日常说的那句众生皆平等。后……