RFR: 8272651: G1 heap region info print order changed by JDK-8269914

[Stefan Johansson]

On Wed, 25 Aug 2021 12:40:16 GMT, Stefan Johansson <sjohanss at openjdk.org> wrote:

> Please review this small change to restore and coordinate the order of the G1 logs. 
> 
> **Summary**
> Recent changes have slightly re-ordered parts of the G1 logs printed with `-Xlog:gc*` for young and full collections. This change will mostly restore the order but also address some differences we had in the past. The biggest part of this change is making sure the region transitions are printed at the "correct" place. For young collections they are moved to just after the phases and for full collections they are moved to be before the end of the pause log.
> 
> Example logs:
> 
> [0,046s][info][gc,start    ] GC(0) Pause Young (Concurrent Start) (System.gc())
> [0,048s][info][gc,task     ] GC(0) Using 24 workers of 28 for evacuation
> [0,049s][info][gc,phases   ] GC(0)   Pre Evacuate Collection Set: 0,1ms
> [0,049s][info][gc,phases   ] GC(0)   Merge Heap Roots: 0,1ms
> [0,049s][info][gc,phases   ] GC(0)   Evacuate Collection Set: 0,4ms
> [0,049s][info][gc,phases   ] GC(0)   Post Evacuate Collection Set: 0,3ms
> [0,049s][info][gc,phases   ] GC(0)   Other: 2,5ms
> [0,049s][info][gc,heap     ] GC(0) Eden regions: 1->0(5)
> [0,049s][info][gc,heap     ] GC(0) Survivor regions: 0->1(1)
> [0,049s][info][gc,heap     ] GC(0) Old regions: 0->0
> [0,049s][info][gc,heap     ] GC(0) Archive regions: 2->2
> [0,049s][info][gc,heap     ] GC(0) Humongous regions: 0->0
> [0,049s][info][gc,metaspace] GC(0) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
> [0,049s][info][gc          ] GC(0) Pause Young (Concurrent Start) (System.gc()) 9M->8M(1024M) 3,563ms
> [0,049s][info][gc,cpu      ] GC(0) User=0,00s Sys=0,00s Real=0,00s
> 
> 
> [0,044s][info][gc,start    ] GC(0) Pause Full (System.gc())
> [0,044s][info][gc,task     ] GC(0) Using 3 workers of 28 for full compaction
> [0,044s][info][gc,phases,start] GC(0) Phase 1: Mark live objects
> [0,044s][info][gc,phases      ] GC(0) Phase 1: Mark live objects 0,607ms
> [0,044s][info][gc,phases,start] GC(0) Phase 2: Prepare for compaction
> [0,045s][info][gc,phases      ] GC(0) Phase 2: Prepare for compaction 0,772ms
> [0,045s][info][gc,phases,start] GC(0) Phase 3: Adjust pointers
> [0,046s][info][gc,phases      ] GC(0) Phase 3: Adjust pointers 0,361ms
> [0,046s][info][gc,phases,start] GC(0) Phase 4: Compact heap
> [0,046s][info][gc,phases      ] GC(0) Phase 4: Compact heap 0,142ms
> [0,050s][info][gc,heap        ] GC(0) Eden regions: 1->0(2)
> [0,050s][info][gc,heap        ] GC(0) Survivor regions: 0->0(0)
> [0,050s][info][gc,heap        ] GC(0) Old regions: 0->1
> [0,050s][info][gc,heap        ] GC(0) Archive regions: 2->2
> [0,050s][info][gc,heap        ] GC(0) Humongous regions: 0->0
> [0,050s][info][gc,metaspace   ] GC(0) Metaspace: 73K(320K)->73K(320K) NonClass: 70K(192K)->70K(192K) Class: 3K(128K)->3K(128K)
> [0,050s][info][gc             ] GC(0) Pause Full (System.gc()) 9M->8M(80M) 6,729ms
> [0,050s][info][gc,cpu         ] GC(0) User=0,01s Sys=0,02s Real=0,01s
> 
> 
> **Testing**
> Locally run g1 tests and also some additional testing through mach5.

Pushed a small change to make sure all JFR events are sent in the correct order.

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

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