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

[Ivan Walulya]

On Thu, 26 Aug 2021 10:37:56 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.
>
> Stefan Johansson has updated the pull request incrementally with one additional commit since the last revision:
> 
>   HeapMark needs to be below JFRMark to make sure all GC events are withing start and end event.

Marked as reviewed by iwalulya (Committer).

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

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