The GCLocker blues...

[Tony Printezis]

Hi all,

(trying again from my Twitter address; moderator: feel free to disregard 
the original I accidentally sent from my personal address)

We have recently noticed an interesting problem which seems to happen 
quite frequently under certain circumstances. Immediately after a young 
GC, a second one happens which seems unnecessary given that it starts 
with an empty or almost empty eden. Here's an example:

{Heap before GC invocations=2 (full 0):
  par new generation   total 471872K, used 433003K [0x00000007bae00000, 
0x00000007dae00000, 0x00000007dae00000)
   eden space 419456K, 100% used [0x00000007bae00000, 
0x00000007d47a0000, 0x00000007d47a0000)
   from space 52416K,  25% used [0x00000007d47a0000, 0x00000007d54dacb0, 
0x00000007d7ad0000)
   to   space 52416K,   0% used [0x00000007d7ad0000, 0x00000007d7ad0000, 
0x00000007dae00000)
  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
0x00000007fae00000, 0x00000007fae00000)
    the space 524288K,   0% used [0x00000007dae00000, 
0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
0x00000007fc2c0000, 0x0000000800000000)
    the space 21248K,  12% used [0x00000007fae00000, 0x00000007fb07d7a0, 
0x00000007fb07d800, 0x00000007fc2c0000)
No shared spaces configured.
1.119: [GC (Allocation Failure)[ParNew: 433003K->15843K(471872K), 
0.0103090 secs] 433003K->15843K(996160K), 0.0103320 secs] [Times: 
user=0.03 sys=0.00, real=0.01 secs]
Heap after GC invocations=3 (full 0):
  par new generation   total 471872K, used 15843K [0x00000007bae00000, 
0x00000007dae00000, 0x00000007dae00000)
   eden space 419456K,   0% used [0x00000007bae00000, 
0x00000007bae00000, 0x00000007d47a0000)
   from space 52416K,  30% used [0x00000007d7ad0000, 0x00000007d8a48c88, 
0x00000007dae00000)
   to   space 52416K,   0% used [0x00000007d47a0000, 0x00000007d47a0000, 
0x00000007d7ad0000)
  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
0x00000007fae00000, 0x00000007fae00000)
    the space 524288K,   0% used [0x00000007dae00000, 
0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
0x00000007fc2c0000, 0x0000000800000000)
    the space 21248K,  12% used [0x00000007fae00000, 0x00000007fb07d7a0, 
0x00000007fb07d800, 0x00000007fc2c0000)
No shared spaces configured.
}
{Heap before GC invocations=3 (full 0):
  par new generation   total 471872K, used 24002K [0x00000007bae00000, 
0x00000007dae00000, 0x00000007dae00000)
   eden space 419456K,   1% used [0x00000007bae00000, 
0x00000007bb5f7c50, 0x00000007d47a0000)
   from space 52416K,  30% used [0x00000007d7ad0000, 0x00000007d8a48c88, 
0x00000007dae00000)
   to   space 52416K,   0% used [0x00000007d47a0000, 0x00000007d47a0000, 
0x00000007d7ad0000)
  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
0x00000007fae00000, 0x00000007fae00000)
    the space 524288K,   0% used [0x00000007dae00000, 
0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
0x00000007fc2c0000, 0x0000000800000000)
    the space 21248K,  12% used [0x00000007fae00000, 0x00000007fb07d7a0, 
0x00000007fb07d800, 0x00000007fc2c0000)
No shared spaces configured.
1.130: [GC (GCLocker Initiated GC)[ParNew: 24002K->12748K(471872K), 
0.0123930 secs] 24002K->12748K(996160K), 0.0124130 secs] [Times: 
user=0.04 sys=0.01, real=0.01 secs]
Heap after GC invocations=4 (full 0):
  par new generation   total 471872K, used 12748K [0x00000007bae00000, 
0x00000007dae00000, 0x00000007dae00000)
   eden space 419456K,   0% used [0x00000007bae00000, 
0x00000007bae00000, 0x00000007d47a0000)
   from space 52416K,  24% used [0x00000007d47a0000, 0x00000007d5413320, 
0x00000007d7ad0000)
   to   space 52416K,   0% used [0x00000007d7ad0000, 0x00000007d7ad0000, 
0x00000007dae00000)
  tenured generation   total 524288K, used 0K [0x00000007dae00000, 
0x00000007fae00000, 0x00000007fae00000)
    the space 524288K,   0% used [0x00000007dae00000, 
0x00000007dae00000, 0x00000007dae00200, 0x00000007fae00000)
  compacting perm gen  total 21248K, used 2549K [0x00000007fae00000, 
0x00000007fc2c0000, 0x0000000800000000)
    the space 21248K,  12% used [0x00000007fae00000, 0x00000007fb07d7a0, 
0x00000007fb07d800, 0x00000007fc2c0000)
No shared spaces configured.
}

Notice that:

* The timestamp of the second GC (1.130) is almost equal to the 
timestamp of the first GC plus the duration of the first GC (1.119 + 
0.0103320 = 1.1293). In this test young GCs normally happen at a 
frequency of one every 100ms-110ms or so.
* The eden at the start of the second GC is almost empty (1% occupancy). 
We've also seen it very often with a completely empty eden.
* (the big hint) The second GC is GClocker-initiated.

This happens most often with ParNew (in some cases, more than 30% of the 
GCs are those unnecessary ones) but also happens with ParallelGC too but 
less frequently (maybe 1%-1.5% of the GCs are those unnecessary ones). I 
was unable to reproduce it with G1.

I can reproduce it with with latest JDK 7, JDK 8, and also the latest 
hotspot-gc/hotspot workspace.

Are you guys looking into this (and is there a CR?)? I have a small test 
I can reproduce it with and a diagnosis / proposed fix(es) if you're 
interested.

Tony

-- 
Tony Printezis | JVM/GC Engineer / VM Team | Twitter

@TonyPrintezis
tprintezis at twitter.com