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

kstefanj · 2021-08-25T12:40:16Z

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.

Progress

Change must not contain extraneous whitespace
Commit message must refer to an issue
Change must be properly reviewed

Issue

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

Reviewers

Thomas Schatzl (@tschatzl - Reviewer) ⚠️ Review applies to 56078ab
Ivan Walulya (@walulyai - Committer) ⚠️ Review applies to 56078ab
Albert Mingkun Yang (@albertnetymk - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/5252/head:pull/5252
$ git checkout pull/5252

Update a local copy of the PR:
$ git checkout pull/5252
$ git pull https://git.openjdk.java.net/jdk pull/5252/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 5252

View PR using the GUI difftool:
$ git pr show -t 5252

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/5252.diff

bridgekeeper · 2021-08-25T12:41:27Z

👋 Welcome back sjohanss! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2021-08-25T12:43:13Z

@kstefanj The following label will be automatically applied to this pull request:

hotspot-gc

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

mlbridge · 2021-08-25T12:46:36Z

Webrevs

tschatzl · 2021-08-25T12:57:06Z

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -3055,6 +3052,9 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
    // determining collector state.
    G1YoungGCTraceTime tm(gc_cause());

+    // Create the heap printer before internal pause timing to have
+    // heap information printed as last part of detailed GC log.
+    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.

Me and Thomas discussed this and we agreed on this being ok. Even if some part of the printing could take a little time it is not important to record it as "other time".

tschatzl · 2021-08-25T13:00:27Z

src/hotspot/share/gc/g1/g1CollectedHeap.cpp

@@ -3042,10 +3043,6 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
  bool should_start_concurrent_mark_operation = collector_state()->in_concurrent_start_gc();
  bool concurrent_operation_is_full_mark = false;

-  // 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 tschatzl@7fcfdfa#diff-da5609c228269aa265489241cdb50e89299e79b8691e0e534abf2823d7de2615

We discussed this as well and compared it with how the G1FullCollectorhandles this and whit this in mind the current proposal is ok. We might want to do more refactoring around this later on, but right now we can see calculating the number of workers as part of the young collector and not only input.

…hing start and end event.

kstefanj · 2021-08-26T10:35:31Z

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

tschatzl

As discussed with Stefan - lgtm.

openjdk · 2021-08-26T17:09:16Z

@kstefanj This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

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

Reviewed-by: tschatzl, iwalulya, ayang

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 97 new commits pushed to the master branch:

fbffa54: 8270438: "Cores to use" output in configure is misleading
5185dbd: 8273098: Unnecessary Vector usage in java.naming
276b07b: 8271490: [ppc] [s390]: Crash in JavaThread::pd_get_top_frame_for_profiling
bb7aa1c: 8272161: Make evacuation failure data structures local to collection
9ede41b: 8229031: Exporting CLASSPATH from shell can result in build failures
16e8305: 8273059: Redundant Math.min call in Http2ClientImpl#getConnectionWindowSize
f55d5ab: 8272838: Move CriticalJNI tests out of tier1
a9188f2: 8268894: forged ASTs can provoke an AIOOBE at com.sun.tools.javac.jvm.ClassWriter::writePosition
1fb798d: 8272915: (doc) package-info typo in extLink
5116784: 8273091: Doc of [Strict]Math.floorDiv(long,int) erroneously documents int in @return tag
... and 87 more: https://git.openjdk.java.net/jdk/compare/79a06df8113ba1da55db5c38fe34608c3507c223...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

albertnetymk · 2021-08-30T08:54:09Z

src/hotspot/share/gc/g1/g1FullCollector.hpp

@@ -55,6 +57,15 @@ class G1FullGCSubjectToDiscoveryClosure: public BoolObjectClosure {
  }
 };

+// Full GC Mark that holds GC id and CPU time trace. Needs to be separate
+// from the G1FullCollector and G1FullGCScope to get consistent logging.


I think saying just "consistent logging" here is too terse; some elaboration (background info and/or with/without this separation comparison) could make the reasoning more explicit.

Suggested change

// from the G1FullCollector and G1FullGCScope to get consistent logging.

// from the G1FullCollector and G1FullGCScope to allow the Full GC logging

// to have the same structure as the Young GC logging.

Would this be enough? I don't want to add to many details as it might easily get stale. But I wanted the comment to let the reader know why this isn't folded in to the other structures.

kstefanj · 2021-08-30T14:35:49Z

Thanks @walulyai, @tschatzl and @albertnetymk for reviewing.

/integrate

openjdk · 2021-08-30T14:37:12Z

Going to push as commit f11e099.
Since your change was applied there have been 97 commits pushed to the master branch:

fbffa54: 8270438: "Cores to use" output in configure is misleading
5185dbd: 8273098: Unnecessary Vector usage in java.naming
276b07b: 8271490: [ppc] [s390]: Crash in JavaThread::pd_get_top_frame_for_profiling
bb7aa1c: 8272161: Make evacuation failure data structures local to collection
9ede41b: 8229031: Exporting CLASSPATH from shell can result in build failures
16e8305: 8273059: Redundant Math.min call in Http2ClientImpl#getConnectionWindowSize
f55d5ab: 8272838: Move CriticalJNI tests out of tier1
a9188f2: 8268894: forged ASTs can provoke an AIOOBE at com.sun.tools.javac.jvm.ClassWriter::writePosition
1fb798d: 8272915: (doc) package-info typo in extLink
5116784: 8273091: Doc of [Strict]Math.floorDiv(long,int) erroneously documents int in @return tag
... and 87 more: https://git.openjdk.java.net/jdk/compare/79a06df8113ba1da55db5c38fe34608c3507c223...master

Your commit was automatically rebased without conflicts.

openjdk · 2021-08-30T14:37:23Z

@kstefanj Pushed as commit f11e099.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

kstefanj added 3 commits August 25, 2021 12:54

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

c200ed5

G1FullGCMark with id and cpu-time

04aaeb5

Fix test

4998d38

openjdk bot added the rfr Pull request is ready for review label Aug 25, 2021

openjdk bot added the hotspot-gc hotspot-gc-dev@openjdk.org label Aug 25, 2021

tschatzl suggested changes Aug 25, 2021

View reviewed changes

HeapMark needs to be below JFRMark to make sure all GC events are wit…

56078ab

…hing start and end event.

tschatzl approved these changes Aug 26, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Aug 26, 2021

walulyai approved these changes Aug 27, 2021

View reviewed changes

albertnetymk reviewed Aug 30, 2021

View reviewed changes

Albert review.

360a1f8

albertnetymk approved these changes Aug 30, 2021

View reviewed changes

openjdk bot closed this Aug 30, 2021

openjdk bot added integrated Pull request has been integrated and removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Aug 30, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

kstefanj commented Aug 25, 2021 •

edited by openjdk bot

Loading

bridgekeeper bot commented Aug 25, 2021

openjdk bot commented Aug 25, 2021

mlbridge bot commented Aug 25, 2021 •

edited

Loading

tschatzl Aug 25, 2021

kstefanj Aug 26, 2021

tschatzl Aug 25, 2021

kstefanj Aug 26, 2021

kstefanj commented Aug 26, 2021

tschatzl left a comment

openjdk bot commented Aug 26, 2021 •

edited

Loading

albertnetymk Aug 30, 2021

kstefanj Aug 30, 2021

kstefanj commented Aug 30, 2021

openjdk bot commented Aug 30, 2021

openjdk bot commented Aug 30, 2021

	// from the G1FullCollector and G1FullGCScope to get consistent logging.
	// from the G1FullCollector and G1FullGCScope to allow the Full GC logging
	// to have the same structure as the Young GC logging.

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

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

Conversation

kstefanj commented Aug 25, 2021 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Aug 25, 2021

openjdk bot commented Aug 25, 2021

mlbridge bot commented Aug 25, 2021 • edited Loading

Webrevs

tschatzl Aug 25, 2021

Choose a reason for hiding this comment

kstefanj Aug 26, 2021

Choose a reason for hiding this comment

tschatzl Aug 25, 2021

Choose a reason for hiding this comment

kstefanj Aug 26, 2021

Choose a reason for hiding this comment

kstefanj commented Aug 26, 2021

tschatzl left a comment

Choose a reason for hiding this comment

openjdk bot commented Aug 26, 2021 • edited Loading

albertnetymk Aug 30, 2021

Choose a reason for hiding this comment

kstefanj Aug 30, 2021

Choose a reason for hiding this comment

kstefanj commented Aug 30, 2021

openjdk bot commented Aug 30, 2021

openjdk bot commented Aug 30, 2021

kstefanj commented Aug 25, 2021 •

edited by openjdk bot

Loading

mlbridge bot commented Aug 25, 2021 •

edited

Loading

openjdk bot commented Aug 26, 2021 •

edited

Loading