logo标签列表

为什么并发标记和清除（CMS）清理的内存量不如Full GC？

javagarbage-collectionheap-memoryconcurrent-mark-sweep
14

我的生产机器出现了一个奇怪的问题。它运行着一个执行CMS（并发标记和清除）的Java应用程序，但只清理老年代的一小部分内容。我怀疑可能存在内存泄漏，并尝试进行了堆转储。但在堆转储之前的Full GC几乎清理了老年代的所有内容。这是怎么回事？我从未见过Java垃圾收集的这种行为。通常CMS和Full GC应该收集大约相同数量的垃圾，但现在CMS保留了大约10GB。

  • Java 1.7.0_75
  • Linux Cent OS 7

GC日志：

**2016-01-04T07:37:40.196+0000: 431200.698: [GC [1 CMS-initial-mark: 21633423K(27336704K)] 22826703K(30101504K), 4.3910840 secs] [Times: user=4.40 sys=0.01, real=4.39 secs] 
2016-01-04T07:37:44.588+0000: 431205.090: [CMS-concurrent-mark-start]
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-mark: 18.213/24.131 secs] [Times: user=126.00 sys=2.22, real=24.13 secs] 
2016-01-04T07:38:08.718+0000: 431229.220: [CMS-concurrent-preclean-start]
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-preclean: 0.118/0.125 secs] [Times: user=0.29 sys=0.00, real=0.12 secs] 
2016-01-04T07:38:08.843+0000: 431229.345: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:38:13.906+0000: 431234.408: [CMS-concurrent-abortable-preclean: 4.975/5.063 secs] [Times: user=10.18 sys=0.03, real=5.06 secs] 
2016-01-04T07:38:14.001+0000: 431234.503: [GC[YG occupancy: 1312993 K (2764800 K)]2016-01-04T07:38:14.001+0000: 431234.503: [Rescan (parallel) , 4.6981760 secs]2016-01-04T07:38:18.699+0000: 431239.202: [weak refs processing, 0.0002970 secs]2016-01-04T07:38:18.700+0000: 431239.202: [scrub string table, 0.0006900 secs] [1 CMS-remark: 21633423K(27336704K)] 22946417K(30101504K), 4.6993310 secs] [Times: user=105.40 sys=0.36, real=4.70 secs] 
2016-01-04T07:38:18.701+0000: 431239.203: [CMS-concurrent-sweep-start]
2016-01-04T07:38:27.967+0000: 431248.469: [CMS-concurrent-sweep: 9.160/9.267 secs] [Times: user=17.91 sys=0.10, real=9.26 secs] 
2016-01-04T07:38:27.968+0000: 431248.470: [CMS-concurrent-reset-start]
2016-01-04T07:38:28.028+0000: 431248.531: [CMS-concurrent-reset: 0.061/0.061 secs] [Times: user=0.14 sys=0.00, real=0.06 secs]** 
2016-01-04T07:38:30.801+0000: 431251.303: [GC [1 CMS-initial-mark: 21633105K(27336704K)] 23039228K(30101504K), 5.6079370 secs] [Times: user=5.60 sys=0.01, real=5.61 secs] 
2016-01-04T07:38:36.409+0000: 431256.911: [CMS-concurrent-mark-start]
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-mark: 17.807/18.264 secs] [Times: user=119.97 sys=1.66, real=18.26 secs] 
2016-01-04T07:38:54.673+0000: 431275.175: [CMS-concurrent-preclean-start]
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-preclean: 0.119/0.126 secs] [Times: user=0.25 sys=0.00, real=0.13 secs] 
2016-01-04T07:38:54.799+0000: 431275.301: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:39:01.382+0000: 431281.884: [CMS-concurrent-abortable-preclean: 6.478/6.583 secs] [Times: user=12.23 sys=0.06, real=6.58 secs] 
2016-01-04T07:39:01.487+0000: 431281.989: [GC[YG occupancy: 1596183 K (2764800 K)]2016-01-04T07:39:01.487+0000: 431281.989: [Rescan (parallel) , 3.5737630 secs]2016-01-04T07:39:05.061+0000: 431285.563: [weak refs processing, 0.0002690 secs]2016-01-04T07:39:05.061+0000: 431285.563: [scrub string table, 0.0005740 secs] [1 CMS-remark: 21633105K(27336704K)] 23229288K(30101504K), 3.5747910 secs] [Times: user=80.26 sys=0.27, real=3.58 secs] 
2016-01-04T07:39:05.062+0000: 431285.564: [CMS-concurrent-sweep-start]
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-sweep: 9.449/16.834 secs] [Times: user=27.52 sys=0.16, real=16.83 secs] 
2016-01-04T07:39:21.895+0000: 431302.397: [CMS-concurrent-reset-start]
2016-01-04T07:39:21.995+0000: 431302.497: [CMS-concurrent-reset: 0.099/0.099 secs] [Times: user=0.23 sys=0.01, real=0.10 secs] 
2016-01-04T07:39:24.104+0000: 431304.606: [GC [1 CMS-initial-mark: **21631742K(27336704K)**] 23455261K(30101504K), 5.6592940 secs] [Times: user=5.67 sys=0.00, real=5.66 secs] 
2016-01-04T07:39:29.764+0000: 431310.266: [CMS-concurrent-mark-start]
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-mark: 19.813/27.096 secs] [Times: user=140.17 sys=2.62, real=27.10 secs] 
2016-01-04T07:39:56.859+0000: 431337.361: [CMS-concurrent-preclean-start]
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-preclean: 0.152/0.242 secs] [Times: user=0.35 sys=0.00, real=0.24 secs] 
2016-01-04T07:39:57.102+0000: 431337.604: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-01-04T07:40:03.016+0000: 431343.518: [CMS-concurrent-abortable-preclean: 5.376/5.914 secs] [Times: user=11.65 sys=0.05, real=5.91 secs] 
2016-01-04T07:40:03.016+0000: 431343.518: [GC[YG occupancy: 2045175 K (2764800 K)]2016-01-04T07:40:03.016+0000: 431343.518: [Rescan (parallel) , 3.4843400 secs]2016-01-04T07:40:06.501+0000: 431347.003: [weak refs processing, 0.0002510 secs]2016-01-04T07:40:06.501+0000: 431347.003: [scrub string table, 0.0006220 secs] [1 CMS-remark: **21631742K(27336704K)**] 23676918K(30101504K), 3.4853760 secs] [Times: user=78.31 sys=0.27, real=3.49 secs] 
2016-01-04T07:40:06.502+0000: 431347.004: [CMS-concurrent-sweep-start]
{Heap before GC invocations=1832 (full 5077):
 par new generation   total 2764800K, used 2166647K [0x00000000bae00000, 0x0000000176600000, 0x0000000176600000)
  eden space 2457600K,  77% used [0x00000000bae00000, 0x000000012e6a4c90, 0x0000000150e00000)
  from space 307200K,  89% used [0x0000000150e00000, 0x0000000161939318, 0x0000000163a00000)
  to   space 307200K,   0% used [0x0000000163a00000, 0x0000000163a00000, 0x0000000176600000)
 concurrent mark-sweep generation total 27336704K, used 21631644K [0x0000000176600000, 0x00000007fae00000, 0x00000007fae00000)
 concurrent-mark-sweep perm gen total 49956K, used 30116K [0x00000007fae00000, 0x00000007fdec9000, 0x0000000800000000)
**2016-01-04T07:40:12.775+0000: 431353.277: [Full GC2016-01-04T07:40:12.775+0000: 431353.277: [CMS2016-01-04T07:40:17.924+0000: 431358.426: [CMS-concurrent-sweep: 9.211/11.422 secs] [Times: user=16.59 sys=0.15, real=11.42 secs] 
 (concurrent mode interrupted): 21631644K->4907878K(27336704K), 39.2467600 secs] 23798292K->4907878K(30101504K), [CMS Perm : 30116K->28023K(49956K)], 39.2468730 secs] [Times: user=39.24 sys=0.05, real=39.25 secs]**

同一个应用程序在另一台使用CentOS 5和Java 7的机器上正常运行。

java -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1581
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false -verbose:gc -XX:+PrintGCDetails
-XX:+UseCompressedOops -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC
-Xloggc:/usr/local/app/logs/current-gc.log -Xms29g -Xmx29g -XX:NewSize=3000m
-XX:SurvivorRatio=8 -XX:CMSInitiatingOccupancyFraction=70
-XX:+UseCMSInitiatingOccupancyOnly
-Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE
-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE
-cp /usr/local/app/conf:/usr/local/app/app.jar:/usr/local/app/lib/* -Xdebug
-Xrunjdwp:transport=dt_socket,address=8099,server=y,suspend=n
-Dvisualvm.display.name=App -XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/usr/local/app/logs/
-XX:ErrorFile=/usr/local/app/logs/hs_err_pid%p.log
-Djgroups.tcpgossip.initial_host=localhost
-Dlog4j.hostname=host7.company.com com.company.app.service.App

更新：问题仍未解决。我尝试了所有方法：更新操作系统软件包和内核，将Java更新到最新版本Java 1.7.0_80，回滚应用程序版本，但都没有成功。

我还验证了以前的GC日志并发现此问题并非一直存在。它是在一个月前部署后开始出现的。

@ravindra 这个问题与G1无关。 - dcernahoschi
看一下这个：https://dev59.com/u2865IYBdhLWcg3wUs7z - Ravindra babu
我认为你正在寻找这种情况发生的解释。你尝试过直接在机器上进行ssh和分析吗？关于更新的问题，我同意@ravindra提供的链接，这可能是jmx的一个bug。 - Yuri
1
我在CMS中尝试了许多组合，最终转向了G1GC。对于29GB的内存来说，我没有看到比G1GC更好的算法。 - Ravindra babu
@ravindra 是的。但它仍然是一个非常年轻的算法，在JDK8中，他们不确定它是否应该成为默认算法。但无论如何，在实践中，特别是对于大堆来说，它似乎是最好的选择。 - Yuri
显示剩余9条评论
4个回答
3

CMS在JDK 7中默认不卸载类。
您需要指定-XX:+CMSClassUnloadingEnabled，或者最好切换到JDK 8。

顺便说一下，如果您在运行jmap时没有使用live参数，则在创建堆转储之前它不会调用Full GC。

确实可以在不进行完整垃圾回收的情况下进行转储，而且它似乎包含了无法访问的对象。这是来自Eclipse MAT的日志：[INFO] Removed 308,720,881 unreachable objects using 12,603,944,736 bytes。 - dcernahoschi
3

因此，你的问题可能有几个可能的原因，我将首先列出可能的快速解决方案，然后在下面说明一些最佳实践，供你在长期考虑时参考。

  1. 可能的快速解决方法：您日志中的“CMS：abort preclean due to time”条目表明，您的CMS收集器未正确调整以在最终的停止世界全GC阶段之前完成其工作。基本上，这个日志信息的意思是预清理阶段超时，CMS收集器的进一步步骤无法运行。从您的日志来看，预清理阶段中止的默认时间为5秒。考虑将此时间增加到10秒左右，并观察发生了什么。您可以通过添加参数-XX:CMSMaxAbortablePrecleanTime=10000来实现这一点。请参见Misamitsu's blog entry on the CMSMaxAbortablePrecleanTime tuning parameter。此外，根据我从Stas' blog entry on the subject中看到的内容，单位是毫秒，而不是秒。

长远来看，请尝试以下措施：

  1. 如果可以的话，请尝试使用G1GC收集器。您正在使用Java 7，因此如果在当前环境中可以，请尝试使用它。它适用于具有大堆积的性能。
  2. 由于这是部署的结果，回滚无效，这表明：
    • 您的整个应用程序（例如JVM调整参数）没有作为部署的一部分捕获，或者...
    • 性能问题的原因与您的应用程序无关。也许你两个生产主机之间的差异和一个不相关的应用程序在其中一个主机上运行，例如不同的防病毒版本，使得垃圾收集器更加困难。因此，如果可以的话，请部署到完全相同的硬件和软件。
  3. 评估是否确实需要如此大的堆。请记住，堆越大，垃圾收集器所需的时间就越长，无论您是否使用并发收集器，如CMS。
  4. 您有很多调整参数，我建议您需要其中大部分。考虑运行基准实验，其中您只消除了-XX:NewSize=3000m、-XX:SurvivorRatio=8、-XX:CMSInitiatingOccupancyFraction=70、-XX:+UseCMSInitiatingOccupancyOnly、-Dsun.rmi.dgc.client.gcInterval=0x7FFFFFFFFFFFFFFE和-Dsun.rmi.dgc.server.gcInterval=0x7FFFFFFFFFFFFFFE参数，并查看您的情况是否有所改善。
我希望这可以帮助到你，如果需要后续问题，请在评论中提出。
关于快速修复：另一台正常工作的机器在日志中显示相同的“CMS：由于时间而中止预清理”。但是，在不同情况下可能会出现问题。 - dcernahoschi
关于1. CMS已被证明更加可预测，我们到目前为止没有遇到任何重大问题。 - dcernahoschi
关于第3点。根据目前的设计，是的，堆积存储了大量缓存以实现快速访问。而且，垃圾回收时间一直很好。 - dcernahoschi
这个答案展示了对问题最好的理解，看起来非常有帮助。我会尝试一下 -XX:CMSMaxAbortablePrecleanTime 参数，看看它是否有任何不同。 - dcernahoschi
如果您有任何进一步的问题和/或疑问，请告诉我。我很乐意帮助您 - 不管积分如何。 - entpnerd
显示剩余3条评论
2
我怀疑你的应用程序由于堆太大而尚未出现对Major集合的需求：既没有耐用的旧代（Old Gen），也没有绝境幸存者空间（Survivor Space）。
如果你认为情况不同（即使已经满足其中任何一个条件，Major集合仍未被触发），请分享你的gclog语句。
另外需要注意的是：由于你使用了大的堆，G1GC已被推荐使用。 编辑： 
-XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly

默认情况下，CMS GC使用一套启发式规则来触发垃圾收集。这使得GC不太可预测，并通常倾向于延迟收集，直到老年代几乎被占满。
选项“-XX:+UseCMSInitiatingOccupancyOnly”阻止使用GC启发式。
选项“-XX:CMSInitiatingOccupancyFraction”告诉Java VM何时触发CMS。
您将其配置为70%。如果您的OldGen [Max heap (29G) - new Gen (3G)]接触到限制的70％，则会触发GC。作为GC的一部分，首先触发小型GC。如果在那个时候小型GC没有释放足够的空间来分配新对象，那么就会触发Major GC或Full GC。
更多详细信息，请查看此文章：article。
我还找到了一个相关的SE问题：CMS garbage collector - when does it run?。您也可以查看此问题。
从您的日志中可以看出，同时标记扫描代总共使用了27336704K内存，其中已使用21631644K，意味着27G中的21G已被使用。仍有6G的内存可用，因此不需要进行FullGC。 - Ravindra babu
这个想法是自动触发的CMS不清理内存，但手动调用的Full GC会清理。为什么？ - dcernahoschi
我假设当您手动调用FullGC时，FullGC日志会生成。如果没有手动干预，CMS根本不会触发FullGC。如果我错了，请纠正我。 - Ravindra babu
CMS没有触发完整的GC，因为已经有6GB的可用空闲内存。CMS算法已经被优化以减少FullGC的调用。 - Ravindra babu
2
这是发生的原因。似乎在尝试执行堆转储时调用了dumpHeap()方法。例如，VisualVM在制作堆转储之前也会触发完整GC。
来自文档：
void dumpHeap(String outputFile, boolean live) throws IOException
以与hprof堆转储相同的格式将堆转储到outputFile文件中。 如果从另一个进程远程调用此方法，则堆转储输出写入名为outputFile的文件，该文件位于目标VM正在运行的计算机上。如果outputFile是相对路径，则它相对于启动目标VM的工作目录。 参数： outputFile - 系统相关的文件名 live - 如果为true，则仅转储可到达的对象，即可从其他对象访问的对象
为什么？
当您尝试查找内存泄漏时，您不希望获取没有引用（未进行垃圾回收）的对象。
建议
我看到了一个相当大的堆，可能最好使用G1。
G1的第一个重点是为需要具有有限GC延迟的大堆大小（约为6GB或更大）和稳定且可预测的暂停时间低于0.5秒的应用程序用户提供解决方案。
还可以查看文档中的建议部分。
我知道这个。我在这里问的是为什么CMS和Full GC没有清理相同数量的内存？Full GC释放了多10GB的内存。 - dcernahoschi
我也同意你在G1gc方面的观点。 - Ravindra babu
网页内容由stack overflow 提供, 点击上面的
可以查看英文原文，
原文链接