Bug ID: JDK-8315503 G1: Code root scan causes long GC pauses due to imbalanced iteration

Type: Enhancement
Component: hotspot
Sub-Component: gc
Affected Version: 21,22

Priority: P4
Status: Resolved
Resolution: Fixed

Submitted: 2023-09-01
Updated: 2024-05-29
Resolved: 2023-10-02

JDK 21	JDK 22
21.0.4-oracleFixed	22 b18Fixed

In some internal test we found that the current claiming policy of one region per thread can cause huge imbalance and very long pause times, see the log:

[4179,965s][gc,phases      ] GC(273)   Evacuate Collection Set: 812,18ms
[..]
[4179,965s][gc,phases      ] GC(273)     Code Root Scan (ms):           Min: 0,00, Avg: 59,03, Max: 775,12, Diff: 775,12, Sum: 944,44, Workers: 16
[4179,965s][gc,phases      ] GC(273)     Object Copy (ms):              Min: 26,74, Avg: 101,06, Max: 118,92, Diff: 92,18, Sum: 1616,98, Workers: 16
[4179,965s][gc,phases      ] GC(273)     Termination (ms):              Min: 0,03, Avg: 643,90, Max: 690,96, Diff: 690,93, Sum: 10302,47, Workers: 16
[4179,965s][gc,phases      ] GC(273)       Termination Attempts:          Min: 1, Avg:  1,0, Max: 1, Diff: 0, Sum:

Fix request [21u] I backport this for parity with 21.0.4-oracle. Medium to larger risk. Central component, larger change, has already3 follow-up fixes. Hung since 10/23, released with jdk22, so it underwent lots of testing. I resolved 4 hunks. I inlcude follow-ups JDK-8317440 and JDK-8318720 in this change (both clean on top) and backport larger JDK-8323685 as dependent PR. Test passes. SAP nightly testing passed.
10-04-2024
A pull request was submitted for review. URL: https://git.openjdk.org/jdk21u-dev/pull/476 Date: 2024-04-08 20:00:14 +0000
08-04-2024
Changeset: 795e5dcc Author: Thomas Schatzl <tschatzl@openjdk.org> Date: 2023-10-02 07:35:02 +0000 URL: https://git.openjdk.org/jdk/commit/795e5dcc856491031b87a1f2a942681a582673ab
02-10-2023
Attached a reproducer for this issue heavily based on the "CodeCacheStress" jmh benchmark. Run with something like: java -Xlog:gc,gc+phases=debug:/tmp/ccstress.log CCStress.java JDK22 pre-change results: ccstress.jdk22:[1.359s][debug][gc,phases] GC(0) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 5.9, Diff: 5.9, Sum: 14.3, Workers: 28 ccstress.jdk22:[1.738s][debug][gc,phases] GC(1) Code Root Scan (ms): Min: 0.0, Avg: 0.3, Max: 7.7, Diff: 7.7, Sum: 7.9, Workers: 28 ccstress.jdk22:[2.462s][debug][gc,phases] GC(2) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 12.9, Diff: 12.9, Sum: 14.1, Workers: 28 ccstress.jdk22:[5.167s][debug][gc,phases] GC(3) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 11.8, Diff: 11.8, Sum: 12.7, Workers: 28 ccstress.jdk22:[7.173s][debug][gc,phases] GC(4) Code Root Scan (ms): Min: 0.0, Avg: 0.6, Max: 15.4, Diff: 15.4, Sum: 17.2, Workers: 28 ccstress.jdk22:[9.111s][debug][gc,phases] GC(5) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 13.9, Diff: 13.9, Sum: 14.2, Workers: 28 ccstress.jdk22:[10.819s][debug][gc,phases] GC(6) Code Root Scan (ms): Min: 0.0, Avg: 0.6, Max: 17.3, Diff: 17.3, Sum: 17.8, Workers: 28 ccstress.jdk22:[12.445s][debug][gc,phases] GC(7) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 14.6, Diff: 14.6, Sum: 14.7, Workers: 28 ccstress.jdk22:[14.154s][debug][gc,phases] GC(8) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 14.3, Diff: 14.3, Sum: 14.4, Workers: 28 ccstress.jdk22:[16.285s][debug][gc,phases] GC(9) Code Root Scan (ms): Min: 0.0, Avg: 0.7, Max: 18.8, Diff: 18.8, Sum: 19.0, Workers: 28 ccstress.jdk22:[18.209s][debug][gc,phases] GC(10) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 15.2, Diff: 15.2, Sum: 15.4, Workers: 28 ccstress.jdk22:[20.140s][debug][gc,phases] GC(11) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 14.2, Diff: 14.2, Sum: 14.4, Workers: 28 ccstress.jdk22:[22.040s][debug][gc,phases] GC(12) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 13.1, Diff: 13.1, Sum: 13.3, Workers: 28 ccstress.jdk22:[24.016s][debug][gc,phases] GC(13) Code Root Scan (ms): Min: 0.0, Avg: 0.7, Max: 19.5, Diff: 19.5, Sum: 19.7, Workers: 28 ccstress.jdk22:[25.970s][debug][gc,phases] GC(14) Code Root Scan (ms): Min: 0.0, Avg: 0.5, Max: 14.3, Diff: 14.3, Sum: 14.5, Workers: 28 ccstress.jdk22:[27.885s][debug][gc,phases] GC(15) Code Root Scan (ms): Min: 0.0, Avg: 0.6, Max: 18.0, Diff: 18.0, Sum: 18.1, Workers: 28 ccstress.jdk22:[29.785s][debug][gc,phases] GC(16) Code Root Scan (ms): Min: 0.0, Avg: 0.1, Max: 1.5, Diff: 1.5, Sum: 1.6, Workers: 28 ccstress.jdk22:[31.689s][debug][gc,phases] GC(17) Code Root Scan (ms): Min: 0.0, Avg: 0.1, Max: 2.5, Diff: 2.5, Sum: 2.7, Workers: 28 ccstress.jdk22:[33.589s][debug][gc,phases] GC(18) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 1.1, Diff: 1.1, Sum: 1.2, Workers: 28 ccstress.jdk22:[35.536s][debug][gc,phases] GC(19) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.7, Diff: 0.7, Sum: 0.8, Workers: 28 ccstress.jdk22:[37.427s][debug][gc,phases] GC(20) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.4, Workers: 28 ccstress.jdk22:[39.315s][debug][gc,phases] GC(21) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.9, Diff: 0.9, Sum: 1.0, Workers: 28 ccstress.jdk22:[41.247s][debug][gc,phases] GC(22) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1, Workers: 28 ccstress.jdk22:[43.168s][debug][gc,phases] GC(23) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1, Workers: 28 ccstress.jdk22:[45.059s][debug][gc,phases] GC(24) Code Root Scan (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1, Workers: 28 after: ccstress.log:[1.334s][debug][gc,phases] GC(0) Code Root Scan (ms): Min: 0.01, Avg: 1.33, Max: 3.37, Diff: 3.36, Sum: 37.32, Workers: 28 ccstress.log:[1.702s][debug][gc,phases] GC(1) Code Root Scan (ms): Min: 0.01, Avg: 1.26, Max: 2.00, Diff: 1.99, Sum: 35.25, Workers: 28 ccstress.log:[2.390s][debug][gc,phases] GC(2) Code Root Scan (ms): Min: 0.02, Avg: 1.18, Max: 2.66, Diff: 2.64, Sum: 33.12, Workers: 28 ccstress.log:[5.026s][debug][gc,phases] GC(3) Code Root Scan (ms): Min: 0.10, Avg: 0.88, Max: 2.30, Diff: 2.19, Sum: 24.71, Workers: 28 ccstress.log:[7.043s][debug][gc,phases] GC(4) Code Root Scan (ms): Min: 0.13, Avg: 3.97, Max: 4.82, Diff: 4.69, Sum: 111.30, Workers: 28 ccstress.log:[8.947s][debug][gc,phases] GC(5) Code Root Scan (ms): Min: 0.10, Avg: 3.60, Max: 4.56, Diff: 4.47, Sum: 100.89, Workers: 28 ccstress.log:[10.671s][debug][gc,phases] GC(6) Code Root Scan (ms): Min: 0.11, Avg: 2.68, Max: 3.92, Diff: 3.81, Sum: 74.96, Workers: 28 ccstress.log:[12.403s][debug][gc,phases] GC(7) Code Root Scan (ms): Min: 0.12, Avg: 2.47, Max: 4.08, Diff: 3.96, Sum: 69.14, Workers: 28 ccstress.log:[14.082s][debug][gc,phases] GC(8) Code Root Scan (ms): Min: 0.09, Avg: 2.12, Max: 3.77, Diff: 3.68, Sum: 59.34, Workers: 28 ccstress.log:[15.698s][debug][gc,phases] GC(9) Code Root Scan (ms): Min: 0.13, Avg: 2.20, Max: 3.14, Diff: 3.01, Sum: 61.62, Workers: 28 ccstress.log:[17.256s][debug][gc,phases] GC(10) Code Root Scan (ms): Min: 0.09, Avg: 1.03, Max: 2.88, Diff: 2.79, Sum: 28.84, Workers: 28 ccstress.log:[18.788s][debug][gc,phases] GC(11) Code Root Scan (ms): Min: 0.10, Avg: 1.84, Max: 4.19, Diff: 4.09, Sum: 51.48, Workers: 28 ccstress.log:[20.297s][debug][gc,phases] GC(12) Code Root Scan (ms): Min: 0.10, Avg: 2.72, Max: 4.21, Diff: 4.11, Sum: 76.05, Workers: 28 ccstress.log:[21.853s][debug][gc,phases] GC(13) Code Root Scan (ms): Min: 0.10, Avg: 1.57, Max: 2.95, Diff: 2.84, Sum: 44.00, Workers: 28 ccstress.log:[23.483s][debug][gc,phases] GC(14) Code Root Scan (ms): Min: 0.09, Avg: 2.14, Max: 4.51, Diff: 4.41, Sum: 60.03, Workers: 28 ccstress.log:[25.070s][debug][gc,phases] GC(15) Code Root Scan (ms): Min: 0.10, Avg: 2.44, Max: 3.80, Diff: 3.70, Sum: 68.32, Workers: 28 ccstress.log:[26.579s][debug][gc,phases] GC(16) Code Root Scan (ms): Min: 0.08, Avg: 0.13, Max: 0.60, Diff: 0.51, Sum: 3.63, Workers: 28 ccstress.log:[28.092s][debug][gc,phases] GC(17) Code Root Scan (ms): Min: 0.09, Avg: 0.14, Max: 0.81, Diff: 0.72, Sum: 3.89, Workers: 28 ccstress.log:[29.588s][debug][gc,phases] GC(18) Code Root Scan (ms): Min: 0.09, Avg: 0.13, Max: 0.64, Diff: 0.55, Sum: 3.53, Workers: 28 ccstress.log:[31.089s][debug][gc,phases] GC(19) Code Root Scan (ms): Min: 0.08, Avg: 0.12, Max: 0.51, Diff: 0.43, Sum: 3.46, Workers: 28 ccstress.log:[32.588s][debug][gc,phases] GC(20) Code Root Scan (ms): Min: 0.09, Avg: 0.12, Max: 0.30, Diff: 0.21, Sum: 3.33, Workers: 28 ccstress.log:[34.082s][debug][gc,phases] GC(21) Code Root Scan (ms): Min: 0.08, Avg: 0.12, Max: 0.23, Diff: 0.15, Sum: 3.38, Workers: 28 ccstress.log:[35.629s][debug][gc,phases] GC(22) Code Root Scan (ms): Min: 0.09, Avg: 0.12, Max: 0.20, Diff: 0.11, Sum: 3.31, Workers: 28 ccstress.log:[37.158s][debug][gc,phases] GC(23) Code Root Scan (ms): Min: 0.08, Avg: 0.11, Max: 0.13, Diff: 0.05, Sum: 3.07, Workers: 28 ccstress.log:[38.692s][debug][gc,phases] GC(24) Code Root Scan (ms): Min: 0.09, Avg: 0.11, Max: 0.14, Diff: 0.04, Sum: 3.13, Workers: 28 ccstress.log:[40.182s][debug][gc,phases] GC(25) Code Root Scan (ms): Min: 0.09, Avg: 0.11, Max: 0.13, Diff: 0.04, Sum: 3.10, Workers: 28 ccstress.log:[41.679s][debug][gc,phases] GC(26) Code Root Scan (ms): Min: 0.09, Avg: 0.12, Max: 0.15, Diff: 0.05, Sum: 3.42, Workers: 28 ccstress.log:[43.169s][debug][gc,phases] GC(27) Code Root Scan (ms): Min: 0.09, Avg: 0.12, Max: 0.15, Diff: 0.06, Sum: 3.36, Workers: 28 ccstress.log:[44.690s][debug][gc,phases] GC(28) Code Root Scan (ms): Min: 0.10, Avg: 0.12, Max: 0.16, Diff: 0.07, Sum: 3.36, Workers: 28 With the change there is more cpu usage if there is not that much parallelism to extract, but it is much better in case of actual unbalanced code root sets.
28-09-2023
A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/15811 Date: 2023-09-19 08:04:23 +0000
20-09-2023

Blocks :	JDK-8316212 - G1: Filter code root insertion into collection set during root scanning
Blocks :	JDK-8317007 - Add bulk removal of dead nmethods during class unloading
Duplicate :	JDK-8242043 - G1: Naming of HeapRegionRemSet locks contribute to startup overhead
Relates :	JDK-7145569 - G1: optimize nmethods scanning
Relates :	JDK-8332420 - Regression in DaCapo-fop-default on linux-x64
Relates :	JDK-8326092 - Pause Remark sometimes has extremely long pause times on class unloading
Relates :	JDK-8318720 - G1: Memory leak in G1CodeRootSet after JDK-8315503
Relates :	JDK-8317440 - Lock rank checking fails when code root set is modified with the Servicelock held after JDK-8315503