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

[Thomas Schatzl]

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.

Changes requested by tschatzl (Reviewer).

src/hotspot/share/gc/g1/g1CollectedHeap.cpp line 3045:

> 3043:   bool concurrent_operation_is_full_mark = false;
> 3044: 
> 3045:   // Verification may use the gang workers, so they must be set up before.

I see (setup of) the amount of gang workers as input to the garbage collection algorithm, i.e. not the algorithm determines the number of threads, but is determined beforehand before doing the collection.

E.g. see G1YoungCollector::collect() in https://github.com/tschatzl/jdk/commit/7fcfdfad9e01e0ae263dc61c1797281a4d5b192f#diff-da5609c228269aa265489241cdb50e89299e79b8691e0e534abf2823d7de2615

src/hotspot/share/gc/g1/g1CollectedHeap.cpp line 3057:

> 3055:     // Create the heap printer before internal pause timing to have
> 3056:     // heap information printed as last part of detailed GC log.
> 3057:     G1HeapPrinterMark hpm(this);

This will make this code (and printing) disappear from the "Other" time in pause timing.

Some of that printing (and data gathering) might be expensive.

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

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