8291753: Add JFR event for GC CPU Time #9760

sangheon · 2022-08-04T23:58:02Z

Hi all,

Could I have reviews to add new JFR event for GC CPU time?
Currently only log message is available for CPU time (user, system, real).
As there is already GCTraceCPUTime class which is used for a log message, I added GCTracer to deliver the event.
The log message of CPU time is printed after GC is completed and tried to keep same.

For G1, manually checked there is not difference.

For test, I had to add an exception as GCCpuTime will be generated after GC end.

Testing: tier 1 ~ 3

Thanks,
Sangheon

Progress

Change must be properly reviewed (1 review required, with at least 1 Reviewer)
Change must not contain extraneous whitespace
Commit message must refer to an issue

Issue

JDK-8291753: Add JFR event for GC CPU Time

Reviewers

Thomas Schatzl (@tschatzl - Reviewer)
Albert Mingkun Yang (@albertnetymk - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760
$ git checkout pull/9760

Update a local copy of the PR:
$ git checkout pull/9760
$ git pull https://git.openjdk.org/jdk pull/9760/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 9760

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

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/9760.diff

bridgekeeper · 2022-08-04T23:58:47Z

👋 Welcome back sangheki! 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 · 2022-08-05T00:02:49Z

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

hotspot

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.

sangheon · 2022-08-10T22:37:31Z

/label add hotspot-gc, hotspot-jfr
/label remove hotspot

openjdk · 2022-08-10T22:40:00Z

@sangheon
The hotspot-gc label was successfully added.

The hotspot-jfr label was successfully added.

sangheon · 2022-08-10T22:40:24Z

/label remove hotspot

openjdk · 2022-08-10T22:41:33Z

@sangheon
The hotspot label was successfully removed.

openjdk · 2022-08-10T22:43:07Z

@sangheon The hotspot label was not set.

mlbridge · 2022-08-11T16:41:58Z

Webrevs

egahlin · 2022-08-11T19:31:25Z

Does this event provide CPU usage for ZGC and Shenandoah?

mlbridge · 2022-08-12T10:07:01Z

Mailing list message from Sangheon Kim on hotspot-gc-dev:

On 8/11/22 12:34 PM, Erik Gahlin wrote:

On Thu, 4 Aug 2022 23:58:02 GMT, Sangheon Kim <sangheki at openjdk.org> wrote:

Hi all,

Could I have reviews to add new JFR event for GC CPU time?
Currently only log message is available for CPU time (user, system, real).
As there is already GCTraceCPUTime class which is used for a log message, I added GCTracer to deliver the event.
The log message of CPU time is printed after GC is completed and tried to keep same.

For G1, manually checked there is not difference.

For test, I had to add an exception as GCCpuTime will be generated after GC end.

Testing: tier 1 ~ 3

Thanks,
Sangheon
Does this event doesn't provide CPU usage for ZGC and Shenandoah?

No.
This event is provided via GCTraceCPUTime class with GCTracer. And both
ZGC and Shenanadoah are not using it.
If you are suggesting to support all GCs, it is out of scope. It may be
address as a separate enhancement.

Thanks,
Sangheon

egahlin · 2022-08-12T12:18:10Z

No. This event is provided via GCTraceCPUTime class with GCTracer. And both ZGC and Shenanadoah are not using it. If you are suggesting to support all GCs, it is out of scope. It may be address as a separate enhancement.

Thanks for the information.

Do you see any issues adding the event for those GCs (as a separate enhancement)? There are no limitation in the information the OS can provide (per thread) or how the GCs are implemented. The reason I am asking is because we want the design of the event to be future proof, so we don't end up with multiple GC CPU events. Users are likely to complain if the event is missing for some GCs. It seems like a very useful event, so I think the demand will be high for other GCs as well. Could you write in the event description which GCs that are supported?

An alternative would be to write the CPU usage as a percentage, similar to the CPULoad and ThreadCPU event. It would be a periodic event emitted every second and tools could display a graph of where the system is spending time. It could perhaps be complemented with a Compiler CPU event, as a separate enhancement.

src/hotspot/share/gc/shared/gcTraceTime.cpp

test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java

sangheon · 2022-08-15T16:52:58Z

Do you see any issues adding the event for those GCs (as a separate enhancement)? There are no limitation in the information the OS can provide (per thread) or how the GCs are implemented. The reason I am asking is because we want the design of the event to be future proof, so we don't end up with multiple GC CPU events. Users are likely to complain if the event is missing for some GCs. It seems like a very useful event, so I think the demand will be high for other GCs as well. Could you write in the event description which GCs that are supported?

I don't see any issues for other GCs. The only reason is that other GCs don't use the class.
And I agree with you, so I filed "JDK-8292373 Add JFR event for GC CPU Time (other GCs)" for future enhancement. Updated the description as well.

src/hotspot/share/jfr/metadata/metadata.xml

tschatzl

Good.

openjdk · 2022-08-22T09:35:15Z

@sangheon 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:

8291753: Add JFR event for GC CPU Time

Reviewed-by: tschatzl, 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 113 new commits pushed to the master branch:

30d4145: 8293230: x86_64: Move AES and GHASH stub definitions into separate source files
4c5501c: 8293548: ProblemList sun/management/jmxremote/bootstrap/RmiBootstrapTest.java#id1 on linux-x64
46e6e41: 8293051: Further refactor javac after removal of -source/-target/--release 7
c0ee30a: 8293348: A false cyclic inheritance error reported
85ec1f8: 8293492: ShenandoahControlThread missing from hs-err log and thread dump
6bd2794: 8293304: Replace some usages of INTPTR_FORMAT with PTR_FORMAT
98da03a: 8293432: Use diamond operator in java.management
ffc249a: 8289613: Drop use of Thread.stop in jshell
8d3399b: 8292758: put support for UNSIGNED5 format into its own header file
6677227: 8293497: Build failure due to MaxVectorSize was not declared when C2 is disabled after JDK-8293254
... and 103 more: https://git.openjdk.org/jdk/compare/0d51f63a2e95976636f8ec74a69096791304724e...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

The rest look fine, but the inconsistency should be resolved IMO.

albertnetymk · 2022-09-07T16:11:50Z

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

-public:
-  G1FullGCMark() : _gc_id(), _cpu_time() { }
-};
-


I don't recall the exact reason for this, but I have a faint memory on having some discussion with its author. It's from https://bugs.openjdk.org/browse/JDK-8272651

Before this PR:

[32.328s][info ][gc ] GC(47) Pause Young (Normal) (G1 Evacuation Pause) 1162M->1032M(3072M) 323.751ms [32.328s][info ][gc,cpu ] GC(47) User=3.22s Sys=0.00s Real=0.33s ... [35.221s][info ][gc ] GC(48) Pause Full (System.gc()) 1134M->660M(3072M) 2650.824ms [35.221s][info ][gc,cpu ] GC(48) User=23.97s Sys=1.49s Real=2.65s

After this PR:

[35.221s][info ][gc ] GC(48) Pause Full (System.gc()) 1134M->660M(3072M) 2650.824ms [35.221s][info ][gc,cpu ] GC(48) User=23.97s Sys=1.49s Real=2.65s ... [41.337s][info ][gc,cpu ] GC(49) User=27.86s Sys=1.58s Real=3.28s [41.337s][info ][gc ] GC(49) Pause Full (System.gc()) 1094M->660M(3072M) 3283.658ms

Note that for Full-GC, the user/sys/real time is before GC-end, which is inconsistent with Young-GC.

Yes, I agree with you and fixed.
I was aware of this issue(and JDK-8272651) at the beginning so mentioned at the RFR above, but...

…pu-time

openjdk · 2022-09-08T00:00:51Z

⚠️ @sangheon This pull request contains merges that bring in commits not present in the target repository. Since this is not a "merge style" pull request, these changes will be squashed when this pull request in integrated. If this is your intention, then please ignore this message. If you want to preserve the commit structure, you must change the title of this pull request to Merge <project>:<branch> where <project> is the name of another project in the OpenJDK organization (for example Merge jdk:master).

sangheon · 2022-09-08T18:18:31Z

Many thanks for the review, Thomas and Albert.

/integrate

openjdk · 2022-09-08T18:20:16Z

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

30d4145: 8293230: x86_64: Move AES and GHASH stub definitions into separate source files
4c5501c: 8293548: ProblemList sun/management/jmxremote/bootstrap/RmiBootstrapTest.java#id1 on linux-x64
46e6e41: 8293051: Further refactor javac after removal of -source/-target/--release 7
c0ee30a: 8293348: A false cyclic inheritance error reported
85ec1f8: 8293492: ShenandoahControlThread missing from hs-err log and thread dump
6bd2794: 8293304: Replace some usages of INTPTR_FORMAT with PTR_FORMAT
98da03a: 8293432: Use diamond operator in java.management
ffc249a: 8289613: Drop use of Thread.stop in jshell
8d3399b: 8292758: put support for UNSIGNED5 format into its own header file
6677227: 8293497: Build failure due to MaxVectorSize was not declared when C2 is disabled after JDK-8293254
... and 103 more: https://git.openjdk.org/jdk/compare/0d51f63a2e95976636f8ec74a69096791304724e...master

Your commit was automatically rebased without conflicts.

openjdk · 2022-09-08T18:20:31Z

@sangheon Pushed as commit 14eb5ad.

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

Add JFR event of GCCpuTime.

07098a0

openjdk bot added the hotspot hotspot-dev@openjdk.org label Aug 5, 2022

Split G1FullGCMark

981c447

openjdk bot added hotspot-gc hotspot-gc-dev@openjdk.org hotspot-jfr hotspot-jfr-dev@openjdk.org labels Aug 10, 2022

openjdk bot removed the hotspot hotspot-dev@openjdk.org label Aug 10, 2022

sangheon marked this pull request as ready for review August 11, 2022 16:35

openjdk bot added the rfr Pull request is ready for review label Aug 11, 2022

tschatzl suggested changes Aug 12, 2022

View reviewed changes

Add Serial GC support and split test.

2075927

egahlin reviewed Aug 16, 2022

View reviewed changes

src/hotspot/share/jfr/metadata/metadata.xml Outdated Show resolved Hide resolved

src/hotspot/share/jfr/metadata/metadata.xml Outdated Show resolved Hide resolved

Reflect egahlin's comment

f432977

tschatzl approved these changes Aug 22, 2022

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Aug 22, 2022

sangheon requested a review from egahlin August 30, 2022 14:03

Merge branch 'master' into 8291753-cpu-time

229df2f

albertnetymk suggested changes Sep 7, 2022

View reviewed changes

sangheon added 2 commits September 7, 2022 16:55

Comment from albertnetymk

df22556

Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-c…

d347ece

…pu-time

albertnetymk approved these changes Sep 8, 2022

View reviewed changes

tschatzl approved these changes Sep 8, 2022

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Sep 8, 2022

openjdk bot closed this Sep 8, 2022

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Sep 8, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8291753: Add JFR event for GC CPU Time #9760

8291753: Add JFR event for GC CPU Time #9760

sangheon commented Aug 4, 2022 •

edited by openjdk bot

Loading

bridgekeeper bot commented Aug 4, 2022

openjdk bot commented Aug 5, 2022

sangheon commented Aug 10, 2022 •

edited

Loading

openjdk bot commented Aug 10, 2022

sangheon commented Aug 10, 2022

openjdk bot commented Aug 10, 2022

openjdk bot commented Aug 10, 2022

mlbridge bot commented Aug 11, 2022 •

edited

Loading

egahlin commented Aug 11, 2022 •

edited

Loading

mlbridge bot commented Aug 12, 2022

egahlin commented Aug 12, 2022

sangheon commented Aug 15, 2022

tschatzl left a comment

openjdk bot commented Aug 22, 2022 •

edited

Loading

albertnetymk left a comment

albertnetymk Sep 7, 2022

sangheon Sep 8, 2022

openjdk bot commented Sep 8, 2022

sangheon commented Sep 8, 2022

openjdk bot commented Sep 8, 2022

openjdk bot commented Sep 8, 2022

8291753: Add JFR event for GC CPU Time #9760

8291753: Add JFR event for GC CPU Time #9760

Conversation

sangheon commented Aug 4, 2022 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

bridgekeeper bot commented Aug 4, 2022

openjdk bot commented Aug 5, 2022

sangheon commented Aug 10, 2022 • edited Loading

openjdk bot commented Aug 10, 2022

sangheon commented Aug 10, 2022

openjdk bot commented Aug 10, 2022

openjdk bot commented Aug 10, 2022

mlbridge bot commented Aug 11, 2022 • edited Loading

Webrevs

egahlin commented Aug 11, 2022 • edited Loading

mlbridge bot commented Aug 12, 2022

egahlin commented Aug 12, 2022

sangheon commented Aug 15, 2022

tschatzl left a comment

Choose a reason for hiding this comment

openjdk bot commented Aug 22, 2022 • edited Loading

albertnetymk left a comment

Choose a reason for hiding this comment

albertnetymk Sep 7, 2022

Choose a reason for hiding this comment

sangheon Sep 8, 2022

Choose a reason for hiding this comment

openjdk bot commented Sep 8, 2022

sangheon commented Sep 8, 2022

openjdk bot commented Sep 8, 2022

openjdk bot commented Sep 8, 2022

sangheon commented Aug 4, 2022 •

edited by openjdk bot

Loading

sangheon commented Aug 10, 2022 •

edited

Loading

mlbridge bot commented Aug 11, 2022 •

edited

Loading

egahlin commented Aug 11, 2022 •

edited

Loading

openjdk bot commented Aug 22, 2022 •

edited

Loading