RFR: 8292266: Add JFR event for total Reference processing time
Hi all, Can I have reviews for this change that adds a new JFR event for total Reference Processing time? The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement. Testing: hs-tier1 ~ 3 Thanks, Sangheon ------------- Commit messages: - Remove comment out code. - Combine GCTrace::report method. - Separate GCTrace::report method. Changes: https://git.openjdk.org/jdk/pull/11230/files Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=00 Issue: https://bugs.openjdk.org/browse/JDK-8292266 Stats: 141 lines in 11 files changed: 135 ins; 2 del; 4 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 05:04:38 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Some minor comments in explanation texts/naming, but lgtm. src/hotspot/share/jfr/metadata/metadata.xml line 393:
391: </Event> 392: 393: <Event name="GCReferenceProcessTime" category="Java Virtual Machine, GC, Reference" label="GC Reference Process Time" startTime="false"
Suggestion: <Event name="GCReferenceProcessingTime" category="Java Virtual Machine, GC, Reference" label="GC Reference Processing Time" startTime="false" src/hotspot/share/jfr/metadata/metadata.xml line 394:
392: 393: <Event name="GCReferenceProcessTime" category="Java Virtual Machine, GC, Reference" label="GC Reference Process Time" startTime="false" 394: description="Total processing time of processed references during GC">
Suggestion: description="Total time for processing java.lang.ref.References during GC"> ------------- Marked as reviewed by tschatzl (Reviewer). PR: https://git.openjdk.org/jdk/pull/11230
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Update src/hotspot/share/jfr/metadata/metadata.xml Co-authored-by: Thomas Schatzl <59967451+tschatzl@users.noreply.github.com> ------------- Changes: - all: https://git.openjdk.org/jdk/pull/11230/files - new: https://git.openjdk.org/jdk/pull/11230/files/ec9209a5..a85df44e Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=01 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=00-01 Stats: 1 line in 1 file changed: 0 ins; 0 del; 1 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Update src/hotspot/share/jfr/metadata/metadata.xml Co-authored-by: Thomas Schatzl <59967451+tschatzl@users.noreply.github.com> ------------- Changes: - all: https://git.openjdk.org/jdk/pull/11230/files - new: https://git.openjdk.org/jdk/pull/11230/files/a85df44e..33fa3b70 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=02 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=01-02 Stats: 1 line in 1 file changed: 0 ins; 0 del; 1 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 16:53:43 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Update src/hotspot/share/jfr/metadata/metadata.xml
Co-authored-by: Thomas Schatzl <59967451+tschatzl@users.noreply.github.com>
src/hotspot/share/gc/shared/gcTrace.cpp line 76:
74: send_reference_stats_event(REF_PHANTOM, rps.phantom_count()); 75: 76: send_reference_process_time_event(rps.total_process_time());
I think this is called by all collectors, but Z and Shenandoah would have zero for "total process time" here. I am not sure if this causes confusion on reading the jfr reports. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 19:43:13 GMT, Albert Mingkun Yang <ayang@openjdk.org> wrote:
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Update src/hotspot/share/jfr/metadata/metadata.xml
Co-authored-by: Thomas Schatzl <59967451+tschatzl@users.noreply.github.com>
src/hotspot/share/gc/shared/gcTrace.cpp line 76:
74: send_reference_stats_event(REF_PHANTOM, rps.phantom_count()); 75: 76: send_reference_process_time_event(rps.total_process_time());
I think this is called by all collectors, but Z and Shenandoah would have zero for "total process time" here. I am not sure if this causes confusion on reading the jfr reports.
You are right and this is current scope of this CR. If both collectors measure spent time, we can add it later. Hopefully under separate CR. Or if the confusion only comes from zero value of the measured time, we can avoid sending zero value event. i.e. skip sending ref-proc-time event for both collectors. My first commit is something like this but stopped as someone may complain lack of the event anyway. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 23:28:41 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
src/hotspot/share/gc/shared/gcTrace.cpp line 76:
74: send_reference_stats_event(REF_PHANTOM, rps.phantom_count()); 75: 76: send_reference_process_time_event(rps.total_process_time());
I think this is called by all collectors, but Z and Shenandoah would have zero for "total process time" here. I am not sure if this causes confusion on reading the jfr reports.
You are right and this is current scope of this CR. If both collectors measure spent time, we can add it later. Hopefully under separate CR.
Or if the confusion only comes from zero value of the measured time, we can avoid sending zero value event. i.e. skip sending ref-proc-time event for both collectors. My first commit is something like this but stopped as someone may complain lack of the event anyway.
Or if the confusion only comes from zero value of the measured time
Yes, that's the confusion I was referring to.
My first commit is something like this but stopped as someone may complain lack of the event anyway.
I see; I actually like the approach in your first commit better -- separate methods for reporting ref counts and processing time. If an event is not supported for a particular collector, it should not be emitted for that collector, IMO.
I still feel the behavior, reporting zero for ref-processing time for Shenandoah and Z, can be surprising, so I'd prefer this is avoided. However, if others think this is fine, I would not block this.
I agree about the zeros. I also prefer that events are implemented for all collectors. It confusing for users or tools that consume the data to not get it for all GCs. I understand it is more work, but I rather delay the event a release than having something that is only partly done for JDK 20. ------------- PR: https://git.openjdk.org/jdk/pull/11230
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Thomas review ------------- Changes: - all: https://git.openjdk.org/jdk/pull/11230/files - new: https://git.openjdk.org/jdk/pull/11230/files/33fa3b70..2b119e74 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=03 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=02-03 Stats: 12 lines in 7 files changed: 0 ins; 0 del; 12 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 23:12:13 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Thomas review
Or if the confusion only comes from zero value of the measured time
Yes, that's the confusion I was referring to.
My first commit is something like this but stopped as someone may complain lack of the event anyway.
I see; I actually like the approach in your first commit better -- separate methods for reporting ref counts and processing time. If an event is not supported for a particular collector, it should not be emitted for that collector, IMO. I still feel the behavior, reporting zero for ref-processing time for Shenandoah and Z, can be surprising, so I'd prefer this is avoided. However, if others think this is fine, I would not block this. ------------- Marked as reviewed by ayang (Reviewer). PR: https://git.openjdk.org/jdk/pull/11230
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision: - Add Shenandoah and Z. albertnetymk and egahlin comment. - Revert to initial commit. Albert review. ------------- Changes: - all: https://git.openjdk.org/jdk/pull/11230/files - new: https://git.openjdk.org/jdk/pull/11230/files/2b119e74..2faec9e3 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=04 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=03-04 Stats: 52 lines in 15 files changed: 23 ins; 20 del; 9 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 02:08:48 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with two additional commits since the last revision:
- Add Shenandoah and Z. albertnetymk and egahlin comment. - Revert to initial commit. Albert review.
1. Reverted to the first version which has separate GCTrace::report_gc_reference_processing_time(). 2. Added Z and Shenandoah impl. For Z and Shenandoah, I understand your point. But this is why I explicitly mentioned on CR/PR that I intended to emit already measured TOTAL time via ReferenceProcessorStats class. i.e. not add something new. Thanks @albertnetymk and @egahlin for your comments. ------------- PR: https://git.openjdk.org/jdk/pull/11230
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision: Rename to report_gc_reference_processing_time(). Change test @requires to !=Epsilon. ------------- Changes: - all: https://git.openjdk.org/jdk/pull/11230/files - new: https://git.openjdk.org/jdk/pull/11230/files/2faec9e3..491e9ef0 Webrevs: - full: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=05 - incr: https://webrevs.openjdk.org/?repo=jdk&pr=11230&range=04-05 Stats: 13 lines in 12 files changed: 0 ins; 1 del; 12 mod Patch: https://git.openjdk.org/jdk/pull/11230.diff Fetch: git fetch https://git.openjdk.org/jdk pull/11230/head:pull/11230 PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 07:21:39 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Rename to report_gc_reference_processing_time(). Change test @requires to !=Epsilon.
I'm fine with either solution (i.e. to not send the event for not-supported collectors), but really, it depends on what this new event is supposed to capture. I.e. the question is what the "total reference processing time" is supposed to mean: is it reference processing time in stw pauses? Or generally "total processing time" (including cpu time spent concurrently)? To me it's the former, so a value of 0.0 is technically correct for the concurrent collectors (actually I'm not sure whether Shenandoah does fully concurrent reference processing). This would suggest to make it available for all collectors, as there is a difference between not having a value for some collectors as it may not only mean "the time is zero" (does not do stw reference processing) but also something like "the collector does not do this at all". When/if we add concurrent reference processing time tracking (which isn't trivial to do), then it may be useful to add another event (or just a value to the existing one) to be able to discriminate between concurrent vs. time spent in stw. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 10:30:26 GMT, Thomas Schatzl <tschatzl@openjdk.org> wrote:
When/if we add concurrent reference processing time tracking (which isn't trivial to do), then it may be useful to add another event (or just a value to the existing one) to be able to discriminate between concurrent vs. time spent in stw.
Maybe name the value in the event something like "STW time" or so to make it clear already what it contains. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 07:21:39 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Rename to report_gc_reference_processing_time(). Change test @requires to !=Epsilon.
I think the new event for ref-processing time should be roughly corresponding to its neighbor `<Event name="GCReferenceStatistics"` in `metadata.xml`, regardless of ref-processing being STW or not.
When/if we add concurrent reference processing time tracking (which isn't trivial to do)
@sangheon 's latest revision does that for Shenandoah and Z. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 12:26:52 GMT, Albert Mingkun Yang <ayang@openjdk.org> wrote:
I think the new event for ref-processing time should be roughly corresponding to its neighbor `<Event name="GCReferenceStatistics"` in `metadata.xml`, regardless of ref-processing being STW or not.
GCReferenceStatistics isn't dependent on whether the work has been performed in stw or concurrently; it shows number of the processed references in the last "pass".
When/if we add concurrent reference processing time tracking (which isn't trivial to do)
@sangheon 's latest revision does that for Shenandoah and Z.
Okay, but addition of this is exactly what makes the event misleading (or hard to explain to users) as I tried to explain: the Shenandoah and Z timings are different in the circumstances they are taken: * for ZGC and Shenandoah it means wall time for concurrent reference processing. This can be arbitrarily lengthened due to mutator impact. * for Serial/Parallel it means wall time for stw reference processing. Which is probably fairly close to cpu time given it is done with the mutator suspended. * for G1 which does both, concurrent weak/reference processing work (preclean) and stw reference processing, this event now only tracks the latter. Adding them together for this event obviously does not make sense. Maybe G1 is the odd one out? Then again, it is hard to add preclean time at the time when this event is sent, but imo that makes a stronger case for separate concurrent/stw reference processing events (and maybe not sending this stw event for shenandoah and Z) I.e. the values between collectors are not comparable although they use the same event/value, and even missing out some parts now. This explains my reluctance to mix different kind of work (concurrent vs. stw) in a single event/value. This can be really confusing (apart from losing G1's concurrent reference processing work here). That is the reason I liked the original limit of this PR's scope to just the stw part, even if that value was always zero for some collectors due to the way they work, better. (All of these timings do not cover time spent in discovery, which is arguably also some kind of "reference processing", but probably not something this event wants to track) ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 14:08:28 GMT, Thomas Schatzl <tschatzl@openjdk.org> wrote:
This explains my reluctance to mix different kind of work (concurrent vs. stw) in a single event/value.
I acknowledge all the drawbacks of having a single event for ref-processing, but I believe it's a good trade-off, a simpler interface that captures the most significant component in most cases. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 07:21:39 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Rename to report_gc_reference_processing_time(). Change test @requires to !=Epsilon.
Having said that, if everyone else agrees with having only one event for whatever a particular GC calls "reference processing", then I'm fine with it. ------------- PR: https://git.openjdk.org/jdk/pull/11230
On Tue, 22 Nov 2022 07:21:39 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
Sangheon Kim has updated the pull request incrementally with one additional commit since the last revision:
Rename to report_gc_reference_processing_time(). Change test @requires to !=Epsilon.
Looks good to me. ------------- Marked as reviewed by eosterlund (Reviewer). PR: https://git.openjdk.org/jdk/pull/11230
On Fri, 18 Nov 2022 05:04:38 GMT, Sangheon Kim <sangheki@openjdk.org> wrote:
Hi all,
Can I have reviews for this change that adds a new JFR event for total Reference Processing time?
The goal is to generate a new JFR event if there is already measured time. This CR doesn't add new time measurement.
Testing: hs-tier1 ~ 3
Thanks, Sangheon
This pull request has been closed without being integrated. ------------- PR: https://git.openjdk.org/jdk/pull/11230
participants (6)
-
Albert Mingkun Yang
-
duke
-
Erik Gahlin
-
Erik Österlund
-
Sangheon Kim
-
Thomas Schatzl