偶尔会遇到长时间的垃圾收集延迟，为什么？

Question

我在处理Java垃圾收集问题和解释日志时遇到了困难。

我的应用程序要求GC耗时不超过2秒，理想情况下不超过100ms。

根据前面的一些建议，我尝试使用以下命令行选项：

 java -XX:MaxGCPauseMillis=100 -XX:NewRatio=9 -XX:+UseConcMarkSweepGC  -XX:+CMSIncrementalMode -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -server -Xmx9g -Xms9g 

应用程序有大量长期存储的对象，这些对象保存在ConcurrentLinkedHashMap中。我偶尔会看到长时间的停顿，在最坏的情况下长达10秒(这是倒数第二个类似下面的GC日志)！

以下是我得到的一些输出：

16938.968: [GC 16938.968: [ParNew: 153343K->17022K(153344K), 7.8608580 secs] 6184328K->6122510K(9420160K) icms_dc=7 , 7.8614100 secs] [Times: user=0.63 sys=0.01, real=7.86 secs] 
16947.087: [GC 16947.087: [ParNew: 153342K->17022K(153344K), 7.2604030 secs] 6258830K->6198642K(9420160K) icms_dc=7 , 7.2609780 secs] [Times: user=0.44 sys=0.00, real=7.27 secs] 
16954.614: [GC 16954.614: [ParNew: 153342K->17024K(153344K), 8.4307620 secs] 6334962K->6274625K(9420160K) icms_dc=7 , 8.4313150 secs] [Times: user=0.62 sys=0.01, real=8.43 secs] 
16963.310: [GC 16963.310: [ParNew: 153344K->17023K(153344K), 6.2588760 secs] 6410945K->6350748K(9420160K) icms_dc=7 , 6.2594290 secs] [Times: user=0.48 sys=0.01, real=6.25 secs] 
16969.834: [GC 16969.834: [ParNew: 153343K->17022K(153344K), 6.0274280 secs] 6487068K->6425868K(9420160K) icms_dc=7 , 6.0279830 secs] [Times: user=0.50 sys=0.01, real=6.03 secs] 
16976.122: [GC 16976.123: [ParNew: 153342K->17022K(153344K), 11.7774620 secs] 6562188K->6503030K(9420160K) icms_dc=7 , 11.7780180 secs] [Times: user=0.43 sys=0.04, real=11.78 secs] 
16988.164: [GC 16988.164: [ParNew: 153342K->17024K(153344K), 10.9477920 secs] 6639350K->6579928K(9420160K) icms_dc=7 , 10.9483440 secs] [Times: user=0.37 sys=0.02, real=10.95 secs] 
16999.371: [GC 16999.372: [ParNew: 153344K->17023K(153344K), 9.8828360 secs] 6716248K->6655886K(9420160K) icms_dc=7 , 9.8833940 secs] [Times: user=0.42 sys=0.01, real=9.88 secs] 
17009.509: [GC 17009.509: [ParNew: 153343K->17023K(153344K), 5.0699960 secs] 6792206K->6727987K(9420160K) icms_dc=7 , 5.0705660 secs] [Times: user=0.55 sys=0.01, real=5.07 secs] 
17014.838: [GC 17014.838: [ParNew: 153343K->17023K(153344K), 6.6411750 secs] 6864307K->6790974K(9420160K) icms_dc=7 , 6.6417400 secs] [Times: user=0.37 sys=0.01, real=6.63 secs] 
17021.735: [GC 17021.735: [ParNew: 153343K->17024K(153344K), 8.0545970 secs] 6927294K->6856409K(9420160K) icms_dc=7 , 8.0551790 secs] [Times: user=0.34 sys=0.03, real=8.05 secs] 
17030.052: [GC 17030.053: [ParNew: 153344K->17023K(153344K), 7.9756730 secs] 6992729K->6922569K(9420160K) icms_dc=7 , 7.9762530 secs] [Times: user=0.34 sys=0.01, real=7.98 secs] 
17038.398: [GC 17038.398: [ParNew: 153343K->17022K(153344K), 12.9613300 secs] 7058889K->6990725K(9420160K) icms_dc=7 , 12.9618850 secs] [Times: user=0.39 sys=0.01, real=12.96 secs] 
17051.630: [GC 17051.630: [ParNew: 153342K->17022K(153344K), 6.8942910 secs] 7127045K->7059607K(9420160K) icms_dc=7 , 6.8948380 secs] [Times: user=0.56 sys=0.02, real=6.89 secs] 
17058.798: [GC 17058.798: [ParNew: 153342K->17024K(153344K), 10.0262190 secs] 7195927K->7126351K(9420160K) icms_dc=7 , 10.0267860 secs] [Times: user=0.37 sys=0.01, real=10.02 secs] 
17069.096: [GC 17069.096: [ParNew: 153344K->17023K(153344K), 10.0419500 secs] 7262671K->7195002K(9420160K) icms_dc=7 , 10.0425020 secs] [Times: user=0.40 sys=0.02, real=10.04 secs] 
17079.410: [GC 17079.410: [ParNew: 153343K->17022K(153344K), 13.5389040 secs] 7331322K->7264275K(9420160K) icms_dc=7 , 13.5394610 secs] [Times: user=0.30 sys=0.01, real=13.54 secs] 
17093.223: [GC 17093.224: [ParNew: 153342K->17023K(153344K), 10.5909450 secs] 7400595K->7330446K(9420160K) icms_dc=7 , 10.5915060 secs] [Times: user=0.33 sys=0.00, real=10.58 secs] 
17104.083: [GC 17104.084: [ParNew: 153343K->17024K(153344K), 5.8420210 secs] 7466766K->7392173K(9420160K) icms_dc=7 , 5.8425920 secs] [Times: user=0.57 sys=0.00, real=5.84 secs] 

我花了几个小时浏览各种描述Java GC调优的网页，但没有一个真正让我能够解释上面的日志并提出一个行动方案。基于我提供的日志的任何具体建议都将不胜感激。

更新：回答以下问题：

机器有16G的内存，下面是从上到下的信息:内存: 15483904k，已用15280084k，203820k可用，155684k缓冲区交换:总计2031608k，已用1347240k，可用684368k，缓存3304044k

这是一次不同的运行，但这里是该进程的当前最高输出：

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
  1016 sanity   17   0 10.2g 6.5g 9464 S    1 44.2  10:24.32 java                      

更新2:一些更详细的日志，这看起来像是造成了400ms的延迟：

{Heap before GC invocations=1331 (full 1):
 par new generation   total 153344K, used 153343K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K, 100% used [0x00002aaaae200000, 0x00002aaab6720000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab77c0000, 0x00002aaab885fff0, 0x00002aaab8860000)
  to   space 17024K,   0% used [0x00002aaab6720000, 0x00002aaab6720000, 0x00002aaab77c0000)
 concurrent mark-sweep generation total 7169664K, used 4258496K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
484.738: [GC 484.738: [ParNew: 153343K->17022K(153344K), 0.3950480 secs] 4411840K->4341689K(7323008K), 0.3954820 secs] [Times: user=0.49 sys=0.07, real=0.40 secs] 
Heap after GC invocations=1332 (full 1):
 par new generation   total 153344K, used 17022K [0x00002aaaae200000, 0x00002aaab8860000, 0x00002aaab8860000)
  eden space 136320K,   0% used [0x00002aaaae200000, 0x00002aaaae200000, 0x00002aaab6720000)
  from space 17024K,  99% used [0x00002aaab6720000, 0x00002aaab77bfb68, 0x00002aaab77c0000)
  to   space 17024K,   0% used [0x00002aaab77c0000, 0x00002aaab77c0000, 0x00002aaab8860000)
 concurrent mark-sweep generation total 7169664K, used 4324666K [0x00002aaab8860000, 0x00002aac6e200000, 0x00002aac6e200000)
 concurrent-mark-sweep perm gen total 21248K, used 13269K [0x00002aac6e200000, 0x00002aac6f6c0000, 0x00002aac73600000)
}

Answer 1

原来问题是堆被换出到磁盘，而延迟是Java的GC必须等待它被换回。

(主要)通过将Linux的"swappiness“参数设置为0来解决。

Answer 2

从时间上看，GC实际上并不是一直在运行(参见用户次数)，所以大多数时候，它都在等待。

只是一个大胆的猜测:它不是交换了吗？这台机器有多少内存？java进程会得到多少(驻留集大小)？

编辑:为什么它在等待：

看看这个(来自你的成绩单)

[Times: user=0.39 sys=0.01, real=12.96 secs]

这意味着(我猜从GC的开始到结束)，12 (几乎13)秒过去了。在这13秒中，.39在用户模式下运行，.01在内核模式下运行。如果时间收集方法不是完全有缺陷的(即，这些数字实际上表示GC进程/线程的运行时间)，这意味着至少等待12秒。

Answer 3

通常，当您需要如此大的堆时，很难获得正确的GC调优。

也就是说，大部分GC挂起时间是由跨年轻垃圾回收幸存下来的对象的内存复制造成的。

您的ConcurrentLinkedHashMap是否一次性使用所有内存持久化对象进行了初始化？或者，随着应用程序的持续运行，它会慢慢变大吗？如果是后者，可能很难减少GC挂起时间，因为有些对象总是会存活下来。如果是前者，您将需要根据持久性对象的大小+ 20%左右来调整您的终身代的大小，并确保您的年轻一代足够大，以跟上在应用程序过程中创建的临时对象。