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

Stefan Johansson sjohanss at openjdk.java.net
Wed Aug 25 12:46:37 UTC 2021


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.

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

Commit messages:
 - Fix test
 - G1FullGCMark with id and cpu-time
 - 8272651: G1 heap region info print order changed by JDK-8269914

Changes: https://git.openjdk.java.net/jdk/pull/5252/files
 Webrev: https://webrevs.openjdk.java.net/?repo=jdk&pr=5252&range=00
  Issue: https://bugs.openjdk.java.net/browse/JDK-8272651
  Stats: 36 lines in 5 files changed: 18 ins; 11 del; 7 mod
  Patch: https://git.openjdk.java.net/jdk/pull/5252.diff
  Fetch: git fetch https://git.openjdk.java.net/jdk pull/5252/head:pull/5252

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



More information about the hotspot-gc-dev mailing list