1

I'm having an issue with GC pause (~400ms) which I'm trying to reduce. I noticed that I always have one worker a lot slower than others :

2013-06-03T17:24:51.606+0200: 605364.503: [GC pause (mixed)
Desired survivor size 109051904 bytes, new threshold 1 (max 1)
- age   1:   47105856 bytes,   47105856 total
, 0.47251300 secs]
[Parallel Time: 458.8 ms]
  [GC Worker Start (ms):  605364503.9  605364503.9  605364503.9  605364503.9  605364503.9  605364504.0
   Avg: 605364503.9, Min: 605364503.9, Max: 605364504.0, Diff:   0.1]
-->  [**Ext Root Scanning (ms)**:  **356.4**  3.1  3.7  3.6  3.2  3.0
   Avg:  62.2, **Min:   3.0, Max: 356.4, Diff: 353.4**] <---
  [Update RS (ms):  0.0  22.4  33.6  21.8  22.3  22.3
   Avg:  20.4, Min:   0.0,

As you can see one worker took 356 ms when others took only 3 ms !!!

If someone has an idea or think it's normal ..

Cyril S.
  • 83
  • 6

1 Answers1

2

[I'd rather post this as a comment, but I still lack the necessary points to do so]

No idea as to whether it is normal, but I've come across the same problem:

2014-01-16T13:52:56.433+0100: 59577.871: [GC pause (young), 2.55099911 secs]
   [Parallel Time: 2486.5 ms]
      [GC Worker Start (ms):  59577871.3  59577871.4  59577871.4  59577871.4  59577871.4  59577871.5  59577871.5  59577871.5
       Avg: 59577871.4, Min: 59577871.3, Max: 59577871.5, Diff:   0.2]
      [Ext Root Scanning (ms):  152.0  164.5  159.0  183.7  1807.0  117.4  113.8  138.2
       Avg: 354.5, Min: 113.8, Max: 1807.0, Diff: 1693.2]

I've been unable to find much about the subject but here http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2013-February/001484.html

Basically as you surmise one the GC worker threads is being held up when processing a single root. I've seen s similar issue that's caused by filling up the code cache (where JIT compiled methods are held). The code cache is treated as a single root and so is claimed in its entirety by a single GC worker thread. As a the code cache fills up, the thread that claims the code cache to scan starts getting held up.

A full GC clears the issue because that's where G1 currently does class unloading: the full GC unloads a whole bunch of classes allowing any the compiled code of any of the unloaded classes' methods to be freed by the nmethod sweeper. So after a a full GC the number of compiled methods in the code cache is less.

It could also be the just the sheer number of loaded classes as the system dictionary is also treated as a single claimable root.

I think I'll try enabling the code cache flushing and let you know. If you finally managed to solve this problem please let me know, I'm striving to get done with it as well.

Kind regards

César Varona
  • 61
  • 1
  • 6