在你的代码之外，服务时延过长的三个追查方向(下)

本文含一些比较有趣的地方，所以和上一篇截开，免得大家看着swap，page cache没劲就把文章关了。

 

第二方面 ： JVM篇 — 高IO波动下的JVM停顿

准备知识：JVM的Stop The World，安全点，黑暗的地底世界

在压测中非常偶然的超时，但CPU正常，网络正常，只有IO在刷盘时偶然写个几秒。那，就继续怀疑IO吧。

第一步，日志都异步写了吗？而且，异步队列满时会选择丢弃吗？

Logback在异步日志队列满时，默认并不是丢弃的而是阻塞等待的，需要自己配置。

或者干脆自己重新写一个更高效的异步Appender。

 

第二步，探究高IO 如何造成JVM停顿

有时GC日志都很正常，只有十几毫秒GC停顿，加上-XX:+PrintGCApplicationStoppedTime 后，真正的停顿才现形。

又或者像下面这样的，user+sys很低，但real很高，因为是多线程并发GC，所以real本来的时间应该是user+sys的十分之一不到的。


[ParNew: 1767244K->134466K(1887488K), 0.0331500 secs] 1767244K->134466K(3984640K), 0.0332520 secs] [Times: user=1.54 sys=0.00, real=1.04 secs]

但日志都异步了呀，JVM和IO还有什么关系？

来吧，用lsof彻底检查一下，去掉那些网络的部分，jar和so的文件

 

lsof -p $pid|grep /|grep -v ".jar"|grep -v ".so"

撇开熟悉的日志文件，发现这两个文件：


/tmp/hsperfdata_calvin/44337
/**我是马赛克**/**公司安全部门别找我**/myapp/logs/gc.log


 

第三步，GC日志

一拍脑袋，对哦，GC日志，如果它被锁住，GC的安全点就出不去哦......

但也不能不写GC日志啊，怎么办？

好在，早有知识储备，详见 Linux下tempfs及/dev/shm原理与应用。 简单说，/dev/shm 就是个默认存在，权限开放的，拿内存当硬盘用的分区，最大上限是总内存的一半，当系统内存不足时会使用swap。板着指头算了一下，由于每次JVM重启时GC日志都会被重置(所以你在启动脚本里总会先把GC日志备份下来)，那以一秒写一条日志的速度，一点内存就够写几年了，于是放心的把日志指向它。

 

-Xloggc:/dev/shm/gc-myapplication.log

怎么好像从来没有人关心过GC日志被锁住的？ 后来才发现，原来网上还是有Linkedin的同学关注过的：Eliminating Large JVM GC Pauses Caused by Background IO Traffic

 

第四步，hsperfdata文件

改完之后继续运行，超时虽然少了，还是有啊～～～

等等，还有一个文件什么鬼？

/tmp/hsperfdata_$user/$pid

涨知识的时刻到了。原来JVM在安全点里会将statistics写入这个文件，给jps，jstats命令用的。它本来已经是MMAP将文件映射到内存了，读写文件本不会锁，但无奈还是要更新inode元信息，在这里被锁了。在安全点里被锁。。。整个JVM就被锁了。

真不知道，JVM里原来还默默做了这事情。。。

解决办法，又把它指向/dev/shm? 可惜不行。所以，咬咬牙，把它禁止了，反正生产上都靠JMX，用不上jstats和jps。 有两种方式禁用它，据说-XX:-UsePerfData 会影响JVM本身做的优化，所以：

 

-XX:+PerfDisableSharedMem

又是哪个疑问，为什么很少听到有人说的，就我们全碰上了？其实有的，比如Cassandra就禁止了它，见JVM statistics cause garbage collection pauses

高IO可以造成各种问题，如果参考上篇，将Linux的刷盘阀值降低，可以治标不治本的缓解很多症状。
 

第三方面 ： 后台辅助程序篇

把前面都都改完了，在线下压测也很棒了，在生产环境里以30ms为目标，还是会有非GC时段的超时，这是为什么呢？

再换个思路，是不是被其他程序影响了？虽然生产上每台机只会部署一个应用，但还有不少监控程序，日志收集程序在跑呀。

运行pidstat 1监控，这些程序不会吃满所有CPU啊。等等，pidstat 以秒来单位运行，见 从dstat理解Linux性能监控体系 ，那毫秒级的峰值它是监控不到的。

又到了发挥想象力乱猜的时刻，主要是看着收集日志的Flueme怎么都不顺眼，看久了忽然发现，Flueme的启动参数几乎是裸奔的，没有配什么GC参数。。。那么按ParallelGCThreads＝8+( Processor - 8 ) ( 5/8 )的公式，24核的服务器，flueme 在Young GC时会有18个比较高优先级的线程在狂抢CPU，会不会是它把CPU给抢得太多了？

反正Flueme是后台收集日志的，停久一点也没所谓，所以加上-XX: ParallelGCThreads=4把它的并发GC线程数降低

参数修改前 15分钟内， 大于30ms的业务调用173次
参数修改后 246分钟内， 大于30ms业务调用 41次

应用被后台老王害了的典型例子。。。。。。。

 
本文内容薛院长亦有贡献，他基于strace的分析方法更工程化，这里就偷懒不写了。

调优路漫漫，超时还没彻底消失，比如偶然会出现SYS time较高的GC，系统又没有Swap ，未完待续。