'Java JVM G1GC Young Generation Eden Size Decrease and Predicted Pause Time Increase without Obvious Reason
My MicroService JVM openjdk version "1.8.0_292" encounter Eden size decrease suddenly from time to time like below and accordingly the predicted young region time increase significantly until several minutes later back to normal
Eden: 3648.0M(3648.0M)->0.0B(872.0M)
As Predicted GC Time co-related to G1GC Refinement Sampling behavior, I would ask help about:
- How to determine if G1GC Refinement Sampling is enough or not?
- I hope to reduce param G1ConRefinementServiceIntervalMillis to make sampling happen more frequently, but not able to found any doc to determine the relationship between sampling rate and predicted pause time, so want to see if anyone has more idea about it.
GC Log When the Predicted Time Start Jump Much Higher:
2022-04-22T23:04:44.299+0900: 38079.801: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 243269632 bytes, new threshold 15 (max 15)
- age 1: 5216336 bytes, 5216336 total
- age 2: 12570776 bytes, 17787112 total
- age 3: 513720 bytes, 18300832 total
- age 4: 563872 bytes, 18864704 total
- age 5: 6550496 bytes, 25415200 total
- age 6: 130688 bytes, 25545888 total
- age 7: 494312 bytes, 26040200 total
- age 8: 553568 bytes, 26593768 total
- age 9: 453296 bytes, 27047064 total
- age 10: 463264 bytes, 27510328 total
- age 11: 567608 bytes, 28077936 total
- age 12: 537752 bytes, 28615688 total
- age 13: 538424 bytes, 29154112 total
- age 14: 509088 bytes, 29663200 total
- age 15: 520584 bytes, 30183784 total
38079.801: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 99357, predicted base time: 19.18 ms, remaining time: 280.82 ms, target pause time: 300.00 ms]
38079.801: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 456 regions, survivors: 4 regions, predicted young region time: 208.60 ms]
38079.801: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 456 regions, survivors: 4 regions, old: 0 regions, predicted pause time: 227.78 ms, target pause time: 300.00 ms]
, 0.0351517 secs]
[Parallel Time: 32.4 ms, GC Workers: 5]
[GC Worker Start (ms): Min: 38079801.5, Avg: 38079801.6, Max: 38079801.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 6.6, Avg: 7.0, Max: 7.6, Diff: 0.9, Sum: 35.1]
[Update RS (ms): Min: 8.3, Avg: 8.4, Max: 8.4, Diff: 0.1, Sum: 41.8]
[Processed Buffers: Min: 142, Avg: 151.0, Max: 159, Diff: 17, Sum: 755]
[Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 16.2, Avg: 16.7, Max: 17.1, Diff: 0.9, Sum: 83.4]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Termination Attempts: Min: 1, Avg: 143.4, Max: 184, Diff: 183, Sum: 717]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
[GC Worker Total (ms): Min: 32.2, Avg: 32.3, Max: 32.3, Diff: 0.2, Sum: 161.3]
[GC Worker End (ms): Min: 38079833.8, Avg: 38079833.8, Max: 38079833.8, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 2.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.9 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 3648.0M(3648.0M)->0.0B(872.0M) Survivors: 32768.0K->49152.0K Heap: 4354.1M(6144.0M)->677.1M(6144.0M)]
[Times: user=0.17 sys=0.00, real=0.04 secs]
2022-04-22T23:04:44.335+0900: 38079.836: Total time for which application threads were stopped: 0.0380738 seconds, Stopping threads took: 0.0002653 seconds
2022-04-22T23:04:44.973+0900: 38080.475: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 62914560 bytes, new threshold 15 (max 15)
- age 1: 21034992 bytes, 21034992 total
- age 2: 596048 bytes, 21631040 total
- age 3: 12546344 bytes, 34177384 total
- age 4: 486568 bytes, 34663952 total
- age 5: 544408 bytes, 35208360 total
- age 6: 6466624 bytes, 41674984 total
- age 7: 130688 bytes, 41805672 total
- age 8: 492152 bytes, 42297824 total
- age 9: 552528 bytes, 42850352 total
- age 10: 452800 bytes, 43303152 total
- age 11: 462616 bytes, 43765768 total
- age 12: 565656 bytes, 44331424 total
- age 13: 537728 bytes, 44869152 total
- age 14: 538376 bytes, 45407528 total
- age 15: 509016 bytes, 45916544 total
38080.476: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 60824, predicted base time: 15.20 ms, remaining time: 284.80 ms, target pause time: 300.00 ms]
38080.476: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 109 regions, survivors: 6 regions, predicted young region time: 29368882.02 ms]
38080.476: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 109 regions, survivors: 6 regions, old: 0 regions, predicted pause time: 29368897.22 ms, target pause time: 300.00 ms]
, 0.0242586 secs]
[Parallel Time: 22.1 ms, GC Workers: 5]
[GC Worker Start (ms): Min: 38080475.8, Avg: 38080475.8, Max: 38080475.8, Diff: 0.1]
[Ext Root Scanning (ms): Min: 6.6, Avg: 6.9, Max: 7.4, Diff: 0.8, Sum: 34.7]
[Update RS (ms): Min: 5.3, Avg: 5.4, Max: 5.4, Diff: 0.0, Sum: 26.8]
[Processed Buffers: Min: 75, Avg: 86.0, Max: 96, Diff: 21, Sum: 430]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 9.1, Avg: 9.6, Max: 10.0, Diff: 0.8, Sum: 48.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Termination Attempts: Min: 1, Avg: 72.2, Max: 98, Diff: 97, Sum: 361]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 22.0, Avg: 22.0, Max: 22.0, Diff: 0.1, Sum: 110.0]
[GC Worker End (ms): Min: 38080497.8, Avg: 38080497.8, Max: 38080497.8, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 2.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.9 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 872.0M(872.0M)->0.0B(888.0M) Survivors: 49152.0K->32768.0K Heap: 1576.1M(6144.0M)->663.2M(6144.0M)]
[Times: user=0.11 sys=0.01, real=0.02 secs]
Sources
This article follows the attribution requirements of Stack Overflow and is licensed under CC BY-SA 3.0.
Source: Stack Overflow
| Solution | Source |
|---|

