近期，线上服务偶尔会出现超时情况。说一下背景，我们的开发语言是java，在单台物理机上部署了3个java模块，他们之间互相调用。服务p999耗时有时候会超过10s，按道理我们的业务不会停滞这么长时间，并且在长时间内只有一台机器多次出现了这个问题。下面是我们的分析流程：
-
登录机器查看WARN报警日志，事故发生时刻打印了大批WARN日志。进一步发现，在大批打印日志之前，有很长时间没有打印任何日志。怀疑可能是java模块GC导致的stop the world。
-
JVM中增加了-XX:+PrintGC参数，会将gc日志输出到指定文件。查看gc日志，发现确实有长时间stop the world的情况，并和问题发生时间吻合。但是有时候出现在minor gc中，有时候出现在普通的safepoint安全点位置。说明并不单纯是gc导致的，但是问题发生原因肯定和stop the
world有关。 -
为了知道到底是什么原因导致的stop the world，我们在线下给JVM增加Safepoint相关的参数-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1。jvm需要进入安全点的事情有：gc、代码优化、加载类、取消偏向锁等。但是不幸的是，线下在压力很大的时候也没法复现问题。这样只能在线上打开Safepoint日志等待问题出现，但是我们担心这样会影响jvm性能，暂时这条路先缓一缓。
-
我们有了新的发现，问题发生时刻机器IO都比较高（sar -dp可以看到历史IO情况，默认情况下是10分钟记录一次，可以改成1分钟一次），并且有时候会两个模块同时出现问题并同时恢复。这样，我们猜测可能是机器本身的问题导致该台机器上所有模块都出现stop the world。所以我们打算在机器上做一个iostat -x 1的监控，希望能够捕获到问题发生时候每一秒的IO情况。
-
问题如期而至，发现stop the world前几秒钟的IO利用率就已经到了100%，有了这个证据我们大概率怀疑是IO导致的stop the world。但是具体是哪个进程IO比较多呢，就我们本身的业务来说没有IO读，IO写的量大约100K/s，理论上不应该导致IO超载。接着我们用了iotop工具，监控每一秒的进程IO情况。不幸的是，我们发现是由jdb2这个进程导致，而这个进程是ext4文件系统刷新到磁盘启动的。除此之外，只有我们本身的业务有IO，但但是写入量很小。
-
这时候看到了一篇文章https://www.jianshu.com/p/ce9b3f0a90f2跟我们的现象很相似，这篇文章讲述了机器高IO导致的gc log write阻塞导致的stop world时间比较长。阻塞的原因有两个：写入page cache时候如果该page正被后台刷写线程写入到磁盘，这时候该page会被锁住导致阻塞。另外是日志文件系统写入时候需要同时将数据写入到日志磁盘文件中（保证数据不丢失），这时候需要写入IO，机器高IO的话会阻塞这一步。
-
死马当作活马医，我们按照文章中的方法将gc日志写到sdb盘（我们的机器有两张盘sda和sdb，业务和操作系统都在sda盘上），同时为了进一步减少模块的日志写入量，我们屏蔽了metric日志的打印。
-
观察了几天后，问题还是出现了，IO同样比较高。想来想去还是需要从IO切入，我们在线下模块线上请求，并使用dd工具将机器的IO占满，查看是否还有长时间stop the world情况？最后的结论是无论将gc日志移到哪里都会出现stop the world情况，甚至即使将整个模块都移到sdb盘，仍然会出现stop the world。这个启发我们如果系统盘IO被占满，业务模块在进行系统调用的时候有可能因为操作系统写IO加锁而被阻塞？这种情况下无论如何业务模块在哪个盘，都会出现长时间stop the world。同时我们使用了strace命令attach到JVM Thread主线程中，记录stop the world发生时候的系统调用，但是也没有发现固定的哪个系统调用耗时长。
-
为了保证系统盘的IO不被占满，我们打算将所有模块都迁移到sdb盘。这样系统盘就没有任何业务IO，理论上不应该再出现IO占满的情况。如果出现了，那必然就是硬件问题，需要运维介入解决。而就在这个时候又发生了一次长时间stop the world，我们突然想到会不会是磁盘的坏道问题？使用命令/opt/MegaRAID/MegaCli/MegaCli64 LDPDInfo -Aall"果然该台机器的系统盘有300多个扇区有问题，啊啊啊啊啊！！！！马上联系运维进行换盘，然后又看其他机器的坏道情况，差不多10台机器都有坏道，也是醉了！！修复了坏道后，这几天服务没有再超时。
问题越诡异，原因可能越简单。之前的经验和这次的经历再次验证了这个真理。不过经过这次问题追查，对JVM的SafePoint相关参数、使用strace attach到JVM Thread调试、怎么查看磁盘坏道等有了更深的了解，当然没有最开始想到可能是磁盘坏道，这对我来说是比较遗憾了，花了很多时间在其他方向。
最后，问题终究是可以解决的，相信就能解决。
网友评论