G1 Garbage Collector spending a majority of time in Ref Proc

Question

I'm new to the G1 Garbage collection, but I have a heap with a Max of 26G, initial size 10G, and it's current size is 26G with 15G used.

I have GC logging turned on with the following arguments:

-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -verbose:gc -Xloggc:

When I check out my garbage collection garbage collection log, I notice that my Ref Proc seems to take the longest. I have -XX:MaxGCPauseMillis=1000 specified and my GC time is close to this, but it still seems like, to me, Ref Proc is running for a long time. I was wondering if there was a way of reducing this time?

Excerpt of my GC log:

[GC pause (young)
Desired survivor size 335544320 bytes, new threshold 15 (max 15)
- age   1:   18542272 bytes,   18542272 total
- age   2:    1752016 bytes,   20294288 total
- age   3:    1083928 bytes,   21378216 total
- age   4:    1078592 bytes,   22456808 total
- age   5:     854640 bytes,   23311448 total
- age   6:     549048 bytes,   23860496 total
- age   7:    1372744 bytes,   25233240 total
- age   8:     623048 bytes,   25856288 total
- age   9:     909984 bytes,   26766272 total
- age  10:     930072 bytes,   27696344 total
- age  11:     928088 bytes,   28624432 total
- age  12:    1053440 bytes,   29677872 total
- age  13:     553512 bytes,   30231384 total
- age  14:     787592 bytes,   31018976 total
- age  15:     985216 bytes,   32004192 total
, 1.22150400 secs]
   [Parallel Time: 176.4 ms]
      [GC Worker Start (ms):  209376973.5  209376973.6  209376973.6  209376973.6  209376973.7  209376973.7  209376973.7  209376973.8  209376973.8  209376973.8  209376973.8  209376973.9  209376973.9  209376974.0  209376974.0  209376974.0  209376974.0  209376974.1  209376974.1  209376974.1  209376974.1  209376974.2  209376974.2
       Avg: 209376973.9, Min: 209376973.5, Max: 209376974.2, Diff:   0.7]
      [Ext Root Scanning (ms):  2.2  2.0  2.2  1.5  36.8  2.2  3.6  1.6  1.6  1.6  1.7  2.2  1.7  1.5  1.5  1.5  1.5  1.8  1.7  1.6  1.3  1.6  1.7
       Avg:   3.3, Min:   1.3, Max:  36.8, Diff:  35.5]
      [Update RS (ms):  13.4  14.0  13.2  14.1  0.0  13.2  12.0  13.7  14.1  13.7  13.7  13.0  13.6  13.7  14.0  13.8  13.7  13.2  13.5  13.8  13.8  13.3  13.3
       Avg:  13.0, Min:   0.0, Max:  14.1, Diff:  14.1]
         [Processed Buffers : 8 4 16 6 0 11 10 9 14 8 8 11 15 5 7 7 13 16 9 6 12 7 13
          Sum: 215, Avg: 9, Min: 0, Max: 16, Diff: 16]
      [Scan RS (ms):  0.3  0.0  0.4  0.0  0.2  0.3  0.2  0.3  0.0  0.3  0.3  0.3  0.3  0.2  0.0  0.3  0.3  0.4  0.2  0.0  0.3  0.3  0.3
       Avg:   0.2, Min:   0.0, Max:   0.4, Diff:   0.3]
      [Object Copy (ms):  151.2  150.7  151.0  150.9  130.3  151.0  150.9  150.3  151.0  150.5  151.5  150.5  151.2  151.6  151.5  151.0  151.4  150.8  150.2  150.3  151.2  150.2  151.3
       Avg: 150.0, Min: 130.3, Max: 151.6, Diff:  21.2]
      [Termination (ms):  4.5  4.8  4.7  4.9  4.2  4.7  4.7  5.4  4.6  5.2  4.2  5.2  4.5  4.1  4.1  4.6  4.2  4.8  5.5  5.2  4.5  5.5  4.4
       Avg:   4.7, Min:   4.1, Max:   5.5, Diff:   1.4]
         [Termination Attempts : 2171 2328 2294 2328 2003 2294 2274 2497 2232 2498 1970 2481 2191 2035 2006 2287 2007 2320 2640 2554 2243 2532 2216
          Sum: 52401, Avg: 2278, Min: 1970, Max: 2640, Diff: 670]
      [GC Worker End (ms):  209377145.9  209377145.2  209377145.8  209377145.5  209377145.3  209377145.8  209377145.9  209377145.7  209377145.8  209377145.2  209377145.4  209377145.6  209377145.2  209377145.2  209377145.2  209377145.8  209377145.9  209377145.4  209377145.7  209377145.6  209377145.2  209377145.6  209377146.0
       Avg: 209377145.6, Min: 209377145.2, Max: 209377146.0, Diff:   0.9]
      [GC Worker (ms):  172.4  171.6  172.2  171.9  171.7  172.1  172.2  171.9  172.0  171.3  171.5  171.8  171.3  171.2  171.2  171.9  171.9  171.4  171.6  171.5  171.0  171.4  171.8
       Avg: 171.7, Min: 171.0, Max: 172.4, Diff:   1.3]
      [GC Worker Other (ms):  4.8  4.8  4.8  4.9  4.9  4.9  4.9  5.0  5.0  5.1  5.1  5.1  5.2  5.2  5.2  5.2  5.3  5.3  5.3  5.4  5.4  5.4  5.5
       Avg:   5.1, Min:   4.8, Max:   5.5, Diff:   0.7]
   [Clear CT:   1.9 ms]
   [Other: 1043.2 ms]
      [Choose CSet:   0.1 ms]
      [Ref Proc: 1029.7 ms]
      [Ref Enq:   5.5 ms]
      [Free CSet:   6.4 ms]
   [Eden: 4660M(4660M)->0B(4680M) Survivors: 460M->440M Heap: 15178M(25600M)->10501M(25600M)]
 [Times: user=4.98 sys=0.00, real=1.22 secs]

score 4 · Accepted Answer · answered Jul 25 '13 at 09:06

4

Do you mean, apart from using less weak/soft references?

I would avoid them as much as you can if you want performance. You can enable -XX:+TraceReferenceGC to get more information on your references.

I often suggest people try larger Eden sizes, and use a memory profiler to reduce the amount of garbage you produce. With so much being cleared from tenured space it appears you are getting a lot of premature promotion.

answered Jul 25 '13 at 09:06

Peter Lawrey

525,659
79
751
1,130

I'm not explicitly using weak/soft references, just declaring my objects without a strength, which I believe makes it Strong. Right now I have the default JVM arguments for everything except memory and G1, so my eden size is some % of my Old Gen. You're saying that it looks like I have a lot of objects going from new -> old then they get removed from the old generation soon after? – Nicholas Jul 25 '13 at 09:54
@Nicholas I am saying, you or a library you are using has lots of WeakReference or SoftReferences. I am also saying you are getting a lot of objects dying in old space, but I suspect this is not you main problem. – Peter Lawrey Jul 25 '13 at 10:44
Okay, thank you for that clarification. I will look into a library we are using, they may be creating objects in that fashion. – Nicholas Jul 25 '13 at 10:55
1

I would get a class dump with `jmap -histo:live {pid} | grep Ref` – Peter Lawrey Jul 25 '13 at 10:58
1

If I'm reading it correctly, and the first column is the total count of those types of objects, there are 418k `WeakReference` objects, which is a lot. I will look into what is causing this. Thank you for all your help. – Nicholas Jul 25 '13 at 11:15
@Nicholas, Did you resolve this problem. I am also facing similar issue http://stackoverflow.com/questions/23101817/g1gc-remark-phase-is-taking-too-long. If its rsolved, can you add more details. ~Thanks – Atul Soman Apr 16 '14 at 14:14
I wasn't able to resolve this with any magic, an algorithm refactor was what fixed it for me. – Nicholas Apr 17 '14 at 01:32
1

Added an answer to point out ParallelRefProc, if you don't mind I would edit it into your accepted answer. – eckes Feb 12 '17 at 16:37
@eckes I +1 your answer. – Peter Lawrey Feb 13 '17 at 07:47

score 1 · Answer 2 · answered Feb 12 '17 at 16:36

1

You can try to specify parallel processing, however it only can improve the times linear to some extend: -XX:+ParallelRefProcEnabled

answered Feb 12 '17 at 16:36

eckes

10,103
1
59
71

G1 Garbage Collector spending a majority of time in Ref Proc

2 Answers2