RFR: Restore heap occupancy in GC logs after JFR changes

Aleksey Shipilev shade at redhat.com
Wed Aug 29 17:12:39 UTC 2018


http://cr.openjdk.java.net/~shade/shenandoah/restore-logging/webrev.01/

This restores the GC logging after JFR changes, by partially reverting the change to GCTraceConcTime:
  http://hg.openjdk.java.net/shenandoah/jdk/rev/bda91c87813a

The critical part of the fix is to pass NULL gc_timer(), so that concurrent time is not recorded as
pause time in JFR.

Before:

[3.753s][info][gc] Trigger: Free (102M) is below minimum threshold (102M)
[3.755s][info][gc] GC(15) Pause Init Mark (process refs) 0.212ms
[3.755s][info][gc] GC(15) Concurrent marking (process refs)
[3.756s][info][gc] GC(15) Concurrent marking (process refs) 0.927ms
[3.756s][info][gc] GC(15) Concurrent precleaning
[3.757s][info][gc] GC(15) Concurrent precleaning 0.188ms
[3.757s][info][gc] GC(15) Pause Final Mark (process refs) 0.270ms
[3.757s][info][gc] GC(15) Concurrent cleanup
[3.757s][info][gc] GC(15) Concurrent cleanup 0.470ms

After:

[145.368s][info   ][gc ] GC(47) Pause Init Mark 0.803ms
[145.477s][info   ][gc ] GC(47) Concurrent marking 12919M->13287M(16384M) 108.655ms
[145.477s][info   ][gc ] GC(47) Pause Final Mark 0.433ms
[145.478s][info   ][gc ] GC(47) Concurrent cleanup 13279M->3487M(16384M) 0.294ms
[145.533s][info   ][gc ] GC(47) Concurrent evacuation 3487M->3999M(16384M) 55.698ms
[145.536s][info   ][gc ] GC(47) Pause Init Update Refs 0.048ms
[145.668s][info   ][gc ] GC(47) Concurrent update references 4007M->4407M(16384M) 132.001ms
[145.670s][info   ][gc ] GC(47) Pause Final Update Refs 0.676ms
[145.670s][info   ][gc ] GC(47) Concurrent cleanup 4407M->1495M(16384M) 0.353ms

Testing: tier1_gc_shenandoah, eyeballing gc logs, eyeballing JFR recordings with Shenandoah enabled

Thanks,
-Aleksey



More information about the shenandoah-dev mailing list