花钱的年华

江南白衣,公众号:春天的旁边

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

| Filed under 技术

本文含一些比较有趣的地方,所以和上一篇截开,免得大家看着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 ,未完待续。

继续女排的图片:

有关的...

发表评论

您的电子邮箱不会被公开。

您可以使用这些 HTML 标签和属性: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>