JDK-8152948 : More unaccounted other time on large machines
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P4
  • Status: Closed
  • Resolution: Not an Issue
  • Submitted: 2016-03-29
  • Updated: 2022-07-20
  • Resolved: 2022-07-20
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
Other
tbdResolved
Related Reports
Duplicate :  
JDK-6868854 - G1: Eliminate serial Other times at the end of a GC pause
Relates :  
JDK-8227671 - G1: assert_used_and_recalculate_used_equal performs work in product builds
Relates :  
JDK-8155094 - Add logging for long lasting methods found in JDK-8152948
Relates :  
JDK-8227665 - Clearing collection set candidates takes a significant amount of time
Relates :  
JDK-8160539 - Stack frame scanning acquires DerivedPointerTableGC_lock mutex
Relates :  
JDK-8159979 - During initial mark, preparing all regions for marking may take a significant amount of time
Description
On very large applications (e.g. 1T heap) there is still a significant amount of unaccounted time in the "Other" category.

Investigate, change the title of this CR and improve the logging for this new phase(s). Also file follow-up issues to remedy these:

[2968.740s][info ][gc,phases   ] GC(53)   Evacuate Collection Set: 175.5ms
[2968.740s][debug][gc,phases   ] GC(53)     Ext Root Scanning (ms):   Min: 15.3, Avg: 22.9, Max: 31.9, Diff: 16.5, Sum: 5488.6, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     Update RS (ms):           Min:  7.6, Avg: 12.6, Max: 19.1, Diff: 11.5, Sum: 3015.7, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)       Processed Buffers:        Min: 0, Avg: 10.7, Max: 60, Diff: 60, Sum: 2557, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     Scan RS (ms):             Min: 12.8, Avg: 16.9, Max: 21.0, Diff:  8.2, Sum: 4048.9, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     Code Root Scanning (ms):  Min:  0.0, Avg:  0.1, Max:  0.6, Diff:  0.6, Sum: 16.0, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     Object Copy (ms):         Min: 106.7, Avg: 107.8, Max: 109.4, Diff:  2.7, Sum: 25879.8, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     Termination (ms):         Min:  0.2, Avg:  0.3, Max:  0.4, Diff:  0.2, Sum: 65.0, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)       Termination Attempts:     Min: 1, Avg:  1.3, Max: 2, Diff: 1, Sum: 317, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     GC Worker Other (ms):     Min:  0.1, Avg:  1.7, Max:  8.6, Diff:  8.6, Sum: 396.6, Threads: 240
[2968.740s][debug][gc,phases   ] GC(53)     GC Worker Total (ms):     Min: 155.1, Avg: 162.1, Max: 171.6, Diff: 16.5, Sum: 38910.6, Threads: 240
[2968.740s][info ][gc,phases   ] GC(53)   Code Roots: 0.2ms
[2968.740s][debug][gc,phases   ] GC(53)     Code Roots Fixup: 0.2ms
[2968.740s][debug][gc,phases   ] GC(53)     Code Roots Purge: 0.0ms
[2968.740s][info ][gc,phases   ] GC(53)   Clear Card Table: 18.1ms
[2968.740s][debug][gc,phases   ] GC(53)     Clear Card Table Serial: 6.6ms
[2968.740s][debug][gc,phases   ] GC(53)     Clear Card Table (ms):    Min:  0.0, Avg:  5.2, Max: 11.2, Diff: 11.2, Sum: 1244.0, Threads: 240
[2968.740s][info ][gc,phases   ] GC(53)   Expand Heap After Collection: 0.0ms
[2968.740s][info ][gc,phases   ] GC(53)   Free Collection Set: 54.3ms
[2968.740s][debug][gc,phases   ] GC(53)     Free Collection Set Serial: 0.0ms
[2968.740s][debug][gc,phases   ] GC(53)     Young Free CSet (ms):     Min:  7.6, Avg: 18.6, Max: 23.9, Diff: 16.3, Sum: 1968.4, Threads: 106
[2968.740s][debug][gc,phases   ] GC(53)     NonYoung Free CSet (ms):  -
[2968.740s][info ][gc,phases   ] GC(53)   Merge Per-Thread State: 36.5ms
[2968.740s][info ][gc,phases   ] GC(53)   Other: 44.6ms
[2968.740s][debug][gc,phases   ] GC(53)     Choose CSet: 0.1ms
[2968.740s][debug][gc,phases   ] GC(53)     Preserve CM Refs: 10.6ms
[2968.740s][debug][gc,phases   ] GC(53)     Reference Processing: 7.6ms
[2968.740s][debug][gc,phases   ] GC(53)     Reference Enqueuing: 4.9ms
[2968.740s][debug][gc,phases   ] GC(53)     Redirty Cards: 1.7ms
[2968.740s][debug][gc,phases   ] GC(53)     Humongous Register: 1.1ms
[2968.740s][debug][gc,phases   ] GC(53)     Humongous Reclaim: 0.0ms

I.e., formatted a bit better:

Other: 44.6ms
  Choose CSet 0.1ms
  Preserve CM Refs: 10.6ms
  Reference Processing: 7.6ms
  Reference Enqueuing: 4.9ms
  Redirty Cards: 1.7ms
  Humongous Register: 1.1ms
  Humongous Reclaim: 0.0ms

Missing: 18.6ms
Comments
The measurements done in this CR are way out of date, since then G1 changed so much that these are useless. Closing this out.
20-07-2022
Some further investigation showed the following areas of code that use a significant amount of time (>=2ms) on that large machines. These are compiled from different runs than the one above. Times given should be evaluated relative to each other, as the absolute times have no meaning. - 5ms: call to gc_prologue() in G1CollectedHeap::do_collection_pause_at_safepoint() to (including) DerivedPointerTable::clear(). Most likely TLAB statistics accumulation and ensuring parsability, as many Java threads are running. - 5-6ms: DerivedPointerTable::update_pointers() - 7-14ms: YoungList::reset_auxiliary_lists() with large survivor; note that somewhere deep down we calculate the remset size - 2-3ms: call to gc_epilogue(): again, per-Java thread operation - 17ms: (sometimes): call to G1RemSet::cleanupHRRS(); - 19ms: (sometimes): record_collection_pause_start() Most likely the call to SurvRateGroup::stop_adding_regions()
25-04-2016