1

In our kafka broker setup, GC takes 20 ms on an average, but it randomly increases to 1-2 secs somtimes. Extreme cases it goes on for 9s. The frequency of this is fairly random. Happens 15 times per day on an average. I have tried using GCEasy, which didn't give any insights. My memory util is at 20% but the process still uses swap although memory is available. Appreciate any input on how this can be minimised

JVM opts:

-Xmx3G -Xms1G -server -XX:MetaspaceSize=96m -XX:+UseG1GC -
XX:MaxGCPauseMillis=20 -XX:InitiatingHeapOccupancyPercent=50 -
XX:G1HeapRegionSize=16M -XX:MinMetaspaceFreeRatio=50 -
XX:MaxMetaspaceFreeRatio=80

GC Log:

2018-04-15T18:22:26.526+0530: 529212.538: [GC pause (G1 Evacuation Pause) (young), 9.6174677 secs]
       [Parallel Time: 9422.7 ms, GC Workers: 10]
          [GC Worker Start (ms): Min: 529212702.8, Avg: 529212736.2, Max: 529212778.8, Diff: 76.1]
          [Ext Root Scanning (ms): Min: 117.8, Avg: 228.8, Max: 320.4, Diff: 202.5, Sum: 2287.9]
          [Update RS (ms): Min: 83.7, Avg: 134.0, Max: 203.6, Diff: 119.9, Sum: 1339.8]
             [Processed Buffers: Min: 1, Avg: 5.3, Max: 11, Diff: 10, Sum: 53]
          [Scan RS (ms): Min: 390.7, Avg: 449.4, Max: 498.2, Diff: 107.6, Sum: 4493.6]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
          [Object Copy (ms): Min: 8438.7, Avg: 8496.9, Max: 8532.1, Diff: 93.3, Sum: 84969.4]
          [Termination (ms): Min: 0.0, Avg: 18.8, Max: 21.5, Diff: 21.5, Sum: 187.9]
             [Termination Attempts: Min: 1, Avg: 3.8, Max: 9, Diff: 8, Sum: 38]
          [GC Worker Other (ms): Min: 2.5, Avg: 27.3, Max: 91.3, Diff: 88.8, Sum: 273.1]
          [GC Worker Total (ms): Min: 9312.4, Avg: 9355.2, Max: 9388.3, Diff: 75.9, Sum: 93551.7]
          [GC Worker End (ms): Min: 529222091.1, Avg: 529222091.3, Max: 529222091.7, Diff: 0.6]
       [Code Root Fixup: 1.9 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 12.1 ms]
       [Other: 180.8 ms]
          [Choose CSet: 0.0 ms]
          [Ref Proc: 18.0 ms]
          [Ref Enq: 0.0 ms]
          [Redirty Cards: 13.4 ms]
          [Humongous Register: 11.8 ms]
          [Humongous Reclaim: 0.2 ms]
          [Free CSet: 5.1 ms]
       [Eden: 768.0M(128.0M)->0.0B(128.0M) Survivors: 16.0M->16.0M Heap: 1775.9M(3072.0M)->1007.3M(3072.0M)]
     [Times: user=10.00 sys=15.22, real=9.63 secs]
1

1 Answer 1

0

Your logs show that, individual time per gc thread per region is low (in 100ms) but overall time for whole garbage collection is high and object copy phase is taking most of time here.

[Parallel Time: 9422.7 ms, GC Workers: 10]
          [GC Worker Start (ms): Min: 529212702.8, Avg: 529212736.2, Max: 529212778.8, Diff: 76.1]
          [Ext Root Scanning (ms): Min: 117.8, Avg: 228.8, Max: 320.4, Diff: 202.5, **Sum: 2287.9**]
          [Update RS (ms): Min: 83.7, Avg: 134.0, Max: 203.6, Diff: 119.9, **Sum: 1339.8**]
             [Processed Buffers: Min: 1, Avg: 5.3, Max: 11, Diff: 10, Sum: 53]
          [Scan RS (ms): Min: 390.7, Avg: 449.4, Max: 498.2, Diff: 107.6, **Sum: 4493.6**]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
          **[Object Copy (ms): Min: 8438.7, Avg: 8496.9, Max: 8532.1, Diff: 93.3, Sum: 84969.4]**
          [Termination (ms): Min: 0.0, Avg: 18.8, Max: 21.5, Diff: 21.5, Sum: 187.9]
             [Termination Attempts: Min: 1, Avg: 3.8, Max: 9, Diff: 8, Sum: 38]
          [GC Worker Other (ms): Min: 2.5, Avg: 27.3, Max: 91.3, Diff: 88.8, Sum: 273.1]
          [GC Worker Total (ms): Min: 9312.4, Avg: 9355.2, Max: 9388.3, Diff: 75.9, Sum: 93551.7]
          [GC Worker End (ms): Min: 529222091.1, Avg: 529222091.3, Max: 529222091.7, Diff: 0.6]

Which is taking average time of collection to higher value. I suspect few reason for this behavior,

  1. XX:G1HeapRegionSize=16M - This parameter should be set considering number of cores available, allowed gc threads/workers etc. Its best that let JVM select that value for you unless you are very sure about this.

  2. Object copy phase is taking time from copying objects from survivor spaces to next spaces. Looks like you are creating large amount of new objects in short duration. You can try increasing heap size if possible and especially young generation size. This will reduce the frequency of object copy from one survivor space to another.

  3. This could also happen because of swapping but not sure from these logs. disabling swapping is worth a try to see is that the culprit.

  4. If you have more processing power in terms of cpu then try increasing number of gc worker threads.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.