RFR: 8278282: G1: Log basic statistics of evacuation failure

[Stefan Johansson]

On Wed, 8 Dec 2021 11:30:45 GMT, Hamlin Li <mli at openjdk.org> wrote:

> This is to get information about the pause time distribution (prepare(copy, sorting, …) , process (iterate) and cleanup) and region/objects/size statistics when processing evacuation failure objects in “Remove Self Forwards”, this information will be helpful when optimize the evacuation failure processing subsequently, and will also be helpful for users to analyze and troubleshoot in the future.
> 
> 
> [10.917s][debug][gc,phases] GC(0)       Restore Retained Regions (ms): ...
> [10.917s][debug][gc,phases] GC(0)         Retained Regions:              ...
> [10.917s][trace][gc,phases] GC(0)         Prepare Retained Object Refs (ms): ...
> [10.917s][trace][gc,phases] GC(0)         Reformat Retained Regions (ms): ...
> [10.917s][trace][gc,phases] GC(0)           Retained Objects:              ...
> [10.917s][trace][gc,phases] GC(0)           Retained Bytes:                ...
> [10.917s][trace][gc,phases] GC(0)         Reclaim Memory (ms):           ...
> [10.917s][trace][gc,phases] GC(0)           Used [Native] Memory:          ...

Haven't looked in detail at the patch yet, but I have a comment on the output. 
> ```
> [10.917s][debug][gc,phases] GC(0)       Restore Retained Regions (ms): ...
> [10.917s][debug][gc,phases] GC(0)         Retained Regions:              ...
> [10.917s][trace][gc,phases] GC(0)         Prepare Retained Object Refs (ms): ...
> [10.917s][trace][gc,phases] GC(0)         Reformat Retained Regions (ms): ...
> [10.917s][trace][gc,phases] GC(0)           Retained Objects:              ...
> [10.917s][trace][gc,phases] GC(0)           Retained Bytes:                ...
> [10.917s][trace][gc,phases] GC(0)         Reclaim Memory (ms):           ...
> [10.917s][trace][gc,phases] GC(0)           Used [Native] Memory:          ...
> ```

I thought we agreed on having more things on debug level and using "Evacuation Failure Regions" for now (until we have more than one type of retained regions), like this:

[10.917s][debug][gc,phases] GC(0)       Restore Retained Regions (ms): ...
[10.917s][debug][gc,phases] GC(0)         Evacuation Failed Regions:              ...
[10.917s][debug][gc,phases] GC(0)         Prepare Retained Object Refs (ms): ...
[10.917s][debug][gc,phases] GC(0)         Reformat Retained Regions (ms): ...
[10.917s][debug][gc,phases] GC(0)           Retained Objects:              ...
[10.917s][trace][gc,phases] GC(0)           Retained Bytes:                ...
[10.917s][debug][gc,phases] GC(0)         Reclaim Memory (ms):           ...
[10.917s][trace][gc,phases] GC(0)           Used [Native] Memory:          ...

Possibly also put the regions count last, to keep the timings at the top.

-------------

PR: https://git.openjdk.java.net/jdk/pull/6763