博客
关于我
强烈建议你试试无所不能的chatGPT,快点击我
一些长时间GC停顿问题的排查及解决办法
阅读量:5845 次
发布时间:2019-06-18

本文共 8534 字,大约阅读时间需要 28 分钟。

hot3.png

对于许多企业级应用,尤其是OLTP应用来说,长暂停很可能导致服务超时,而对这些运行在JVM上的应用来说,垃圾回收(GC)可能是长暂停最主要的原因。本文将描述一些可能碰到GC长暂停的不同场景,以及说明我们如何排查和解决这些GC停顿的问题。

下面是一些应用在运行时,可能导致GC长暂停的不同场景。

1. 碎片化

这个绝对要排在第一位。因为,正是因为碎片化问题--CMS最致命的缺陷,导致这个统治了OLAP系统十多年的垃圾回收器直接退出历史舞台(CMS已经是deprecated,未来版本会被移除,请珍惜那些配置了CMS的JVM吧),面对G1以及最新的ZGC,天生残(碎)缺(片)的CMS毫无还手之力。

对于CMS,由于老年代的碎片化问题,在YGC时可能碰到晋升失败(promotion failures,即使老年代还有足够多有效的空间,但是仍然可能导致分配失败,因为没有足够连续的空间),从而触发Concurrent Mode Failure,发生会完全STW的FullGC。FullGC相比CMS这种并发模式的GC需要更长的停顿时间才能完成垃圾回收工作,这绝对是Java应用最大的灾难之一。

为什么CMS场景下会有碎片化问题?由于CMS在老年代回收时,采用的是标记清理(Mark-Sweep)算法,它在垃圾回收时并不会压缩堆,日积月累,导致老年代的碎片化问题会越来越严重,直到发生单线程的Mark-Sweep-Compact GC,即FullGC,会完全STW。如果堆比较大的话,STW的时间可能需要好几秒,甚至十多秒,几十秒都有可能。

接下来的cms gc日志,由于碎片率非常高,从而导致promotion failure,然后发生concurrent mode failure,触发的FullGC总计花了17.1365396秒才完成:

  1. {Heap before GC invocations=7430 (full 24):

  2. parnew generation total 134400K, used 121348K[0x53000000, 0x5c600000, 0x5c600000)

  3. eden space 115200K, 99% used [0x53000000, 0x5a07e738, 0x5a080000)

  4. from space 19200K, 32% used [0x5a080000, 0x5a682cc0, 0x5b340000)

  5. to space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000)

  6. concurrent mark-sweep generation total 2099200K, used 1694466K [0x5c600000, 0xdc800000, 0xdc800000)

  7. concurrent-mark-sweep perm gen total 409600K, used 186942K [0xdc800000, 0xf5800000, 0xfbc00000)

  8. 10628.167: [GC Before GC:

  9. Statistics for BinaryTreeDictionary:

  10. ------------------------------------

  11. Total Free Space: 103224160

  12. Max Chunk Size: 5486

  13. Number of Blocks: 57345

  14. Av. Block Size: 1800

  15. Tree Height: 36 <---- High fragmentation

  16. Statistics for IndexedFreeLists:

  17. --------------------------------

  18. Total Free Space: 371324

  19. Max Chunk Size: 254

  20. Number of Blocks: 8591 <---- High fragmentation

  21. Av. Block Size: 43

  22. free=103595484

  23. frag=1.0000 <---- High fragmentation

  24. Before GC:

  25. Statistics for BinaryTreeDictionary:

  26. ------------------------------------

  27. Total Free Space: 0

  28. Max Chunk Size: 0

  29. Number of Blocks: 0

  30. Tree Height: 0

  31. Statistics for IndexedFreeLists:

  32. --------------------------------

  33. Total Free Space: 0

  34. Max Chunk Size: 0

  35. Number of Blocks: 0

  36. free=0 frag=0.0000

  37. 10628.168: [ParNew (promotion failed) Desired survivor size 9830400 bytes, new threshold 1 (max 1)

  38. - age 1: 4770440 bytes, 4770440 total: 121348K->122157K(134400K), 0.4263254secs]

  39. 10628,594: [CMS10630.887: [CMS-concurrent-mark: 7.286/8.682 secs] [Times: user=14.81, sys=0.34, real=8.68 secs]

  40. (concurrent mode failure):1698044K->625427K(2099200K), 17.1365396 secs]

  41. 1815815K->625427K(2233600K), [CMS Perm : 186942K->180711K(409600K)]

  42.  

  43. After GC:

  44. Statistics for BinaryTreeDictionary:

  45. ------------------------------------

  46. Total Free Space: 377269492

  47. Max Chunk Size:

  48. 377269492

  49. Number of Blocks: 1 <---- No fragmentation

  50. Av. Block Size: 377269492

  51. Tree Height: 1 <---- No fragmentation

  52. Statistics for IndexedFreeLists:

  53. --------------------------------

  54. Total Free Space: 0

  55. Max Chunk Size: 0

  56. Number of Blocks: 0

  57. free=377269492

  58. frag=0.0000 <---- No fragmentation

  59. After GC:

  60. Statistics for BinaryTreeDictionary:

  61. ------------------------------------

  62. Total Free Space: 0

  63. Max Chunk Size: 0

  64. Number of Blocks: 0

  65. Tree Height: 0

  66. Statistics for IndexedFreeLists:

  67. --------------------------------

  68. Total Free Space: 0

  69. Max Chunk Size: 0

  70. Number of Blocks: 0

  71. free=0 frag=0.0000

  72. , 17.5645589 secs] [Times: user=17.82 sys=0.06, real=17.57 secs]

  73. Heap after GC invocations=7431 (full 25):

  74. parnew generation total 134400K, used 0K [0x53000000, 0x5c600000, 0x5c600000)

  75. eden space 115200K, 0% used [0x53000000, 0x53000000, 0x5a080000)

  76. from space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000)

  77. to space 19200K, 0% used [0x5a080000, 0x5a080000, 0x5b340000)

  78. concurrent mark-sweep generation total 2099200K, used 625427K [0x5c600000, 0xdc800000, 0xdc800000)

  79. concurrent-mark-sweep perm gen total 409600K, used 180711K [0xdc800000, 0xf5800000, 0xfbc00000)

  80. }

  81. Total time for which application threads were stopped: 17.5730653 seconds

不知道怎么看CMS的碎片率?请戳笔者另一篇文章吧:[如何了解CMS的垃圾碎片率:   ]

2. GC时操作系统的活动

当发生GC时,一些操作系统的活动,比如swap,可能导致GC停顿时间更长,这些停顿可能是几秒,甚至几十秒级别。

如果你的系统配置了允许使用swap空间,操作系统可能把JVM进程的非活动内存页移到swap空间,从而释放内存给当前活动进程(可能是操作系统上其他进程,取决于系统调度)。Swapping由于需要访问磁盘,所以相比物理内存,它的速度的令人发指。所以,如果在GC的时候,系统正好需要执行Swapping,那么GC停顿的时间一定会非常非常非常恐怖。

下面是一段持续了29.48秒的YGC日志:

  1. {Heap before GC invocations=132 (full 0):

  2. par new generation total 2696384K, used 2696384K [0xfffffffc20010000, 0xfffffffce0010000, 0xfffffffce0010000)

  3. eden space 2247040K, 100% used [0xfffffffc20010000, 0xfffffffca9270000, 0xfffffffca9270000)

  4. from space 449344K, 100% used [0xfffffffca9270000, 0xfffffffcc4940000, 0xfffffffcc4940000)

  5. to space 449344K, 0% used [0xfffffffcc4940000, 0xfffffffcc4940000, 0xfffffffce0010000)

  6. concurrent mark-sweep generation total 9437184K, used 1860619K [0xfffffffce0010000, 0xffffffff20010000, 0xffffffff20010000)

  7. concurrent-mark-sweep perm gen total 1310720K, used 511451K [0xffffffff20010000, 0xffffffff70010000, 0xffffffff70010000)

  8. 2013-07-17T03:58:06.601-0700: 51522.120: [GC Before GC: :2696384K->449344K(2696384K), 29.4779282 secs] 4557003K->2326821K(12133568K) ,29.4795222 secs] [Times: user=915.56, sys=6.35, real=29.48 secs]

最后一行[Times: user=915.56, sys=6.35, real=29.48 secs]中real就是YGC时应用真实的停顿时间。

发生YGC的这个时间点,vmstat命令输出结果如下:

  1. r b w swap free re mf pi po fr de sr s0 s1 s2 s3 in sy cs us sy id

  2. 0 0 0 77611960 94847600 55 266 0 0 0 0 0 0 0 0 0 3041 2644 2431 44 8 48

  3. 0 0 0 76968296 94828816 79 324 0 18 18 0 0 0 0 1 0 3009 3642 2519 59 13 28

  4. 1 0 0 77316456 94816000 389 2848 0 7 7 0 0 0 0 2 0 40062 78231 61451 42 6 53

  5. 2 0 0 77577552 94798520 115 591 0 13 13 0 0 13 12 1 0 4991 8104 5413 2 0 98

YGC总计花了29秒才完成。vmstat命令输出结果表示,可用swap空间在这个时间段减少了600m。这就意味着,在GC的时候,内存中的一些页被移到了swap空间,这个内存页不一定属于JVM进程,可能是其他操作系统上的其他进程。

从上面可以看出,操作系统上可用物理内容不足以运行系统上所有的进程,解决办法就是尽可能运行更少的进程,增加RAM从而提升系统的物理内存。在这个例子中,Old区有9G,但是只使用了1.8G(mark-sweep generation total 9437184K, used 1860619K)。我们可以适当的降低Old区的大小以及整个堆的大小,从而减少内存压力,最小化系统上的应用发生swapping的可能。

除了swapping以外,我们也需要监控了解长GC暂停时的任何IO或者网络活动情况等, 可以通过iostat和netstat两个工具来实现. 我们还能通过mpstat查看CPU统计信息,从而弄清楚在GC的时候是否有足够的CPU资源。

3. 堆空间不够

如果应用程序需要的内存比我们执行的Xmx还要大,也会导致频繁的垃圾回收,甚至OOM。由于堆空间不足,对象分配失败,JVM就需要调用GC尝试回收已经分配的空间,但是GC并不能释放更多的空间,从而又回导致GC,进入恶性循环。

应用运行时,频繁的FullGC会引起长时间停顿,在下面这个例子中,Perm空间几乎是满的,并且在Perm区尝试分配内存也都失败了,从而触发FullGC:

  1. 166687.013: [Full GC [PSYoungGen:126501K->0K(922048K)] [PSOldGen: 2063794K->1598637K(2097152K)]2190295K->1598637K(3019200K) [PSPermGen: 165840K->164249K(166016K)],6.8204928 secs] [Times: user=6.80 sys=0.02, real=6.81 secs]

  2. 166699.015: [Full GC [PSYoungGen:125518K->0K(922048K)] [PSOldGen: 1763798K->1583621K(2097152K)]1889316K->1583621K(3019200K) [PSPermGen: 165868K->164849K(166016K)],4.8204928 secs] [Times: user=4.80 sys=0.02, real=4.81 secs]

同样的,如果在老年代的空间不够的话,也会导致频繁FullGC,这类问题比较好办,给足老年代和永久代,不要做太抠门的人了,嘿嘿。

4. JVM Bug

什么软件都有BUG,JVM也不例外。有时候,GC的长时间停顿就有可能是BUG引起的。例如,下面列举的这些JVM的BUG,就可能导致Java应用在GC时长时间停顿。

  1. 6459113: CMS+ParNew: wildly different ParNew pause times depending on heap shape caused by allocation spread

  2. fixed in JDK 6u1 and 7

  3.  

  4. 6572569: CMS: consistently skewed work distribution indicated in (long) re-mark pauses

  5. fixed in JDK 6u4 and 7

  6.  

  7. 6631166: CMS: better heuristics when combatting fragmentation

  8. fixed in JDK 6u21 and 7

  9.  

  10. 6999988: CMS: Increased fragmentation leading to promotion failure after CR#6631166 got implemented

  11. fixed in JDK 6u25 and 7

  12.  

  13. 6683623: G1: use logarithmic BOT code such as used by other collectors

  14. fixed in JDK 6u14 and 7

  15.  

  16. 6976350: G1: deal with fragmentation while copying objects during GC

  17. fixed in JDK 8

如果你的JDK正好是上面这些版本,强烈建议升级到更新BUG已经修复的版本。

5. 显示System.gc调用

检查是否有显示的System.gc调用,应用中的一些类里,或者第三方模块中调用System.gc调用从而触发STW的FullGC,也可能会引起非常长时间的停顿。如下GC日志所示,Full GC后面的(System)表示它是由调用System.GC触发的FullGC,并且耗时5.75秒:

  1. 164638.058: [Full GC (System) [PSYoungGen: 22789K->0K(992448K)]

  2. [PSOldGen: 1645508K->1666990K(2097152K)] 1668298K->1666990K(3089600K)

  3. [PSPermGen: 164914K->164914K(166720K)], 5.7499132 secs] [Times: user=5.69, sys=0.06, real=5.75 secs]

如果你使用了RMI,能观察到固定时间间隔的FullGC,也是由于RMI的实现调用了System.gc。这个时间间隔可以通过系统属性配置:

 
  1. -Dsun.rmi.dgc.server.gcInterval=7200000

  2. -Dsun.rmi.dgc.client.gcInterval=7200000

JDK 1.4.2和5.0的默认值是60000毫秒,即1分钟;JDK6以及以后的版本,默认值是3600000毫秒,即1个小时。

如果你要关闭通过调用System.gc()触发FullGC,配置JVM参数 -XX:+DisableExplicitGC即可。

那么如何定位并解决这类问题问题呢?

  1. 配置JVM参数:-XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps and -XX:+PrintGCApplicationStoppedTime. 如果是CMS,还需要添加-XX:PrintFLSStatistics=2,然后收集GC日志。因为GC日志能告诉我们GC频率,是否长时间停顿等重要信息。

  2. 使用vmstat, iostat, netstat和mpstat等工具监控系统全方位健康状况。

  3. 使用GCHisto工具可视化分析GC日志,弄明白消耗了很长时间的GC,以及这些GC的出现是否有一定的规律。

  4. 尝试从GC日志中能否找出一下JVM堆碎片化的表征。

  5. 监控指定应用的堆大小是否足够。

  6. 检查你运行的JVM版本,是否有与长时间停顿相关的BUG,然后升级到修复问题的最新JDK。

转载于:https://my.oschina.net/u/3872757/blog/3040245

你可能感兴趣的文章
java中回调函数以及关于包装类的Demo
查看>>
读书:为了那个美妙的咔哒声
查看>>
OllyDBG 入门系列教学--让你瞬间成为破解高手
查看>>
爬虫去重(只是讲了去重的策略,没有具体讲实现过程,反正就是云里雾里)...
查看>>
avcodec_open2()分析
查看>>
Jquery Form表单取值
查看>>
Team Name
查看>>
西门子_TDC_数据耦合小经验
查看>>
codevs——2822 爱在心中
查看>>
JAVA MAC 配置
查看>>
大话数据结构之四(串)
查看>>
加热炉简是新来的整个系统的板
查看>>
Mockito使用注意事项
查看>>
[LeetCode] Palindrome Linked List 回文链表
查看>>
UVA - 825Walking on the Safe Side(dp)
查看>>
评论:人才流失强力折射出现实畸形人才观
查看>>
虚拟运营商10月或大面积放号 哭穷背后仍有赢家
查看>>
UML中关联,组合与聚合等关系的辨析
查看>>
ios的google解析XML框架GDataXML的配置及使用
查看>>
netty-当一个客户端连接到来的时候发生了什么
查看>>