1

I'm working with an application that was recently upgraded and I'm seeing new behavior that I can't quite explain. The pattern of collections seems decent but then will perform in excess of 10 G1 Evacuation Collections (Young) in a row, within a few seconds. They seem to be clearing up the Eden memory, but I don't understand why it's filling up so quickly.

Is this a complex problem or am I doing something wrong? (If I have posted too much detail, I can edit and remove it).

-XX:+UseG1GC -Xms10240m -Xmx10240m -XX:NewRatio=2 -XX:NewSize=1792m -XX:G1ReservePercent=30 -XX:+AggressiveOpts

GCViewer If you look at this screenshot, you can see nearly solid blue lines where the young gen collections happen in rapid succession.


    2017-03-02T12:27:08.527-0800: 48187.087: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 299892736 bytes, new threshold 15 (max 15)
    - age   1:    6684488 bytes,    6684488 total
    - age   2:   15234432 bytes,   21918920 total
    - age   3:    5530024 bytes,   27448944 total
    - age   4:    5502152 bytes,   32951096 total
    - age   5:    4490976 bytes,   37442072 total
    - age   6:    1736456 bytes,   39178528 total
    - age   7:    2849184 bytes,   42027712 total
    - age   8:    2600504 bytes,   44628216 total
    - age   9:    1793032 bytes,   46421248 total
    - age  10:    1996752 bytes,   48418000 total
    - age  11:     876104 bytes,   49294104 total
    - age  12:    2233720 bytes,   51527824 total
    - age  13:    1218392 bytes,   52746216 total
    - age  14:     903760 bytes,   53649976 total
    - age  15:    1774480 bytes,   55424456 total
    , 0.0369978 secs]
       [Parallel Time: 32.2 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48187087.1, Avg: 48187087.2, Max: 48187087.3, Diff: 0.2]
          [Ext Root Scanning (ms): Min: 4.4, Avg: 6.5, Max: 12.0, Diff: 7.7, Sum: 51.9]
          [Update RS (ms): Min: 4.0, Avg: 8.5, Max: 9.6, Diff: 5.6, Sum: 68.3]
             [Processed Buffers: Min: 8, Avg: 13.4, Max: 19, Diff: 11, Sum: 107]
          [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 15.4, Avg: 16.6, Max: 17.8, Diff: 2.4, Sum: 132.5]
          [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
          [GC Worker Total (ms): Min: 31.9, Avg: 31.9, Max: 32.0, Diff: 0.2, Sum: 255.6]
          [GC Worker End (ms): Min: 48187119.1, Avg: 48187119.2, Max: 48187119.3, Diff: 0.1]
       [Code Root Fixup: 0.4 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.7 ms]
       [Other: 3.7 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.8 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.2 ms]
          [Humongous Register: 0.2 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.8 ms]
       [Eden: 4508.0M(4508.0M)->0.0B(4516.0M) Survivors: 68.0M->64.0M Heap: 7036.0M(10.0G)->2524.1M(10.0G)]
     [Times: user=0.26 sys=0.00, real=0.04 secs] 



    2017-03-02T12:27:09.078-0800: 48187.638: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 301989888 bytes, new threshold 15 (max 15)
    - age   1:      31144 bytes,      31144 total
    - age   2:    6631192 bytes,    6662336 total
    - age   3:   15225176 bytes,   21887512 total
    - age   4:    5530024 bytes,   27417536 total
    - age   5:    5501976 bytes,   32919512 total
    - age   6:    4490976 bytes,   37410488 total
    - age   7:    1736456 bytes,   39146944 total
    - age   8:    2849184 bytes,   41996128 total
    - age   9:    2600504 bytes,   44596632 total
    - age  10:    1793032 bytes,   46389664 total
    - age  11:    1996752 bytes,   48386416 total
    - age  12:     876104 bytes,   49262520 total
    - age  13:    2233720 bytes,   51496240 total
    - age  14:    1218392 bytes,   52714632 total
    - age  15:     903760 bytes,   53618392 total
    , 0.0320568 secs]
       [Parallel Time: 28.0 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48187638.4, Avg: 48187638.5, Max: 48187638.6, Diff: 0.2]
          [Ext Root Scanning (ms): Min: 3.8, Avg: 5.4, Max: 11.2, Diff: 7.4, Sum: 43.4]
          [Update RS (ms): Min: 2.4, Avg: 7.4, Max: 8.7, Diff: 6.3, Sum: 59.2]
             [Processed Buffers: Min: 7, Avg: 11.6, Max: 15, Diff: 8, Sum: 93]
          [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 13.6, Avg: 14.6, Max: 15.0, Diff: 1.3, Sum: 116.5]
          [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Termination Attempts: Min: 1, Avg: 1.9, Max: 3, Diff: 2, Sum: 15]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
          [GC Worker Total (ms): Min: 27.6, Avg: 27.7, Max: 27.8, Diff: 0.3, Sum: 221.9]
          [GC Worker End (ms): Min: 48187666.2, Avg: 48187666.3, Max: 48187666.3, Diff: 0.1]
       [Code Root Fixup: 0.3 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.7 ms]
       [Other: 3.0 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.5 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.2 ms]
          [Humongous Register: 0.2 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.6 ms]
       [Eden: 4516.0M(4516.0M)->0.0B(4520.0M) Survivors: 64.0M->60.0M Heap: 7040.1M(10.0G)->2521.7M(10.0G)]
     [Times: user=0.23 sys=0.00, real=0.03 secs]



    2017-03-02T12:27:09.618-0800: 48188.179: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 301989888 bytes, new threshold 15 (max 15)
    - age   1:      47960 bytes,      47960 total
    - age   2:      26736 bytes,      74696 total
    - age   3:    6628208 bytes,    6702904 total
    - age   4:   15151304 bytes,   21854208 total
    - age   5:    5530024 bytes,   27384232 total
    - age   6:    5501976 bytes,   32886208 total
    - age   7:    4490976 bytes,   37377184 total
    - age   8:    1736456 bytes,   39113640 total
    - age   9:    2849184 bytes,   41962824 total
    - age  10:    2600504 bytes,   44563328 total
    - age  11:    1792992 bytes,   46356320 total
    - age  12:    1996752 bytes,   48353072 total
    - age  13:     876104 bytes,   49229176 total
    - age  14:    2233720 bytes,   51462896 total
    - age  15:    1218392 bytes,   52681288 total
    , 0.0347669 secs]
       [Parallel Time: 30.5 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48188179.0, Avg: 48188179.0, Max: 48188179.1, Diff: 0.1]
          [Ext Root Scanning (ms): Min: 4.0, Avg: 6.2, Max: 14.5, Diff: 10.5, Sum: 49.9]
          [Update RS (ms): Min: 0.7, Avg: 8.2, Max: 10.1, Diff: 9.4, Sum: 65.9]
             [Processed Buffers: Min: 6, Avg: 12.5, Max: 22, Diff: 16, Sum: 100]
          [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 14.4, Avg: 15.4, Max: 15.8, Diff: 1.4, Sum: 123.1]
          [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Termination Attempts: Min: 1, Avg: 1.6, Max: 3, Diff: 2, Sum: 13]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
          [GC Worker Total (ms): Min: 30.2, Avg: 30.2, Max: 30.3, Diff: 0.1, Sum: 241.8]
          [GC Worker End (ms): Min: 48188209.2, Avg: 48188209.3, Max: 48188209.3, Diff: 0.2]
       [Code Root Fixup: 0.3 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.7 ms]
       [Other: 3.3 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 0.6 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.4 ms]
          [Humongous Register: 0.2 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.5 ms]
       [Eden: 4520.0M(4520.0M)->0.0B(4520.0M) Survivors: 60.0M->60.0M Heap: 7041.7M(10.0G)->2525.3M(10.0G)]
     [Times: user=0.24 sys=0.00, real=0.03 secs]

 

    2017-03-02T12:27:10.264-0800: 48188.825: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 301989888 bytes, new threshold 15 (max 15)
    - age   1:      48824 bytes,      48824 total
    - age   2:      18672 bytes,      67496 total
    - age   3:      17312 bytes,      84808 total
    - age   4:    6627608 bytes,    6712416 total
    - age   5:   15149168 bytes,   21861584 total
    - age   6:    5530024 bytes,   27391608 total
    - age   7:    5501976 bytes,   32893584 total
    - age   8:    4490848 bytes,   37384432 total
    - age   9:    1736456 bytes,   39120888 total
    - age  10:    2849184 bytes,   41970072 total
    - age  11:    2600504 bytes,   44570576 total
    - age  12:    1792992 bytes,   46363568 total
    - age  13:    1996752 bytes,   48360320 total
    - age  14:     876104 bytes,   49236424 total
    - age  15:    2233720 bytes,   51470144 total
    , 0.0343310 secs]
       [Parallel Time: 28.8 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48188825.2, Avg: 48188825.3, Max: 48188825.5, Diff: 0.3]
          [Ext Root Scanning (ms): Min: 3.9, Avg: 5.9, Max: 12.0, Diff: 8.1, Sum: 47.5]
          [Update RS (ms): Min: 2.9, Avg: 8.0, Max: 9.3, Diff: 6.3, Sum: 63.6]
             [Processed Buffers: Min: 8, Avg: 11.8, Max: 21, Diff: 13, Sum: 94]
          [Scan RS (ms): Min: 0.1, Avg: 0.3, Max: 0.4, Diff: 0.3, Sum: 2.3]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 13.0, Avg: 14.2, Max: 14.9, Diff: 1.9, Sum: 113.3]
          [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Termination Attempts: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 12]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
          [GC Worker Total (ms): Min: 28.3, Avg: 28.4, Max: 28.6, Diff: 0.4, Sum: 227.5]
          [GC Worker End (ms): Min: 48188853.7, Avg: 48188853.8, Max: 48188853.8, Diff: 0.1]
       [Code Root Fixup: 0.4 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.6 ms]
       [Other: 4.5 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 1.7 ms]
          [Ref Enq: 0.1 ms]
          [Redirty Cards: 0.3 ms]
          [Humongous Register: 0.3 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.7 ms]
       [Eden: 4520.0M(4520.0M)->0.0B(4524.0M) Survivors: 60.0M->56.0M Heap: 7045.3M(10.0G)->2522.1M(10.0G)]
     [Times: user=0.23 sys=0.00, real=0.03 secs]

 

    2017-03-02T12:27:10.866-0800: 48189.426: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 301989888 bytes, new threshold 15 (max 15)
    - age   1:     579088 bytes,     579088 total
    - age   2:       9904 bytes,     588992 total
    - age   3:      18376 bytes,     607368 total
    - age   4:      14720 bytes,     622088 total
    - age   5:    6624344 bytes,    7246432 total
    - age   6:   11726288 bytes,   18972720 total
    - age   7:    5529984 bytes,   24502704 total
    - age   8:    5492072 bytes,   29994776 total
    - age   9:    4482976 bytes,   34477752 total
    - age  10:    1736360 bytes,   36214112 total
    - age  11:    2848368 bytes,   39062480 total
    - age  12:    2600504 bytes,   41662984 total
    - age  13:    1792992 bytes,   43455976 total
    - age  14:    1996752 bytes,   45452728 total
    - age  15:     876104 bytes,   46328832 total
    , 0.0350574 secs]
       [Parallel Time: 29.2 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48189427.4, Avg: 48189427.5, Max: 48189427.6, Diff: 0.2]
          [Ext Root Scanning (ms): Min: 4.0, Avg: 5.8, Max: 11.5, Diff: 7.5, Sum: 46.0]
          [Update RS (ms): Min: 3.3, Avg: 8.2, Max: 9.6, Diff: 6.3, Sum: 65.8]
             [Processed Buffers: Min: 7, Avg: 13.0, Max: 22, Diff: 15, Sum: 104]
          [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
          [Object Copy (ms): Min: 13.2, Avg: 14.4, Max: 14.9, Diff: 1.7, Sum: 114.8]
          [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.3, Diff: 0.3, Sum: 2.1]
             [Termination Attempts: Min: 1, Avg: 3.8, Max: 7, Diff: 6, Sum: 30]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
          [GC Worker Total (ms): Min: 28.8, Avg: 28.9, Max: 29.0, Diff: 0.2, Sum: 231.1]
          [GC Worker End (ms): Min: 48189456.4, Avg: 48189456.4, Max: 48189456.4, Diff: 0.1]
       [Code Root Fixup: 0.3 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.7 ms]
       [Other: 4.8 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 1.4 ms]
          [Ref Enq: 0.2 ms]
          [Redirty Cards: 0.3 ms]
          [Humongous Register: 0.9 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.5 ms]
       [Eden: 4524.0M(4524.0M)->0.0B(4524.0M) Survivors: 56.0M->56.0M Heap: 7046.1M(10.0G)->2525.3M(10.0G)]
     [Times: user=0.24 sys=0.00, real=0.03 secs]

 

    2017-03-02T12:27:11.515-0800: 48190.075: [GC pause (G1 Evacuation Pause) (young)
    Desired survivor size 301989888 bytes, new threshold 15 (max 15)
    - age   1:     827320 bytes,     827320 total
    - age   2:      16496 bytes,     843816 total
    - age   3:       2352 bytes,     846168 total
    - age   4:      18176 bytes,     864344 total
    - age   5:      14528 bytes,     878872 total
    - age   6:    6577816 bytes,    7456688 total
    - age   7:   11698856 bytes,   19155544 total
    - age   8:    5520560 bytes,   24676104 total
    - age   9:    5492032 bytes,   30168136 total
    - age  10:    4482976 bytes,   34651112 total
    - age  11:    1736360 bytes,   36387472 total
    - age  12:    2848368 bytes,   39235840 total
    - age  13:    2600504 bytes,   41836344 total
    - age  14:    1792992 bytes,   43629336 total
    - age  15:    1996752 bytes,   45626088 total
    , 0.0353327 secs]
       [Parallel Time: 28.5 ms, GC Workers: 8]
          [GC Worker Start (ms): Min: 48190075.8, Avg: 48190075.9, Max: 48190076.1, Diff: 0.3]
          [Ext Root Scanning (ms): Min: 3.3, Avg: 6.0, Max: 11.7, Diff: 8.4, Sum: 47.7]
          [Update RS (ms): Min: 3.1, Avg: 7.5, Max: 8.7, Diff: 5.6, Sum: 60.4]
             [Processed Buffers: Min: 6, Avg: 13.0, Max: 23, Diff: 17, Sum: 104]
          [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 1.9]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
          [Object Copy (ms): Min: 12.8, Avg: 14.0, Max: 14.7, Diff: 1.9, Sum: 111.8]
          [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
             [Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 11]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.4, Max: 2.1, Diff: 2.1, Sum: 2.9]
          [GC Worker Total (ms): Min: 28.0, Avg: 28.1, Max: 28.2, Diff: 0.3, Sum: 224.8]
          [GC Worker End (ms): Min: 48190103.9, Avg: 48190104.0, Max: 48190104.1, Diff: 0.2]
       [Code Root Fixup: 0.4 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 0.7 ms]
       [Other: 5.7 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 2.6 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 0.3 ms]
          [Humongous Register: 0.2 ms]
          [Humongous Reclaim: 0.1 ms]
          [Free CSet: 1.9 ms]
       [Eden: 4524.0M(4524.0M)->0.0B(4512.0M) Survivors: 56.0M->60.0M Heap: 7049.3M(10.0G)->2529.7M(10.0G)]
     [Times: user=0.23 sys=0.00, real=0.04 secs]
Frank Behnke
  • 11
  • 1

1 Answers1

0

They seem to be clearing up the Eden memory, but I don't understand why it's filling up so quickly.

You already identified all that can be identified from the logs you have provided. A generation fills up because your application allocates objects. Which objects? You'll have to use an allocation profiler to identify that.

The pattern of collections seems decent but then will perform in excess of 10 G1 Evacuation Collections (Young) in a row, within a few seconds.

But it does not seem particularly excessive. It's spending 30-80ms per second on GC to clean gigabytes of memory. That's still a minimum mutator utilization of 92%.

Maybe your application is just bursty?

the8472
  • 40,999
  • 5
  • 70
  • 122
  • Thank you for looking. I believe that yes, the application is very bursty. Ultimately, I found that I was database bound (not enough connections allowed to the tomcat app.) This was not a garbage collection issue. – Frank Behnke Mar 06 '17 at 23:22