奇怪的小gc发生后，正常小gc

2013-11-26T10:19:30.011+0800: [GC [ParNew: 2432484K->19997K(2696640K), 0.0378270 secs] 5560240K->3155822K(7691712K), 0.0398670 secs] [Times: user=0.18 sys=0.00, real=0.04 secs] 
2013-11-26T10:19:36.277+0800: [GC [ParNew: 2417093K->15777K(2696640K), 0.0372550 secs] 5552917K->3151795K(7691712K), 0.0388490 secs] [Times: user=0.28 sys=0.00, real=0.04 secs] 
**2013-11-26T10:19:36.325+0800: [GC [ParNew: 20441K->16452K(2696640K), 0.0186420 secs] 3156459K->3153092K(7691712K), 0.0200280 secs] [Times: user=0.17 sys=0.00, real=0.02 secs]** 
2013-11-26T10:19:41.464+0800: [GC [ParNew: 2413508K->22811K(2696640K), 0.0426440 secs] 5550148K->3160128K(7691712K), 0.0444710 secs] [Times: user=0.25 sys=0.00, real=0.04 secs]

显然小gc每5或6秒发生。奇怪的小gc发生后，正常小gc

2013-11-26T10：19：36.277之后，在2013-11-26T10：19：36.325有一个小小的gc，只有20441K被使用！

为什么小gc发生了（上面的线）？谁知道？

更多detais：

这种现象仅发生每24小时不超过10倍。

有关于我们的服务器的详细信息：

CPU计数12个CPU

CPU速度的2400MHz

内存总容量16322984 KB

JVM的ARGS（热点1.6.0_26）是：

-Xms7804M -Xmx7804M -Xmn2926M -XX：PermSize = 256M -XX：MaxPermSize = 256M -XX：SurvivorRatio = 8 -XX：TargetSurvivorRatio = 70 -XX：MaxTen uringThreshold = 10 -server -Xss256k -XX：+ HeapDumpOnOutOfMemoryError -XX：+ PrintGCDetails -XX：+ PrintGCDateStamps -XX：+ UseConcMarkSweepGC -XX：+ DisableExplicitGC -XX：SoftRefLRUPolicyMSPerMB = 0 -XX：CMSInitiatingOccupancyFraction = 75 -XX：+ UseCMSInitiatingOccupancyOnly - XX：ParallelGCThreads = 12 -XX：+ CMSScavengeBeforeRemark -XX：+ CMSClassUnloadingEnabled

@Alexey Ragozin多个日志：

2013-11-27T23:34:47.352+0800: [GC [ParNew: 2496458K->81521K(2696640K), 0.0381510 secs]  5104803K->2690529K(7691712K), 0.0406260 secs] [Times: user=0.28 sys=0.00, real=0.04 secs] 
2013-11-27T23:34:51.745+0800: [GC [ParNew: 2478577K->57599K(2696640K), 0.0535680 secs] 5087585K->2716762K(7691712K), 0.0554400 secs] [Times: user=0.28 sys=0.01, real=0.06 secs] 
2013-11-27T23:34:55.728+0800: [GC [ParNew: 2454747K->19841K(2696640K), 0.0300150 secs] 5113910K->2679701K(7691712K), 0.0320030 secs] [Times: user=0.18 sys=0.00, real=0.03 secs] 
**2013-11-27T23:34:55.769+0800: [GC [ParNew: 21438K->16389K(2696640K), 0.0171200 secs] 2681299K->2676788K(7691712K), 0.0187850 secs] [Times: user=0.13 sys=0.00, real=0.02 secs]** 
2013-11-27T23:34:59.888+0800: [GC [ParNew: 2413445K->16017K(2696640K), 0.0251400 secs] 5073844K->2676744K(7691712K), 0.0271570 secs] [Times: user=0.15 sys=0.00, real=0.02 secs] 
2013-11-27T23:35:04.374+0800: [GC [ParNew: 2413073K->16059K(2696640K), 0.0240360 secs] 5073800K->2677460K(7691712K), 0.0259960 secs] [Times: user=0.15 sys=0.00, real=0.03 secs] 
... ... 
2013-11-28T02:56:57.719+0800: [GC [ParNew: 2449927K->45500K(2696640K), 0.0360740 secs] 6195838K->3791742K(7691712K), 0.0379370 secs] [Times: user=0.23 sys=0.00, real=0.03 secs] 
2013-11-28T02:57:37.987+0800: [GC [ParNew: 2442556K->54097K(2696640K), 0.0383490 secs] 6188798K->3800678K(7691712K), 0.0402170 secs] [Times: user=0.23 sys=0.00, real=0.04 secs] 
2013-11-28T02:57:38.036+0800: [GC [1 CMS-initial-mark: 3746580K(4995072K)] 3801777K(7691712K), 0.0694940 secs] [Times: user=0.06 sys=0.00, real=0.07 secs] 
2013-11-28T02:57:38.770+0800: [CMS-concurrent-mark: 0.661/0.662 secs] [Times: user=2.15 sys=0.00, real=0.66 secs] 
2013-11-28T02:57:38.806+0800: [CMS-concurrent-preclean: 0.035/0.035 secs] [Times: user=0.06 sys=0.01, real=0.04 secs] 
CMS: abort preclean due to time 2013-11-28T02:57:43.862+0800: [CMS-concurrent-abortable-preclean: 5.016/5.056 secs] [Times: user=6.82 sys=0.19, real=5.05 secs] 
**2013-11-28T02:57:43.872+0800: [GC[YG occupancy: 407766 K (2696640 K)]2013-11-28T02:57:43.872+0800: [GC [ParNew: 407766K->35780K(2696640K), 0.0236470 secs] 4154346K->3782623K(7691712K), 0.0256460 secs] [Times: user=0.20 sys=0.00, real=0.03 secs]** 
[Rescan (parallel) , 0.0119390 secs][weak refs processing, 0.8478360 secs][class unloading, 0.0661530 secs][scrub symbol & string tables, 0.0146780 secs] [1 CMS-remark: 3746843K(4995072K)] 3782623K(7691712K), 1.1138910 secs] [Times: user=1.41 sys=0.00, real=1.12 secs] 
2013-11-28T02:57:48.965+0800: [CMS-concurrent-sweep: 3.893/3.977 secs] [Times: user=5.65 sys=0.15, real=3.97 secs] 
2013-11-28T02:57:48.977+0800: [CMS-concurrent-reset: 0.012/0.012 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

来源

2013-11-26 yongfei gao

这是什么语言/环境？世界上有许多*不同的垃圾收集器。 –

这是java。 jvm是热点1.6.0_26 –

我怀疑任何人，除了人谁写的和/或维持特定的GC ，可以正确/正确地解释这种现象。

但是，我会观察到您的应用程序正在创建非常多的垃圾。 2400000K ==每6秒垃圾2.4Gb。要么你有病态应用程序，要么这是一个非常不切实际的垃圾收集器基准测试...，它不会告诉你任何关于GC如何用于实际应用程序的意义。

如果你问这个问题只是为了满足你的好奇心，我建议你自己查的现象......然后汇报你的结果作为自答。

来源

2013-11-26 09:19:54

首先，应用程序在线，而不是beanchmark！其次，服务器上每秒约有27535页面浏览量（我们有42个服务器组成该集群）。 “每6秒垃圾2.4Gb”可能是病理性的。我们将分析后面的堆转储以优化应用程序。现在，当调整jvm时，我们发现了奇怪的小gc。所以我问了这个问题，如果您有任何建议，请告诉我，谢谢！ –

我的建议是“忽略它”！对于具有非常大吞吐量（和大量内核）的系统来说，垃圾产生率可能不会过高。但是日志似乎表示集合需要0.02秒的实时时间......而且小的开销无关紧要。 –

谢谢！我只是对外观有些好奇。 –

当年轻一代填满时发生小GC。如果遵循以高速率创建新对象的应用程序将经历越来越多的次要垃圾回收。鉴于您发布的GC日志，您的应用程序也可以看到完全相同的行为。您可以高速创建对象，从而经常触发次要GC。

对于一般GC有关更多信息，你可以给看看这个资源：http://www.oracle.com/webfolder/technetwork/tutorials/obe/java/gc01/index.html

来源

2013-11-26 09:33:14

-XX:+CMSScavengeBeforeRemark是你的怪异次要收集的一个原因。

CMS要做2停止这世界暂停完成旧空间收集周期

初始标记
此言

他们都需要扫描整个年轻的空间。在年轻收藏之后，年轻空间中的物品数量相当小，因此这是一个有益的时间表。旧的空间收藏在年轻收藏之后立即停止。

-XX:+CMSScavengeBeforeRemark只要CMS准备好暂停留言，即使伊甸园尚未满满，选项也会迫使年轻人收藏。

你会在每个旧的空间采集周期中看到这个“现象”。

更多关于CMS机制的细节 - 更Understanding GC pauses in JVM, HotSpot's CMS collector
关于JVM GC选项 - HotSpot JVM garbage collection options cheat sheet

UPDATE
从技术上讲有可能导致过早年轻GC的另一个原因。如果应用程序尝试分配不适合Eden的大数组，JVM可能会开始收集以释放空间。这是可能的，但更有可能的是JVM将选择直接在旧空间中分配这个数组。

来源

2013-11-27 05:00:38

在添加选项“CMSScavengeBeforeRemark”之前，它已经发生。所以我认为这不是原因。此外，如果添加“CMSScavengeBeforeRemark”，则较小的gc发生在预清洁阶段和备注阶段之间，如下所示： 2013-11-27T12：21：47.055 + 0800：[GC [YG入住率：2142008 K（2696640 K）] 2013-11-27T12：21：47.055 + 0800：[GC [ParNew：2142008K-> 22468K（2696640K），0.0246940secs] 5888491K-> 3769345K（7691712K），0.0268340secs] [Times：user = 0.16 sys = 0.00，real = 0.03秒] –

@ user3007751您能否使用新的日志片段更新您的原始文章？ JVM启动年轻收集的原因数量有限。备注是其中之一。我添加了另一个原因的描述，但它不太可能是你的情况。 –

我发布了更多日志。也许正如@Stephen C所建议的那样，这是无关紧要的。我只是对外观有些好奇。 –

奇怪的小gc发生后，正常小gc

回答

相关问题