In the gc log, sometimes with the following entry:
[346.310s][info ][gc,phases ] GC(743) Other: -24.8ms
[346.310s][debug][gc,phases ] GC(743) Choose CSet: 0.1ms
[346.310s][debug][gc,phases ] GC(743) Preserve CM Refs: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Reference Processing: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Reference Enqueuing: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Redirty Cards: 0.4ms
[346.310s][debug][gc,phases ] GC(743) Humongous Register: 0.4ms
[346.310s][debug][gc,phases ] GC(743) Humongous Reclaim: 0.0ms
Earlier in the log
[345.709s][info ][gc ] GC(742) Concurrent Mark (345.709s)
[345.709s][info ][gc,task ] GC(742) GC Workers: 1
[345.709s][info ][gc,start ] GC(743) Pause Young (G1 Evacuation Pause) (345.709s)
[345.709s][info ][gc,task ] GC(743) GC Workers: 4
[345.709s][trace][gc,ergo,cset] GC(743) Start choosing CSet. pending cards: 19463 predicted base time: 28.34ms remaining time: 171.66ms target pause time: 200.00ms
[345.709s][trace][gc,ergo,cset] GC(743) Add young regions to CSet. eden: 896 regions, survivors: 128 regions, predicted young region time: 557.11ms, target pause time: 200.00ms
[345.709s][debug][gc,ergo,cset] GC(743) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 0.00
[346.310s][info ][gc,phases ] GC(743) Root Region Scan Waiting: 26.5ms
The last line for the pause does not include the Root Region Scan Waiting time.
This workload generates a lot of dirty cards and rset changes, so marking could be long.
The problem is in
void G1GCPhaseTimes::print() {
...
if (_root_region_scan_wait_time_ms > 0.0) {
info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
...
info_line("Other", _gc_pause_time_ms - accounted_time_ms);
...
}
Root Region Scan Waiting is included in the accounted_time_ms, but _gc_pause_time_ms is recorded after Root Region Scan Waiting is done in G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
...
wait_for_root_region_scanning();
...
g1_policy()->note_gc_start(active_workers);
...}
we should move g1_policy()->note_gc_start to before wait_for_root_region_scanning
[346.310s][info ][gc,phases ] GC(743) Other: -24.8ms
[346.310s][debug][gc,phases ] GC(743) Choose CSet: 0.1ms
[346.310s][debug][gc,phases ] GC(743) Preserve CM Refs: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Reference Processing: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Reference Enqueuing: 0.0ms
[346.310s][debug][gc,phases ] GC(743) Redirty Cards: 0.4ms
[346.310s][debug][gc,phases ] GC(743) Humongous Register: 0.4ms
[346.310s][debug][gc,phases ] GC(743) Humongous Reclaim: 0.0ms
Earlier in the log
[345.709s][info ][gc ] GC(742) Concurrent Mark (345.709s)
[345.709s][info ][gc,task ] GC(742) GC Workers: 1
[345.709s][info ][gc,start ] GC(743) Pause Young (G1 Evacuation Pause) (345.709s)
[345.709s][info ][gc,task ] GC(743) GC Workers: 4
[345.709s][trace][gc,ergo,cset] GC(743) Start choosing CSet. pending cards: 19463 predicted base time: 28.34ms remaining time: 171.66ms target pause time: 200.00ms
[345.709s][trace][gc,ergo,cset] GC(743) Add young regions to CSet. eden: 896 regions, survivors: 128 regions, predicted young region time: 557.11ms, target pause time: 200.00ms
[345.709s][debug][gc,ergo,cset] GC(743) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 0.00
[346.310s][info ][gc,phases ] GC(743) Root Region Scan Waiting: 26.5ms
The last line for the pause does not include the Root Region Scan Waiting time.
This workload generates a lot of dirty cards and rset changes, so marking could be long.
The problem is in
void G1GCPhaseTimes::print() {
...
if (_root_region_scan_wait_time_ms > 0.0) {
info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
...
info_line("Other", _gc_pause_time_ms - accounted_time_ms);
...
}
Root Region Scan Waiting is included in the accounted_time_ms, but _gc_pause_time_ms is recorded after Root Region Scan Waiting is done in G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
...
wait_for_root_region_scanning();
...
g1_policy()->note_gc_start(active_workers);
...}
we should move g1_policy()->note_gc_start to before wait_for_root_region_scanning