benmo | 发布于 2020-12-02 19:52:52 | 阅读量 765 |
发布于 2020-12-02 19:52:52 |

一、问题发现

    收到开发反馈线上应用某台机器有GC耗时情况,登录改机器,查看gc日志,过滤GC耗时的时间点

$ awk '/application threads/&&$11>1 || /GC remark|GC concurrent/&&$(NF-1)>1' /home/q/xx/xx-app/logs/gc.log.0.current
2020-09-22T15:14:50.522+0800: 414339.613: Total time for which application threads were stopped: 1.5485152 seconds, Stopping threads took: 1.4468679 seconds
2020-09-23T14:08:39.983+0800: 496769.074: [GC concurrent-root-region-scan-start]
2020-09-23T14:08:40.129+0800: 496769.220: [GC concurrent-mark-start]
2020-09-23T14:08:44.453+0800: 496773.543: [GC concurrent-mark-end, 4.3237479 secs]
2020-09-23T14:08:44.484+0800: 496773.574: [GC remark 2020-09-23T14:08:44.484+0800: 496773.574: [Finalize Marking, 0.0685901 secs] 2020-09-23T14:08:44.552+0800: 496773.643: [GC ref-proc, 0.6058526 secs] 2020-09-23T14:08:45.158+0800: 496774.249: [Unloading, 12.1510679 secs], 13.2001619 secs]
2020-09-23T14:08:57.684+0800: 496786.775: Total time for which application threads were stopped: 13.2082159 seconds, Stopping threads took: 0.0006442 seconds
2020-09-23T14:08:57.854+0800: 496786.945: [GC concurrent-cleanup-start]
2020-09-23T14:09:01.397+0800: 496790.488: Total time for which application threads were stopped: 1.1119271 seconds, Stopping threads took: 0.0002674 seconds
2020-09-23T20:56:14.571+0800: 521223.662: Total time for which application threads were stopped: 1.0247786 seconds, Stopping threads took: 0.9523914 seconds

    可以明显看到在14:08:44GC耗时长达13s,并且在14:08:44.484还有触发GC remark(该阶段处于STW),这会暂停线程,而这个耗时这对于很多服务来说是难以接受的

 

二、问题排查

    获取到了GC耗时的时间后,我们通过监控平台获取的各个监控项,开始排查这个点有异常的指标,最终分析发现,在14.08分,SWAP出现了释放资源、内存资源增长的情况

    

   为啥会这样呢?JVM用到了SWAP,GC释放了这部分内存到memory?为了验证JVM是否用到swap,我们通过检查proc下的进程内存资源占用

$ awk '/Swap:/{S+=$(NF-1)}END{print S/1024}' /proc/$(ps -ef | grep [x]xs-app | awk '{print $2}')/smaps
358.364

看到确实有用到358Mb的SWAP

    为了验证GC耗时与swap操作有必然关系,我们抽样了几十台机器,使用ansible过滤耗时的GC日志,通过时间点确认到GC耗时的时间点与swap操作的时间点确实是一致的

   但是为什么会用到swap呢?通过内核参数,我们看到系统默认的swappiness=60(即内存使用量达到100-60=40%)就可能会开始使用swap,而当时的内存使用率,我们通过监控看是已经有60%的,满足使用swap的条件

$ cat /proc/sys/vm/swappiness
60

 

三、问题分析

    当内存使用率达到水位线(vm.swappiness)时,linux会把一部分暂时不使用的内存数据放到磁盘swap去,以便腾出更多可用内存空间。当需要使用位于swap区的数据时,必须先将其换回内存中,当JVM进行GC时,需要对相应堆分区的已用内存进行遍历;假如GC的时候,有堆的一部分内容被交换到SWAP中,遍历到这部分的时候就需要将其交换回内存,而Linux对SWAP的回收是滞后的(SWAP操作会占用CPU与系统IO),在高并发/QPS服务中,这种滞后带来的结果是致命的(stw)

 

四、问题处理

    设置vm.swappiness=0(重启应用释放swap后生效),JVM应用尽量不适用swap,另外不要强制swapoff -a去释放关闭swap,强制关闭会立即遍历swap释放到内存中,可能会引发系统IO或者其他问题

# 临时生效
$ sysctl vm.swappiness=0
# 或者
$ echo 0 > /proc/sys/vm/swappiness

# 永久生效
$ echo "vm.swappiness=0" >> /etc/sysctl.conf

 

参考资料: 

Memory Sizing for WebSphere Applications on System z Linux

How To Check Swap Usage Size and Utilization in Linux

 

 

 


内容更新于: 2020-12-02 19:52:52
链接地址: http://blog.leanote.com/post/benmo/JVM%E4%BD%BF%E7%94%A8SWAP%E5%BC%95%E5%8F%91%E7%9A%84GC%E8%80%97%E6%97%B6

上一篇: Linux IO子系统优化

下一篇: Ansible--奇淫技巧

765 人读过
立即登录, 发表评论.
没有帐号? 立即注册
0 条评论
文档导航