RFR: FreeSet should report its internal state before/after GC cycle

[Aleksey Shipilev]

On 04/11/2018 08:24 PM, Aleksey Shipilev wrote:
> http://cr.openjdk.java.net/~shade/shenandoah/freeset-log-af/webrev.01/
> 
> This introduces the extended logging for FreeSet, that makes sense to dump before/after Allocation
> Failure. This helps to diagnose the reason for the AF itself, as well as see how efficiently GC is
> dealing with cleaning up the space. With our current mechanics, we might just dump the freeset
> before/after the GC cycle, because that handles the AF paths as well.
> 
> Testing: hotspot_gc_shenandoah
> 
> Sample output:
> 
> [9.177s][info][gc      ] GC(6) Cancelling concurrent GC: Allocation Failure During Evac
> [9.180s][info][gc      ] GC(6) Concurrent evacuation 7117M->10234M(10240M) 195.019ms
> [9.180s][info][gc,ergo ] Free set:
> [9.180s][info][gc,ergo ]   Used: 3121M of 3121M
> [9.180s][info][gc,ergo ]   Mutator view:
> [9.180s][info][gc,ergo ]     Regions: 0
> [9.180s][info][gc,ergo ]     Max regular: 0K
> [9.180s][info][gc,ergo ]     Max humongous: 0K
> [9.180s][info][gc,ergo ]   Collector view:
> [9.180s][info][gc,ergo ]     Regions: 0
> [9.180s][info][gc,ergo ]     Max regular: 0K
> [9.180s][info][gc,ergo ] Pacer for Idle. Initial: 204M, Alloc Tax Rate: 1.0x
> [9.181s][info][gc,ergo ] Free set:
> [9.181s][info][gc,ergo ]   Used: 3121M of 3121M
> [9.181s][info][gc,ergo ]   Mutator view:
> [9.181s][info][gc,ergo ]     Regions: 0
> [9.181s][info][gc,ergo ]     Max regular: 0K
> [9.181s][info][gc,ergo ]     Max humongous: 0K
> [9.181s][info][gc,ergo ]   Collector view:
> [9.181s][info][gc,ergo ]     Regions: 0
> [9.181s][info][gc,ergo ]     Max regular: 0K

Actually, ragged output is not good for grepping. Made into single line:
  http://cr.openjdk.java.net/~shade/shenandoah/freeset-log-af/webrev.02/

[8.496s][info][gc,ergo ] Free set: Used: 20M of 3752M, Regions: 1142 mutator, 0 collector
[8.496s][info][gc,ergo ] Free set: Mutator view: Max regular: 4096K, Max humongous: 3522560K,
External frag: 8%, Internal frag: 18%
[8.496s][info][gc,ergo ] Free set: Collector view: Max regular: 0K


Thanks,
-Aleksey