如何减少 Full GC 的数量？答案

【问题标题】：How do I reduce the amount of Full GC?如何减少 Full GC 的数量？
【发布时间】：2012-12-10 05:29:17
【问题描述】：

我有一个 java 程序，它可以下载信息并对其进行解析，并将结果存储在 MySQL 数据库中。可以多次启动，最多同时启动3次。

我发现服务器负载在某些时候变得非常高（> 10），虽然我仍然需要调整我的 MySQL 服务器，但我发现 java 程序经常停止或 GC 并且服务器正在磨削到绝对停止。

在阅读了一些 GC configuration articles 之后，我使用以下参数来减少发生的完整 GC 扫描的数量（或至少阻止它们停止程序）：

-d64 
-Xms256m 
-Xmx256m 
-XX:PermSize=128m 
-XX:MaxPermSize=128m 
-server 
-XX:+PrintGCTimeStamps 
-Xloggc:/log/gc_$1_$2.log 
-XX:+UseConcMarkSweepGC 
-verbose:gc 
-XX:-UseAdaptiveSizePolicy

但是，现在我在每次运行时看到几乎恒定的 Full GC。以下是日志的摘录：

1057.920: [Full GC 30851K->29270K(258880K), 0.1528210 secs]
1058.965: [Full GC 30303K->29297K(258880K), 0.2060580 secs]
1062.652: [Full GC 29839K->29353K(258880K), 0.2875420 secs]
1063.639: [Full GC 30894K->29356K(258880K), 0.1839510 secs]
1070.604: [Full GC 33956K->29262K(258880K), 0.3445180 secs]
1072.146: [Full GC 29770K->29262K(258880K), 0.2201660 secs]
1074.600: [Full GC 30295K->29321K(258880K), 0.1319390 secs]
1081.234: [Full GC 31373K->29293K(258880K), 0.1931140 secs]
1086.498: [Full GC 30591K->29347K(258880K), 0.2624270 secs]

几乎每秒都有一次 Full GC。是我选择了错误的参数还是可以使用其他方法来阻止这种情况？

更新：

这是运行的 gc 日志输出的前 10 分钟，-XX:+PrintGCDetails。我还删除了-XX:-UseAdaptiveSizePolicy

4.794: [GC 5.367: [ParNew: 34112K->4224K(38336K), 0.0814000 secs] 34112K->8605K(520064K), 0.0816920 secs] [Times: user=0.04 sys=0.03, real=0.65 secs] 
5.843: [GC 5.843: [ParNew: 38336K->4224K(38336K), 0.0371760 secs] 42717K->15987K(520064K), 0.0372770 secs] [Times: user=0.02 sys=0.01, real=0.04 secs] 
6.153: [GC 6.153: [ParNew: 38336K->4224K(38336K), 0.0333900 secs] 50099K->24554K(520064K), 0.0334970 secs] [Times: user=0.02 sys=0.02, real=0.04 secs] 
15.668: [GC 15.668: [ParNew: 38336K->4224K(38336K), 0.0471250 secs] 58666K->30766K(520064K), 0.0472230 secs] [Times: user=0.06 sys=0.00, real=0.05 secs] 
220.547: [Full GC (System) 220.548: [CMS: 26542K->31455K(481728K), 3.3996650 secs] 57025K->31455K(520064K), [CMS Perm : 20869K->20848K(131072K)], 3.3998940 secs] [Times: user=0.38 sys=0.05, real=3.40 secs] 
448.238: [Full GC (System) 448.264: [CMS: 31455K->31236K(481728K), 2.3479700 secs] 32783K->31236K(520064K), [CMS Perm : 20898K->20895K(131072K)], 2.5008180 secs] [Times: user=0.30 sys=0.03, real=2.53 secs] 
456.217: [Full GC (System) 456.217: [CMS: 31236K->31177K(481728K), 0.2216600 secs] 33856K->31177K(520064K), [CMS Perm : 20912K->20910K(131072K)], 0.2218030 secs] [Times: user=0.21 sys=0.00, real=0.22 secs] 
480.982: [Full GC (System) 480.982: [CMS: 31177K->31251K(481728K), 0.2026140 secs] 32586K->31251K(520064K), [CMS Perm : 20915K->20912K(131072K)], 0.2027550 secs] [Times: user=0.19 sys=0.00, real=0.20 secs] 
483.419: [Full GC (System) 483.419: [CMS: 31251K->31196K(481728K), 0.2436580 secs] 33189K->31196K(520064K), [CMS Perm : 20928K->20926K(131072K)], 0.2438080 secs] [Times: user=0.23 sys=0.00, real=0.24 secs] 
484.583: [Full GC (System) 484.583: [CMS: 31196K->31233K(481728K), 0.2706090 secs] 31842K->31233K(520064K), [CMS Perm : 20980K->20973K(131072K)], 0.2707580 secs] [Times: user=0.25 sys=0.01, real=0.27 secs] 
486.361: [Full GC (System) 486.424: [CMS: 31233K->31235K(481728K), 0.2614690 secs] 32866K->31235K(520064K), [CMS Perm : 20994K->20993K(131072K)], 0.2618060 secs] [Times: user=0.21 sys=0.02, real=0.33 secs] 
521.280: [Full GC (System) 521.280: [CMS: 31235K->31163K(481728K), 0.2190910 secs] 34502K->31163K(520064K), [CMS Perm : 21010K->21009K(131072K)], 0.2192190 secs] [Times: user=0.15 sys=0.00, real=0.22 secs] 
531.169: [Full GC (System) 531.169: [CMS: 31163K->29453K(481728K), 0.2923910 secs] 32492K->29453K(520064K), [CMS Perm : 21015K->20845K(131072K)], 0.2925890 secs] [Times: user=0.27 sys=0.01, real=0.29 secs] 
532.270: [Full GC (System) 532.271: [CMS: 29453K->29384K(481728K), 0.2542390 secs] 32073K->29384K(520064K), [CMS Perm : 20852K->20850K(131072K)], 0.2780520 secs] [Times: user=0.20 sys=0.01, real=0.28 secs] 
533.320: [Full GC (System) 533.321: [CMS: 29384K->29379K(481728K), 0.2429570 secs] 30030K->29379K(520064K), [CMS Perm : 20853K->20851K(131072K)], 0.2430970 secs] [Times: user=0.17 sys=0.00, real=0.24 secs] 
542.963: [Full GC (System) 542.963: [CMS: 29379K->29443K(481728K), 0.2208060 secs] 30708K->29443K(520064K), [CMS Perm : 20854K->20851K(131072K)], 0.2209180 secs] [Times: user=0.11 sys=0.01, real=0.22 secs] 
544.949: [Full GC (System) 544.949: [CMS: 29443K->29405K(481728K), 0.1397210 secs] 31382K->29405K(520064K), [CMS Perm : 20855K->20853K(131072K)], 1.0028950 secs] [Times: user=0.14 sys=0.00, real=1.00 secs] 
546.517: [Full GC (System) 546.517: [CMS: 29405K->29464K(481728K), 0.2366270 secs] 30051K->29464K(520064K), [CMS Perm : 20858K->20857K(131072K)], 0.2367790 secs] [Times: user=0.20 sys=0.00, real=0.23 secs] 
547.508: [Full GC (System) 547.508: [CMS: 29464K->29467K(481728K), 0.1974860 secs] 30756K->29467K(520064K), [CMS Perm : 20859K->20858K(131072K)], 0.1976260 secs] [Times: user=0.17 sys=0.01, real=0.19 secs] 
560.975: [Full GC (System) 560.975: [CMS: 29467K->29382K(481728K), 0.1750130 secs] 32092K->29382K(520064K), [CMS Perm : 20865K->20864K(131072K)], 0.1751500 secs] [Times: user=0.17 sys=0.00, real=0.17 secs] 
573.975: [Full GC (System) 573.975: [CMS: 29382K->29451K(481728K), 0.2862430 secs] 30711K->29451K(520064K), [CMS Perm : 20868K->20865K(131072K)], 0.2863970 secs] [Times: user=0.19 sys=0.00, real=0.28 secs] 
575.101: [Full GC (System) 575.101: [CMS: 29451K->29381K(481728K), 0.1325170 secs] 31390K->29381K(520064K), [CMS Perm : 20869K->20867K(131072K)], 0.1326370 secs] [Times: user=0.13 sys=0.00, real=0.14 secs] 
580.396: [Full GC (System) 580.396: [CMS: 29381K->29454K(481728K), 0.1913770 secs] 30709K->29454K(520064K), [CMS Perm : 20875K->20872K(131072K)], 0.1928260 secs] [Times: user=0.19 sys=0.00, real=0.19 secs] 
582.300: [Full GC (System) 582.300: [CMS: 29454K->29403K(481728K), 0.1238430 secs] 31392K->29403K(520064K), [CMS Perm : 20875K->20873K(131072K)], 0.1239580 secs] [Times: user=0.12 sys=0.00, real=0.13 secs] 
582.982: [Full GC (System) 582.982: [CMS: 29403K->29457K(481728K), 0.1238720 secs] 30049K->29457K(520064K), [CMS Perm : 20875K->20874K(131072K)], 0.1239860 secs] [Times: user=0.12 sys=0.00, real=0.13 secs] 
584.284: [Full GC (System) 584.284: [CMS: 29457K->29461K(481728K), 0.1820700 secs] 31431K->29461K(520064K), [CMS Perm : 20875K->20874K(131072K)], 0.1823370 secs] [Times: user=0.16 sys=0.01, real=0.18 secs] 
592.363: [Full GC (System) 592.364: [CMS: 29461K->29385K(481728K), 0.2151030 secs] 32081K->29385K(520064K), [CMS Perm : 20892K->20890K(131072K)], 0.2153350 secs] [Times: user=0.18 sys=0.02, real=0.22 secs] 
599.096: [Full GC (System) 599.096: [CMS: 29385K->29408K(481728K), 0.1319160 secs] 30713K->29408K(520064K), [CMS Perm : 20894K->20890K(131072K)], 0.1320350 secs] [Times: user=0.13 sys=0.00, real=0.14 secs]

【问题讨论】：

你为你的java进程分配了相当少量的内存（最大256mb）是故意的（硬件限制？） - 如果不是我会增加最大堆大小看看是否它使它变得更好。操作使用/需要多少内存（下载内容和处理听起来像是分配了一些字节......）
@PeterLiljenberg 我们在服务器中有 4gb 内存，其中 3 块给 MySQL 服务器。我选择 256mb 作为最大堆大小，因为我认为它不需要那么多。我将它增加到 512mb，看看是否有积极影响。
您是否在代码中的某处调用System.gc()，因为当我阅读它时，它是从 30MB 到 29MB 的完整 gc-ing。
@MarkRotteveel 我也是这么读的。不，我不会在任何地方打电话给System.gc()。
@Cyntech 请添加-XX:+DisableExplicitGC 以排除System.gc() 的可能性。从更新的日志来看，确实有人在明确地调用它。

标签： java performance logging garbage-collection sun

【解决方案1】：

首先，使用-XX:+PrintGCDetails 查看每个集合的完整 GC 统计信息。然后你应该计算 Live Data Set、Allocation Rate 和 Promotion Rate 的大小。这将告诉您是否需要更大的堆或您的例如。小根太小了。有关如何计算这些统计信息的提示，请参阅 Advanced JVM Tuning。获得这些统计信息后，您可以使用 -XX:InitialSurvivorRatio=3 -XX:SurvivorRatio=3 -XX:TargetSurvivorRatio=90 调整年轻一代，并使用例如调整大小。 -Xmn -Xmx -Xms。根据您的分配/晋升率调整数字。

暂时不要使用-XX:-UseAdaptiveSizePolicy。此选项用于禁用自动 GC 人体工程学，以便您可以调整堆参数。但是如果你不知道你的应用程序的分配行为，那么这个参数将无济于事。此外，仅对吞吐量收集器 (-XX:+UseParallelOldGC) 启用了自适应大小策略。

此外，如果您想调整 GC 的吞吐量，您应该使用 -XX:+UseParallelOldGC 和例如-XX:ParallelGCThreads=4。这将启用多线程年轻/老一代 GC（前提是您在多核上运行）。

此外，使用-XX:MaxTenuringThreshold=15 设置任期并使用-XX:+PrintTenuringDistribution 进行检查。

更新：

请看一下日志，你能不能也用-XX:+DisableExplicitGC，因为Full GC (System)意味着有人在打电话给System.gc()。

【讨论】：

据我所知，如果您指定 -Xms 和 -Xmx 具有相同的值，那么自适应大小策略无论如何都会被禁用，因为 JVM 没有“空间”来调整其参数。
我已经用详细的 gc 统计信息更新了帖子。没有提到 PSYoungGen GC 来计算分配率，除非您指的是 ParNew GC？ Full GC 似乎与 CMS 相关，让我感到困惑的是，它并没有接近分配内存的上限，但仍在进行 Full GC...
请看一下日志，你能不能也用-XX:+DisableExplicitGC，因为Full GC (System)意味着有人在调用System.gc()。
@MarkRotteveel 有趣的评论，但我认为仅指定 -Xms 和 -Xmx 与显式禁用自适应大小策略的效果不同。该策略也用于年轻一代和幸存者大小。此外，某些参数不能与 Policy 一起使用，例如。 -XX:SurvivorRatio=。因此，虽然几乎相同，但并不相同。 :-)
我好像记得读过，如果 -Xmx 和 -Xms 相同，那么年轻代 + 幸存者空间的总大小也是固定的，只会调整它们的相对大小（可能是与 G1 不同，请参阅weblogs.java.net/blog/kcpeppe/archive/2011/12/19/…)

【解决方案2】：

内存很便宜，年轻一代比老一代 GC 便宜得多。

尝试 2 或 4 GB 堆...应该少得多的完整 GC（如果您的应用表现得足够好，则可能为 0）。一个parnew应该只需要几毫秒。

【讨论】：

虽然我同意这个想法，但它似乎不会在任何区域已满时触发。

【解决方案3】：

根据这些参数，您不应该因为老一代的空间不足而进行完整的 GC，因为老一代的容量应该超过 200MB，而您显然只使用了 30MB。

如果您使用 PrintGCDetails 标志，CMS 收集器可以为您提供有关正在发生的事情的更多信息。将此添加到您的参数中：-XX:+PrintGCDetails。

我的第一个想法是完全 GC 是由并发模式故障引起的。一些关于这些的阅读：

编辑：

根据您详细的 GC 日志，以及一些进一步的查看，当日志显示 Full GC (System) 时，它似乎表示 explicit GC invocation。如果您不自己调用它，也许您正在使用的库是？

那里的答案是指制作一个自定义的运行时类，它可以帮助您追踪谁在调用 GC。在 Java 6 中做到这一点的一种方法是按照these instructions 将内容添加到您的引导类路径。

【讨论】：

我添加了详细的 gc 日志记录。提到了 CMS GC，但没有提到并发模式失败。
对，但现在它说的是“Full GC (System)”，这意味着调用 System.gc()。更新了我的答案。
完全有可能，但是，编写自定义运行时类可能有点棘手，因为我使用 One-Jar 将我的程序打包到可执行 jar 中。我正在使用的其他库是 mysql 连接器、commons-io、oauth-signpost 和 slf4j/logback）。
@Cyntech 即使使用 one-jar，您也应该能够使用 bootclasspath 方法，因为您仍然可以访问 Java 命令行提示符。您想单独构建运行时 jar，但是当您运行 jar 时，只需使用 java -jar my-app.jar（来自 One-Jar 站点）而不是 java -Xbootclasspath:runtime.jar -jar my-app 。罐。也就是说，-XX:+DisableExplicitGC 也应该可以解决问题。