RFR: 8291753: Add JFR event for GC CPU Time
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 ------------- Commit messages: - Split G1FullGCMark - Add JFR event of GCCpuTime. Changes: https://git.openjdk.org/jdk/pull/9760/files Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=00 Issue: https://bugs.openjdk.org/browse/JDK-8291753 Stats: 181 lines in 20 files changed: 136 ins; 11 del; 34 mod Patch: https://git.openjdk.org/jdk/pull/9760.diff Fetch: git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760 PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 4 Aug 2022 23:58:02 GMT, Sangheon Kim <sangheki@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? ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 4 Aug 2022 23:58:02 GMT, Sangheon Kim <sangheki@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
Changes requested by tschatzl (Reviewer). src/hotspot/share/gc/shared/gcTraceTime.cpp line 93:
91: } 92: 93: GCTraceCPUTime::GCTraceCPUTime() { GCTraceCPUTime(nullptr); }
Suggestion: GCTraceCPUTime::GCTraceCPUTime() : GCTraceCPUTime(nullptr) { } The way the other constructor is called is wrong afaik. However if serial gc support were added, this constructor could be deleted. test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 36:
34: * @key jfr 35: * @requires vm.hasJFR 36: * @requires vm.gc == "G1" | vm.gc == null | vm.gc == "Parallel"
Please also add support for serial gc, it provides tracer classes. Also I would consider blacklisting non-supporting collectors instead, i.e. ZGC, Shenandoah and Epsilon. That way the missing functionality is eventually found more easily, i.e. by searching for `!= <gc>` instead of finding all tests that exclude that collector. Also since the test is only run with G1, it would be sufficient to just `@requires G1/null`. test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 38:
36: * @requires vm.gc == "G1" | vm.gc == null | vm.gc == "Parallel" 37: * @library /test/lib /test/jdk 38: * @run main/othervm -Xmx32m -XX:+UseG1GC jdk.jfr.event.gc.detailed.TestGCCpuTimeEvent
I think you want separate tests like the `gc/Systemgc.java` test here. This will always run the test with G1 even when initially invoked with the intent to execute the serial gc test. test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 56:
54: for (int i = 0; i < 100; i++) { 55: bytes = new byte[1024 * 1024]; 56: }
Please use Whitebox/WhiteBox.youngGC() to guarantee invocation of a GC. This test currently hinges on the compiler/interpreter not being too clever. ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Fri, 12 Aug 2022 12:06:10 GMT, Thomas Schatzl <tschatzl@openjdk.org> wrote:
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Add Serial GC support and split test.
src/hotspot/share/gc/shared/gcTraceTime.cpp line 93:
91: } 92: 93: GCTraceCPUTime::GCTraceCPUTime() { GCTraceCPUTime(nullptr); }
Suggestion:
GCTraceCPUTime::GCTraceCPUTime() : GCTraceCPUTime(nullptr) { }
The way the other constructor is called is wrong afaik. However if serial gc support were added, this constructor could be deleted.
Done.
test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 36:
34: * @key jfr 35: * @requires vm.hasJFR 36: * @requires vm.gc == "G1" | vm.gc == null | vm.gc == "Parallel"
Please also add support for serial gc, it provides tracer classes. Also I would consider blacklisting non-supporting collectors instead, i.e. ZGC, Shenandoah and Epsilon. That way the missing functionality is eventually found more easily, i.e. by searching for `!= <gc>` instead of finding all tests that exclude that collector.
Also since the test is only run with G1, it would be sufficient to just `@requires G1/null`.
Added Serial GC support. Separated to serial, parallel and G1 tests.
test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 38:
36: * @requires vm.gc == "G1" | vm.gc == null | vm.gc == "Parallel" 37: * @library /test/lib /test/jdk 38: * @run main/othervm -Xmx32m -XX:+UseG1GC jdk.jfr.event.gc.detailed.TestGCCpuTimeEvent
I think you want separate tests like the `gc/Systemgc.java` test here. This will always run the test with G1 even when initially invoked with the intent to execute the serial gc test.
Done.
test/jdk/jdk/jfr/event/gc/detailed/TestGCCpuTimeEvent.java line 56:
54: for (int i = 0; i < 100; i++) { 55: bytes = new byte[1024 * 1024]; 56: }
Please use Whitebox/WhiteBox.youngGC() to guarantee invocation of a GC. This test currently hinges on the compiler/interpreter not being too clever.
Done. ------------- PR: https://git.openjdk.org/jdk/pull/9760
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
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Add Serial GC support and split test. ------------- Changes: - all: https://git.openjdk.org/jdk/pull/9760/files - new: https://git.openjdk.org/jdk/pull/9760/files/981c4479..2075927c Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=01 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=00-01 Stats: 57 lines in 6 files changed: 34 ins; 8 del; 15 mod Patch: https://git.openjdk.org/jdk/pull/9760.diff Fetch: git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760 PR: https://git.openjdk.org/jdk/pull/9760
On Mon, 15 Aug 2022 01:42:14 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Add Serial GC support and split test.
src/hotspot/share/jfr/metadata/metadata.xml line 498:
496: </Event> 497: 498: <Event name="GCCpuTime" category="Java Virtual Machine, GC, Detailed" label="GC CPU Time" description="GC CPU Time information in seconds"
Could you change the name to "GCCPUTime". Other events uses capital letters in abbreviations. src/hotspot/share/jfr/metadata/metadata.xml line 501:
499: thread="true" stackTrace="false" startTime="false"> 500: <Field type="uint" name="gcId" label="GC Identifier" relation="GcId" description="Identifier signifying GC during which the object was promoted" /> 501: <Field type="double" name="userTime" label="User Time" />
Could you change the field type to "ulong", convert the value to nanoseconds and set contentType="nanos"? This will allow the output to be properly formatted, i.e. 23 ms, in the jfr-tool. You can also remove the mentioning of "in seconds" in the event description. The content type will allow tools to format the unit. I am also missing supported GCs in the event description. The description of gcId seems strange, which "object"? I think you can skip the description. The event has thread="true". Is data emitted per thread? If so, it may makes sense to aggregate for all threads. I think most user don't care about which thread the CPU was consumed. Otherwise, set thread="false". (If you want per thread for JVM engineers, I think the event name and label should reflect it is per thread and perhaps not enable it in the "detailed" configuration, not "normal", in .jfc files) ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Tue, 16 Aug 2022 10:15:03 GMT, Erik Gahlin <egahlin@openjdk.org> wrote:
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Add Serial GC support and split test.
src/hotspot/share/jfr/metadata/metadata.xml line 498:
496: </Event> 497: 498: <Event name="GCCpuTime" category="Java Virtual Machine, GC, Detailed" label="GC CPU Time" description="GC CPU Time information in seconds"
Could you change the name to "GCCPUTime". Other events uses capital letters in abbreviations.
Renamed to "GCCPUTime".
src/hotspot/share/jfr/metadata/metadata.xml line 501:
499: thread="true" stackTrace="false" startTime="false"> 500: <Field type="uint" name="gcId" label="GC Identifier" relation="GcId" description="Identifier signifying GC during which the object was promoted" /> 501: <Field type="double" name="userTime" label="User Time" />
Could you change the field type to "ulong", convert the value to nanoseconds and set contentType="nanos"? This will allow the output to be properly formatted, i.e. 23 ms, in the jfr-tool. You can also remove the mentioning of "in seconds" in the event description. The content type will allow tools to format the unit. I am also missing supported GCs in the event description.
The description of gcId seems strange, which "object"? I think you can skip the description.
The event has thread="true". Is data emitted per thread? If so, it may makes sense to aggregate for all threads. I think most user don't care about which thread the CPU was consumed. Otherwise, set thread="false".
(If you want per thread for JVM engineers, I think the event name and label should reflect it is per thread and perhaps not enable it in the "detailed" configuration, not "normal", in .jfc files)
1. Changed as you suggested. I had same idea but the original data is in seconds. And I wanted to use same unit as log message and avoid conversion. But as you said, the tool gets the benefit. 1-2. Added supported GCs in the description. 2. Removed description field of gcid. 3. Removed 'thread=true'. ------------- PR: https://git.openjdk.org/jdk/pull/9760
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
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Reflect egahlin's comment ------------- Changes: - all: https://git.openjdk.org/jdk/pull/9760/files - new: https://git.openjdk.org/jdk/pull/9760/files/2075927c..f4329777 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=02 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=01-02 Stats: 28 lines in 7 files changed: 0 ins; 0 del; 28 mod Patch: https://git.openjdk.org/jdk/pull/9760.diff Fetch: git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760 PR: https://git.openjdk.org/jdk/pull/9760
On Wed, 17 Aug 2022 01:08:52 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Reflect egahlin's comment
Good. ------------- Marked as reviewed by tschatzl (Reviewer). PR: https://git.openjdk.org/jdk/pull/9760
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
Sangheon Kim has updated the pull request with a new target base due to a merge or a rebase. The pull request now contains five commits: - Merge branch 'master' into 8291753-cpu-time - Reflect egahlin's comment - Add Serial GC support and split test. - Split G1FullGCMark - Add JFR event of GCCpuTime. ------------- Changes: https://git.openjdk.org/jdk/pull/9760/files Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=03 Stats: 225 lines in 23 files changed: 163 ins; 12 del; 50 mod Patch: https://git.openjdk.org/jdk/pull/9760.diff Fetch: git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760 PR: https://git.openjdk.org/jdk/pull/9760
On Wed, 31 Aug 2022 14:53:04 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request with a new target base due to a merge or a rebase. The pull request now contains five commits:
- Merge branch 'master' into 8291753-cpu-time - Reflect egahlin's comment - Add Serial GC support and split test. - Split G1FullGCMark - Add JFR event of GCCpuTime.
The rest look fine, but the inconsistency should be resolved IMO. src/hotspot/share/gc/g1/g1FullCollector.hpp line 70:
68: G1FullGCMark() : _gc_id(), _cpu_time() { } 69: }; 70:
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. ------------- Changes requested by ayang (Reviewer). PR: https://git.openjdk.org/jdk/pull/9760
On Wed, 7 Sep 2022 16:11:50 GMT, Albert Mingkun Yang <ayang@openjdk.org> wrote:
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision:
- Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-cpu-time - Comment from albertnetymk
src/hotspot/share/gc/g1/g1FullCollector.hpp line 70:
68: G1FullGCMark() : _gc_id(), _cpu_time() { } 69: }; 70:
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... ------------- PR: https://git.openjdk.org/jdk/pull/9760
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
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision: - Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-cpu-time - Comment from albertnetymk ------------- Changes: - all: https://git.openjdk.org/jdk/pull/9760/files - new: https://git.openjdk.org/jdk/pull/9760/files/229df2f2..d347ece1 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=04 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=9760&range=03-04 Stats: 23 lines in 3 files changed: 14 ins; 4 del; 5 mod Patch: https://git.openjdk.org/jdk/pull/9760.diff Fetch: git fetch https://git.openjdk.org/jdk pull/9760/head:pull/9760 PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 8 Sep 2022 00:04:11 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision:
- Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-cpu-time - Comment from albertnetymk
Marked as reviewed by ayang (Reviewer). ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 8 Sep 2022 00:04:11 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision:
- Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-cpu-time - Comment from albertnetymk
Marked as reviewed by tschatzl (Reviewer). ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 8 Sep 2022 00:04:11 GMT, Sangheon Kim <sangheki@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
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision:
- Merge remote-tracking branch 'origin/8291753-cpu-time' into 8291753-cpu-time - Comment from albertnetymk
Many thanks for the review, Thomas and Albert. ------------- PR: https://git.openjdk.org/jdk/pull/9760
On Thu, 4 Aug 2022 23:58:02 GMT, Sangheon Kim <sangheki@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
This pull request has now been integrated. Changeset: 14eb5ad0 Author: Sangheon Kim <sangheki@openjdk.org> URL: https://git.openjdk.org/jdk/commit/14eb5ad0dc987ffe3621f4eeeebeb6b5a2cd691b Stats: 218 lines in 23 files changed: 163 ins; 2 del; 53 mod 8291753: Add JFR event for GC CPU Time Reviewed-by: tschatzl, ayang ------------- PR: https://git.openjdk.org/jdk/pull/9760
participants (4)
-
Albert Mingkun Yang
-
Erik Gahlin
-
Sangheon Kim
-
Thomas Schatzl