Integrated: 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.

This pull request has now been integrated.

Changeset: f11e099a
Author:    Stefan Johansson <sjohanss at openjdk.org>
URL:       https://git.openjdk.java.net/jdk/commit/f11e099a149adfecc474ba37276ec8672067d090
Stats:     41 lines in 5 files changed: 21 ins; 13 del; 7 mod

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

Reviewed-by: tschatzl, iwalulya, ayang

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

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