8259808: Add JFR event to detect GC locker stall #2088

D-D-H · 2021-01-15T02:42:20Z

GC locker will stall the operation of GC, resulting in some Java threads can not continue to run until GC locker is released, thus affecting the response time of the application. Add a JFR event to report this information is helpful to detect this issue.

For the test purpose, I add two Whitebox methods to lock/unlock critical.

Progress

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

Issue

JDK-8259808: Add JFR event to detect GC locker stall

Reviewers

Stefan Johansson (@kstefanj - Reviewer) ⚠️ Review applies to 85987c5
Thomas Schatzl (@tschatzl - Reviewer)
Erik Gahlin (@egahlin - Reviewer) ⚠️ Review applies to a5d0e0a

Download

$ git fetch https://git.openjdk.java.net/jdk pull/2088/head:pull/2088
$ git checkout pull/2088

bridgekeeper · 2021-01-15T02:43:32Z

👋 Welcome back ddong! 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-01-15T02:44:29Z

@D-D-H 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.

D-D-H · 2021-01-15T02:45:21Z

/label add hotspot-jfr

openjdk · 2021-01-15T02:45:33Z

@D-D-H
The hotspot-jfr label was successfully added.

mlbridge · 2021-01-15T02:48:14Z

Webrevs

D-D-H · 2021-01-15T02:55:41Z

/label add hotspot-gc

openjdk · 2021-01-15T02:55:52Z

@D-D-H
The hotspot-gc label was successfully added.

D-D-H · 2021-01-15T03:14:10Z

GC locker will stall the operation of GC, resulting in some Java threads can not continue to run until GC locker is released, thus affecting the response time of the application. Add a JFR event to report this information is helpful to detect this issue.

For the test purpose, I add two Whitebox methods to lock/unlock critical.

D-D-H · 2021-01-18T02:50:54Z

Greetings,
please help review this patch:)

Thanks

stefank

Not a review, but a few comments about what probably needs to be cleaned up before a proper review starts.

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

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

src/hotspot/share/prims/whitebox.cpp

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

src/hotspot/share/utilities/ticks.hpp

D-D-H · 2021-01-18T13:52:09Z

Refactored.

Testing: jdk/jfr all passed.

kstefanj

Some comments.

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

D-D-H · 2021-01-22T13:30:59Z

Some comments.

Thanks for the review :)

kstefanj

I think this looks good now but please await a second reviewer.

I took if for a spin in out internal testing and tier1-2 looks ok as well as the JFR tests.

openjdk · 2021-01-25T18:11:20Z

@D-D-H 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:

8259808: Add JFR event to detect GC locker stall

Reviewed-by: sjohanss, tschatzl, egahlin

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 194 new commits pushed to the master branch:

f353fcf: 8258894: C2: Forbid GCM to move stores into loops
ac276bb: 8257074: Update the ByteBuffers micro benchmark
7ed591c: 8260314: Replace border="1" on tables with CSS
e696baa: 8260448: Simplify ManagementFactory$PlatformMBeanFinder
b3c8a52: 8259050: Error recovery in lexer could be improved
bf15c70: 8260460: GitHub actions still fail on Linux x86_32 with "Could not configure libc6:i386"
3e4194c: 8260022: [ppc] os::print_function_and_library_name shall resolve function descriptors transparently
fa40a96: 8253420: Refactor HeapRegionManager::find_highest_free
4d004c9: 8260449: Remove stale declaration of SATBMarkQueue::apply_closure_and_empty()
fd2641e: 8260236: better init AnnotationCollector _contended_group
... and 184 more: https://git.openjdk.java.net/jdk/compare/ae9187d757b6ed585d85c6e66105ca20bebe7bc7...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.

As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@stefank, @kstefanj, @tschatzl, @egahlin) but any other Committer may sponsor as well.

➡️ To flag this PR as ready for integration with the above commit message, type /integrate in a new comment. (Afterwards, your sponsor types /sponsor in a new comment to perform the integration).

tschatzl · 2021-01-26T09:27:08Z

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

+
+import sun.hotspot.WhiteBox;
+
+/**


This block should be the first thing in the test after the copyright notice.

Fixed. But I notice that there are many other tests that didn't comply with this rule.

tschatzl · 2021-01-26T09:27:13Z

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

+        for (var i = 0; i < STALL_THREAD_COUNT; i++) {
+            ts[i] = new Thread(() -> {
+                STALL_COUNT_SIGNAL.countDown();
+                for (int j = 0; j < LOOP; j++) {


Since the test already uses WhiteBox, please use whitebox to trigger a gc instead of this dodgy method.

Triggering a GC is not enough, I hope these threads could be stalled by the GC locker(call GCLocker::stall_until_clear) so that a correct assertion of the number of stall count could be added.
I think it could not be done by WhiteBox::youngGC/fullGC, please correct me if I'm wrong.

I agree, although this is more a theoretical concern since it's not checked. Let's keep this for now as is though.

tschatzl · 2021-01-26T09:42:59Z

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

@@ -97,6 +98,7 @@ bool GCLocker::check_active_before_gc() {
  if (is_active() && !_needs_gc) {
    verify_critical_count();
    _needs_gc = true;
+    GCLockerTracer::start_gc_locker(_jni_lock_count);


Not really convinced that passing _jni_lock_count here gives a lot of information: this is the number of threads in a critical section at the point of the first thread needing a gc. It's probably better than nothing. At least this information should be added to the description of the event (if that is possible).

I think this field can be used to judge whether there are many threads that are often in a critical section, but I am not sure if it really helps to analyze the problem., and just as you said, it's better than nothing. An appropriate description of this field has been added.

tschatzl · 2021-01-26T09:46:16Z

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

@@ -0,0 +1,126 @@
+/*
+ * Copyright (c) 2021 Alibaba Group Holding Limited. All Rights Reserved.


Would it be possible to keep with the general format of copyright messages in other code, i.e. "Copyright (c) , . ..."? I.e. if possible please add a comma after the year.

tschatzl · 2021-01-26T09:48:41Z

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

@@ -1090,6 +1090,11 @@
    <Field type="boolean" name="onOutOfMemoryError" label="On Out of Memory Error" />
  </Event>

+  <Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" description="GC Locker Information" label="GC Locker" startTime="true" thread="true" stackTrace="true">
+    <Field type="uint" name="lockCount" label="Lock Count" />
+    <Field type="uint" name="stallCount" label="Stall Count" />


Please add descriptions to the fields as mentioned above.

egahlin · 2021-01-26T16:49:37Z

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

@@ -1091,8 +1091,8 @@
  </Event>

  <Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" description="GC Locker Information" label="GC Locker" startTime="true" thread="true" stackTrace="true">
-    <Field type="uint" name="lockCount" label="Lock Count" />
-    <Field type="uint" name="stallCount" label="Stall Count" />
+    <Field type="uint" name="lockCount" label="Lock Count" description="the number of java threads in a critical section when the GC locker is started" />


I would suggest changing this to:

"The number of Java threads in a critical section when the GC locker is started"
"The number of Java threads stalled by the GC locker"

egahlin · 2021-01-26T16:52:51Z

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

@@ -1091,8 +1091,8 @@
  </Event>

  <Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" description="GC Locker Information" label="GC Locker" startTime="true" thread="true" stackTrace="true">


"GC Locker Information" is not very useful. Remove the description completely or provide more information.

D-D-H · 2021-01-27T02:25:46Z

/integrate

openjdk · 2021-01-27T02:26:15Z

@D-D-H
Your change (at version 7efac60) is now ready to be sponsored by a Committer.

kstefanj · 2021-01-27T14:31:57Z

Since @tschatzl requested changes yesterday I will wait for him to sponsor this.

tschatzl

Looks good.

tschatzl · 2021-01-27T15:27:43Z

/sponsor

openjdk · 2021-01-27T15:29:04Z

@tschatzl @D-D-H Since your change was applied there have been 194 commits pushed to the master branch:

f353fcf: 8258894: C2: Forbid GCM to move stores into loops
ac276bb: 8257074: Update the ByteBuffers micro benchmark
7ed591c: 8260314: Replace border="1" on tables with CSS
e696baa: 8260448: Simplify ManagementFactory$PlatformMBeanFinder
b3c8a52: 8259050: Error recovery in lexer could be improved
bf15c70: 8260460: GitHub actions still fail on Linux x86_32 with "Could not configure libc6:i386"
3e4194c: 8260022: [ppc] os::print_function_and_library_name shall resolve function descriptors transparently
fa40a96: 8253420: Refactor HeapRegionManager::find_highest_free
4d004c9: 8260449: Remove stale declaration of SATBMarkQueue::apply_closure_and_empty()
fd2641e: 8260236: better init AnnotationCollector _contended_group
... and 184 more: https://git.openjdk.java.net/jdk/compare/ae9187d757b6ed585d85c6e66105ca20bebe7bc7...master

Your commit was automatically rebased without conflicts.

Pushed as commit 311a0a9.

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

8259808: Add JFR event to detect GC locker stall

b68814f

openjdk bot added hotspot hotspot-dev@openjdk.org rfr Pull request is ready for review labels Jan 15, 2021

openjdk bot added the hotspot-jfr hotspot-jfr-dev@openjdk.org label Jan 15, 2021

openjdk bot added the hotspot-gc hotspot-gc-dev@openjdk.org label Jan 15, 2021

stefank suggested changes Jan 18, 2021

View reviewed changes

Refactor based on comments

c36d4f9

kstefanj suggested changes Jan 22, 2021

View reviewed changes

src/hotspot/share/gc/shared/gcTraceSend.cpp Show resolved Hide resolved

src/hotspot/share/gc/shared/gcTraceSend.cpp Outdated Show resolved Hide resolved

src/hotspot/share/gc/shared/gcTraceSend.cpp Show resolved Hide resolved

src/hotspot/share/gc/shared/gcTraceSend.cpp Show resolved Hide resolved

add assertions and reset _jni_lock_count

41641d8

add GCLockerTracer::is_started() that makes the logic more clear

85987c5

kstefanj approved these changes Jan 25, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Jan 25, 2021

tschatzl suggested changes Jan 26, 2021

View reviewed changes

Add descriptions and fix the format problem

a5d0e0a

egahlin approved these changes Jan 26, 2021

View reviewed changes

improve descriptions

7efac60

openjdk bot added the sponsor Pull request is ready to be sponsored label Jan 27, 2021

tschatzl approved these changes Jan 27, 2021

View reviewed changes

openjdk bot closed this Jan 27, 2021

openjdk bot added integrated Pull request has been integrated and removed sponsor Pull request is ready to be sponsored ready Pull request is ready to be integrated rfr Pull request is ready for review labels Jan 27, 2021

D-D-H deleted the jfr_gclocker branch February 5, 2021 02:13

		@@ -0,0 +1,126 @@
		/*
		* Copyright (c) 2021 Alibaba Group Holding Limited. All Rights Reserved.

		@@ -1091,8 +1091,8 @@
		</Event>

		<Event name="GCLocker" category="Java Virtual Machine, GC, Detailed" description="GC Locker Information" label="GC Locker" startTime="true" thread="true" stackTrace="true">


		import sun.hotspot.WhiteBox;

		/**

8259808: Add JFR event to detect GC locker stall #2088

8259808: Add JFR event to detect GC locker stall #2088

Conversation

D-D-H commented Jan 15, 2021 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Download

bridgekeeper bot commented Jan 15, 2021

openjdk bot commented Jan 15, 2021

D-D-H commented Jan 15, 2021

openjdk bot commented Jan 15, 2021

mlbridge bot commented Jan 15, 2021 • edited Loading

Webrevs

D-D-H commented Jan 15, 2021

openjdk bot commented Jan 15, 2021

D-D-H commented Jan 15, 2021

D-D-H commented Jan 18, 2021

stefank left a comment

Choose a reason for hiding this comment

D-D-H commented Jan 18, 2021

kstefanj left a comment

Choose a reason for hiding this comment

D-D-H commented Jan 22, 2021

kstefanj left a comment

Choose a reason for hiding this comment

openjdk bot commented Jan 25, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

D-D-H Jan 26, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

D-D-H commented Jan 27, 2021

openjdk bot commented Jan 27, 2021

kstefanj commented Jan 27, 2021

tschatzl left a comment

Choose a reason for hiding this comment

tschatzl commented Jan 27, 2021

openjdk bot commented Jan 27, 2021

D-D-H commented Jan 15, 2021 •

edited by openjdk bot

Loading

mlbridge bot commented Jan 15, 2021 •

edited

Loading

openjdk bot commented Jan 25, 2021 •

edited

Loading

D-D-H Jan 26, 2021 •

edited

Loading