-
Enhancement
-
Resolution: Fixed
-
P4
-
8-shenandoah, 11-shenandoah, 14, 15
-
b18
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-8243607 | 14.0.2 | Aleksey Shipilev | P4 | Resolved | Fixed | b04 |
Our current log prints the heap changes for every operation, including those that do not change the heap directly. It clutters the GC log unnecessarily. We might consider only printing heap changes for the ops that do affect either used() or capacity().
Before:
[124.743s][info][gc] Trigger: Average GC time (1748.33 ms) is above the time for allocation rate (2215 MB/s) to deplete free headroom (3856M)
[124.749s][info][gc] GC(21) Concurrent reset 14567M->14585M(20480M) 6.079ms
[124.751s][info][gc] GC(21) Pause Init Mark (unload classes) 0.504ms
[125.482s][info][gc] GC(21) Concurrent marking (unload classes) 14671M->16071M(20480M) 731.045ms
[125.484s][info][gc] GC(21) Pause Final Mark (unload classes) 0.932ms
[125.492s][info][gc] GC(21) Concurrent roots processing 16175M->16216M(20480M) 7.794ms
[125.492s][info][gc] GC(21) Concurrent cleanup 16216M->16128M(20480M) 0.169ms
[125.725s][info][gc] GC(21) Concurrent evacuation 16128M->17201M(20480M) 232.863ms
[125.726s][info][gc] GC(21) Pause Init Update Refs 0.101ms
[126.531s][info][gc] GC(21) Concurrent update references 17255M->19111M(20480M) 805.111ms
[126.533s][info][gc] GC(21) Pause Final Update Refs 0.244ms
[126.533s][info][gc] GC(21) Concurrent cleanup 19111M->5423M(20480M) 0.238ms
After:
[125.755s][info][gc] Trigger: Average GC time (1764.16 ms) is above the time for allocation rate (2241 MB/s) to deplete free headroom (3950M)
[125.760s][info][gc] GC(21) Concurrent reset 5.215ms
[125.763s][info][gc] GC(21) Pause Init Mark (unload classes) 0.470ms
[126.507s][info][gc] GC(21) Concurrent marking (unload classes) 744.055ms
[126.510s][info][gc] GC(21) Pause Final Mark (unload classes) 0.826ms
[126.525s][info][gc] GC(21) Concurrent roots processing 12.399ms
[126.525s][info][gc] GC(21) Concurrent cleanup 16260M->16098M(20480M) 0.168ms
[126.726s][info][gc] GC(21) Concurrent evacuation 200.802ms
[126.727s][info][gc] GC(21) Pause Init Update Refs 0.111ms
[127.445s][info][gc] GC(21) Concurrent update references 717.766ms
[127.446s][info][gc] GC(21) Pause Final Update Refs 0.265ms
[127.447s][info][gc] GC(21) Concurrent cleanup 18736M->5208M(20480M) 0.229ms
Before:
[124.743s][info][gc] Trigger: Average GC time (1748.33 ms) is above the time for allocation rate (2215 MB/s) to deplete free headroom (3856M)
[124.749s][info][gc] GC(21) Concurrent reset 14567M->14585M(20480M) 6.079ms
[124.751s][info][gc] GC(21) Pause Init Mark (unload classes) 0.504ms
[125.482s][info][gc] GC(21) Concurrent marking (unload classes) 14671M->16071M(20480M) 731.045ms
[125.484s][info][gc] GC(21) Pause Final Mark (unload classes) 0.932ms
[125.492s][info][gc] GC(21) Concurrent roots processing 16175M->16216M(20480M) 7.794ms
[125.492s][info][gc] GC(21) Concurrent cleanup 16216M->16128M(20480M) 0.169ms
[125.725s][info][gc] GC(21) Concurrent evacuation 16128M->17201M(20480M) 232.863ms
[125.726s][info][gc] GC(21) Pause Init Update Refs 0.101ms
[126.531s][info][gc] GC(21) Concurrent update references 17255M->19111M(20480M) 805.111ms
[126.533s][info][gc] GC(21) Pause Final Update Refs 0.244ms
[126.533s][info][gc] GC(21) Concurrent cleanup 19111M->5423M(20480M) 0.238ms
After:
[125.755s][info][gc] Trigger: Average GC time (1764.16 ms) is above the time for allocation rate (2241 MB/s) to deplete free headroom (3950M)
[125.760s][info][gc] GC(21) Concurrent reset 5.215ms
[125.763s][info][gc] GC(21) Pause Init Mark (unload classes) 0.470ms
[126.507s][info][gc] GC(21) Concurrent marking (unload classes) 744.055ms
[126.510s][info][gc] GC(21) Pause Final Mark (unload classes) 0.826ms
[126.525s][info][gc] GC(21) Concurrent roots processing 12.399ms
[126.525s][info][gc] GC(21) Concurrent cleanup 16260M->16098M(20480M) 0.168ms
[126.726s][info][gc] GC(21) Concurrent evacuation 200.802ms
[126.727s][info][gc] GC(21) Pause Init Update Refs 0.111ms
[127.445s][info][gc] GC(21) Concurrent update references 717.766ms
[127.446s][info][gc] GC(21) Pause Final Update Refs 0.265ms
[127.447s][info][gc] GC(21) Concurrent cleanup 18736M->5208M(20480M) 0.229ms
- backported by
-
JDK-8243607 Shenandoah: only print heap changes for operations that directly affect it
- Resolved