CMS: "premature" minor GCs w/ ParNew

[Vladimir Ivanov]

John,

So, I got some more data on that [1] (unfortunaltey, no log w/ GC reason 
yet). Application does some work in between, but it's tiny (worked for 
0.1ms & allocated ~1Mb).

Best regards,
Vladimir Ivanov

[1]
101220.389: [GC 101220.390: [ParNew
Desired survivor size 53673984 bytes, new threshold 3 (max 3)
- age   1:     929440 bytes,     929440 total
- age   2:    2864592 bytes,    3794032 total
- age   3:    1028480 bytes,    4822512 total
: 845730K->7106K(943744K), 0.0838040 secs] 
4111626K->3273982K(14575232K), 0.0844520 secs] [Times: user=0.52 
sys=0.00, real=0.09 secs]

Total time for which application threads were stopped: 0.0874230 seconds
Application time: 0.0001460 seconds

101220.477: [GC 101220.477: [ParNew
Desired survivor size 53673984 bytes, new threshold 3 (max 3)
- age   1:       2104 bytes,       2104 total
- age   2:     927096 bytes,     929200 total
- age   3:    3913192 bytes,    4842392 total
: 8148K->5665K(943744K), 0.0186370 secs] 3275023K->3273571K(14575232K), 
0.0191650 secs] [Times: user=0.27 sys=0.00, real=0.02 secs]

Total time for which application threads were stopped: 0.0222120 seconds
Application time: 8.6636930 seconds

101229.163: [GC 101229.164: [ParNew
Desired survivor size 53673984 bytes, new threshold 3 (max 3)
- age   1:    1012848 bytes,    1012848 total
- age   3:     872344 bytes,    1885192 total
: 844577K->3631K(943744K), 0.0860900 secs] 
4112483K->3274358K(14575232K), 0.0867710 secs] [Times: user=0.28 
sys=0.00, real=0.09 secs]

On 5/15/13 9:00 PM, John Cuthbertson wrote:
> Hi Vladimir,
>
> Can you run with an early access jdk8? If so then enable the flag
> PrintGCCause and you should get the reasons for these GCs. How do the
> timestamps of these premature GCs compare to the previous GC? Are they
> back to back with a non-premature GC? 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.
>
> 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.
>
> 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
>