G1 unexpectedly clamps eden length clamping for time

Wed Feb 7 02:40:38 UTC 2024

Hi folks,

I'm looking into a report of expected reductions in the number of G1 eden
regions on our compute platform, where we use CFS on our shared compute
tier.

Reading through G1Policy it occurred to me that the
measured cost_per_byte_ms is critical, and that if the measured workers
were throttled, it would cause this weighted average to be artificially
inflated, blowing out pause time estimates and clamping the eden length.

Does my reading of the code and the log snippet below support that
hypothesis, or can a trained eye spot something I'm missing?

Cheers,
Danny

[93957.673s][1152][trace][gc,ergo,heap  ] Predicted base time: total
61.367096 lb_cards 102041 rs_length 0 effective_scanned_cards 102041
card_merge_time 0.699990 card_scan_time 22.050733 constant_other_time
6.205279 survivor_evac_time 32.411094
[93957.673s][1152][trace][gc,ergo,heap  ] Young desired length 860 survivor
length 11 allocated young length 859 absolute min young length 859 absolute
max young length 860 desired eden length by mmu 0 desired eden length by
pause 849
[93957.673s][1152][trace][gc,ergo,heap  ] Young target length: Common free
regions at end of collection 1113 desired young length 860 reserve region
144 max to eat into reserve 71
[93957.673s][1152][trace][gc,ergo,heap  ] Young target length: No need to
use reserve receiving additional eden 1
[93957.673s][1152][trace][gc,ergo,heap  ] Young target length: young target
length 860 allocated young length 859 received additional eden 1
[93957.673s][1152][trace][gc,ergo,heap  ] Young list length update: pending
cards 102041 rs_length 0 old target 860 desired: 860 target: 860 max: 903
[93957.709s][1152][info ][gc,start      ] GC(2837) Pause Young (Mixed) (G1
Evacuation Pause)
[93957.709s][1152][info ][gc,task       ] GC(2837) Using 4 workers of 4 for
evacuation
[93957.710s][1152][trace][gc,ergo,cset  ] GC(2837) Start choosing CSet.
Pending cards: 97118 target pause time: 200.00ms
[93957.710s][1152][trace][gc,ergo,heap  ] GC(2837) Predicted base time:
total 63.263775 lb_cards 97118 rs_length 25934 effective_scanned_cards
110151 card_merge_time 0.844123 card_scan_time 23.803278
constant_other_time 6.205279 survivor_evac_time 32.411094
[93957.710s][1152][trace][gc,ergo,cset  ] GC(2837) Added young regions to
CSet. Eden: 849 regions, Survivors: 11 regions, predicted eden time:
61.51ms, predicted base time: 63.26ms, target pause time: 200.00ms,
remaining time: 75.22ms
[93957.710s][1152][debug][gc,ergo,cset  ] GC(2837) Start adding marking
candidates to collection set. Min 2 regions, max 144 regions, time
remaining 75.22ms, optional threshold 15.04ms
[93957.710s][1152][debug][gc,ergo,cset  ] GC(2837) Marking candidates
exhausted.
[93957.710s][1152][debug][gc,ergo,cset  ] GC(2837) Finish adding marking
candidates to collection set. Initial: 13, optional: 0, predicted initial
time: 17.97ms, predicted optional time: 0.00ms, time remaining: 57.25ms
[93957.710s][1152][debug][gc,ergo       ] GC(2837) Running G1 Merge Heap
Roots using 4 workers for 873 regions
[93958.042s][1152][debug][gc,ergo       ] GC(2837) Running G1 Rebuild Free
List Task using 4 workers for rebuilding free list of regions
[93958.042s][1152][debug][gc,ergo,heap  ] GC(2837) Heap expansion: short
term pause time ratio 0.35% long term pause time ratio 0.33% threshold
7.69% pause time ratio 7.69% fully expanded true resize by 0B
[93958.042s][1152][debug][gc,ergo,ihop  ] GC(2837) Do not request
concurrent cycle initiation (still doing mixed collections) occupancy:
2508193792B allocation request: 0B threshold: 0B (0.00) source: end of GC
[93958.042s][1152][info ][gc,mmu        ] GC(2837) MMU target violated:
201.0ms (200.0ms/201.0ms)
[93958.042s][1152][debug][gc,ergo       ] GC(2837) do not continue mixed
GCs (candidate old regions not available)
[93958.042s][1152][debug][gc,ergo,ihop  ] GC(2837) Request concurrent cycle
initiation (occupancy higher than threshold) occupancy: 2508193792B
allocation request: 0B threshold: 0B (0.00) source: end of GC
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Predicted base time:
total 164.552708 lb_cards 86379 rs_length 50370 effective_scanned_cards
88850 card_merge_time 0.930841 card_scan_time 18.267386 constant_other_time
6.197170 survivor_evac_time 139.157311
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Young desired length 159
survivor length 36 allocated young length 36 absolute min young length 71
absolute max young length 860 desired eden length by mmu 1 desired eden
length by pause 123
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Young target length:
Common free regions at end of collection 1099 desired young length 159
reserve region 144 max to eat into reserve 71
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Young target length: No
need to use reserve receiving additional eden 123
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Young target length:
young target length 159 allocated young length 36 received additional eden
123
[93958.042s][1152][trace][gc,ergo,heap  ] GC(2837) Young list length
update: pending cards 86379 rs_length 50370 old target 860 desired: 159
target: 159 max: 202
[93958.042s][1152][debug][gc,ergo,refine] GC(2837) GC refinement: goal:
91539 + 6762 / 20.00ms, actual: 80518 / 17.06ms,
[93958.042s][1152][debug][gc,ergo,refine] GC(2837) New pending cards
target: 89589
[93958.042s][1152][info ][gc,phases     ] GC(2837)   Pre Evacuate
Collection Set: 0.9ms
[93958.042s][1152][info ][gc,phases     ] GC(2837)   Merge Heap Roots: 1.5ms
[93958.042s][1152][info ][gc,phases     ] GC(2837)   Evacuate Collection
Set: 325.0ms
[93958.042s][1152][info ][gc,phases     ] GC(2837)   Post Evacuate
Collection Set: 5.3ms
[93958.042s][1152][info ][gc,phases     ] GC(2837)   Other: 0.2ms
[93958.042s][1152][info ][gc,heap       ] GC(2837) Eden regions: 849->0(123)
[93958.042s][1152][info ][gc,heap       ] GC(2837) Survivor regions:
11->36(108)
[93958.042s][1152][info ][gc,heap       ] GC(2837) Old regions: 310->299
[93958.042s][1152][info ][gc,heap       ] GC(2837) Humongous regions: 0->0
[93958.042s][1152][info ][gc,metaspace  ] GC(2837) Metaspace:
450519K(457984K)->450519K(457984K) NonClass:
399480K(403584K)->399480K(403584K) Class: 51038K(54400K)->51038K(54400K)
[93958.042s][1152][info ][gc            ] GC(2837) Pause Young (Mixed) (G1
Evacuation Pause) 9349M->2668M(11472M) 333.112ms
[93958.043s][1152][info ][gc,cpu        ] GC(2837) User=1.19s Sys=0.00s
Real=0.34s
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20240207/15c89533/attachment.htm>