CMS: "premature" minor GCs w/ ParNew

[Vladimir Ivanov]

John,

> Can you run with an early access jdk8? If so then enable the flag
> PrintGCCause and you should get the reasons for these GCs.
What I have right now is just a GC log. But I'll try to get the data for 
JDK8 build.

> How do the timestamps of these premature GCs compare to the previous GC? Are they
> back to back with a non-premature GC?
It starts right after the previous GC (see attached excerpt from the GC 
log). Normally, minor GCs are scheduled every 5 secs.

Does it look like the application
> didn't run between a normal GC and the premature GC? You can use
> PrintGCApplicationConcurrentTime and PrintGCApplicationStoppedTime to
> see how long the application runs between safepoints.
It may be the case (at least it seems so - there's no output from 
application in between). Thanks for the suggestion. I'll try to 
experiment with these flags.

> These premature GCs could be GC locker related. When the last thread
> exits a critical region there is a slight window before the GC locker
> initiated GC where another application can nip in and successfully
> schedule a regular GC.
Can you elaborate on this a little? I don't grasp how it can lead to a 
premature GC. Don't we schedule a GC anyway? Or does GC locker initiated 
GC have some special treatment?

Best regards,
Vladimir Ivanov

> JohnC
>
> On 5/15/2013 8:05 AM, Vladimir Ivanov wrote:
>> Hi,
>>
>> I see minor GCs occurring when young gen occupancy is very low, e.g.:
>> [ParNew: 8446K->7381K(943744K), 0.0274200 secs]
>>
>> Does anybody know what provokes such "premature" GCs?
>>
>> There's no CMS concurrent cycle running or any other interesting GC
>> events occurred around that moment - just a sequence of minor GCs with
>> such outlier.
>>
>> Such premature minor GCs occur on a regular basis.
>>
>> JDK version: 6u37, 64-Bit Server VM (20.12-b01, mixed mode)
>>
>> Best regards,
>> Vladimir Ivanov
>
-------------- next part --------------
2815.890: [ParNew: 846434K->8703K(943744K), 0.0283070 secs] 5208106K->4371653K(14575232K), 0.0289450 secs] [Times: user=0.48 sys=0.00, real=0.03 secs]
2820.780: [ParNew: 847615K->8402K(943744K), 0.0256840 secs] 5210565K->4372838K(14575232K), 0.0263680 secs] [Times: user=0.43 sys=0.00, real=0.03 secs]
2825.823: [ParNew: 847314K->10748K(943744K), 0.0268660 secs] 5211750K->4376420K(14575232K), 0.0275100 secs] [Times: user=0.43 sys=0.01, real=0.02 secs]
2831.078: [ParNew: 849660K->8160K(943744K), 0.0283290 secs] 5215332K->4375099K(14575232K), 0.0290450 secs] [Times: user=0.49 sys=0.00, real=0.03 secs]
2835.868: [ParNew: 847072K->4838K(943744K), 0.0287050 secs] 5214011K->4375941K(14575232K), 0.0294310 secs] [Times: user=0.48 sys=0.00, real=0.03 secs]
2840.808: [ParNew: 843750K->5540K(943744K), 0.0145170 secs] 5214853K->4377917K(14575232K), 0.0152300 secs] [Times: user=0.21 sys=0.00, real=0.02 secs]
2846.000: [ParNew: 844455K->18412K(943744K), 0.0279150 secs] 5216833K->4392039K(14575232K), 0.0286510 secs] [Times: user=0.47 sys=0.00, real=0.03 secs]
2846.030: [ParNew: 18476K->17990K(943744K), 0.0273230 secs] 4392102K->4393039K(14575232K), 0.0277960 secs] [Times: user=0.47 sys=0.00, real=0.03 secs]
2850.840: [ParNew: 856899K->7863K(943744K), 0.0250810 secs] 5231947K->4384207K(14575232K), 0.0257860 secs] [Times: user=0.43 sys=0.00, real=0.03 secs]
2855.868: [ParNew: 846775K->3671K(943744K), 0.0282020 secs] 5223119K->4384360K(14575232K), 0.0289250 secs] [Times: user=0.48 sys=0.00, real=0.03 secs]
2861.178: [ParNew: 842583K->5120K(943744K), 0.0113870 secs] 5223272K->4385809K(14575232K), 0.0120760 secs] [Times: user=0.17 sys=0.00, real=0.01 secs]
2865.899: [ParNew: 844032K->5750K(943744K), 0.0159510 secs] 5224721K->4387581K(14575232K), 0.0166430 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]
2870.832: [ParNew: 844662K->5634K(943744K), 0.0132100 secs] 5226493K->4388785K(14575232K), 0.0139100 secs] [Times: user=0.20 sys=0.00, real=0.02 secs]