RFR: Restore heap occupancy in GC logs after JFR changes

[Zhengyu Gu]

Okay.

-Zhengyu

On 08/29/2018 01:12 PM, Aleksey Shipilev wrote:
> 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
>