Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8324066: "clhsdb jstack" should not by default scan for j.u.c locks because it can be very slow #17479

Closed
wants to merge 7 commits into from

Conversation

plummercj
Copy link
Contributor

@plummercj plummercj commented Jan 18, 2024

I noticed that "clhsdb jstack" seemed to hang when I attached to process with a somewhat large heap. It had taken over 10 minutes when I finally decided to have a look at the SA process (using bin/jstack), which came up with the following in the stack:

at sun.jvm.hotspot.oops.ObjectHeap.iterateObjectsOfKlass([jdk.hotspot.agent@23-internal](jdk.hotspot.agent@23-internal)/ObjectHeap.java:117)
at sun.jvm.hotspot.runtime.ConcurrentLocksPrinter.fillLocks([jdk.hotspot.agent@23-internal](jdk.hotspot.agent@23-internal)/ConcurrentLocksPrinter.java:70)
at sun.jvm.hotspot.runtime.ConcurrentLocksPrinter.<init>([jdk.hotspot.agent@23-internal](jdk.hotspot.agent@23-internal)/ConcurrentLocksPrinter.java:36)
at sun.jvm.hotspot.tools.StackTrace.run([jdk.hotspot.agent@23-internal](jdk.hotspot.agent@23-internal)/StackTrace.java:71)

This code is meant to print information about j.u.c. locks. It it works by searching the entire java heap for instances of AbstractOwnableSynchronizer. This is a very expensive operation because it means not only does SA need to read in the entire java heap, but it needs to create a Klass mirror for every heap object so it can determine its type.

Our testing doesn't seem to run into this slowness problem because "clhsdb jstack" only iterates over the heap if AbstractOwnableSynchronizer has been loaded, which it won't be if no j.u.c. locks have been created. This seems to be the case wherever we use "clhsdb jstack" in testing. We do have some tests that likely result in j.u.c locks, but they all use "jhsdb jstack", which doesn't have this issue (it requires use of the --locks argument to enable printing of j.u.c locks).

This issue was already called out in JDK-8262098. For this CR I am proposing that "clhsdb jstack" not include j.u.c lock scanning by default, and add the -l argument to enable it. This will make it similar to bin/jstack, which also has a -l argument, and to "clhsdb jstack", which has a --locks argument (which maps internally to the Jstack.java -l argument).

The same changes are also being made to "clhsdb pstack".

Tested with all tier1, tier2, and tier5 svc tests.


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-8324066: "clhsdb jstack" should not by default scan for j.u.c locks because it can be very slow (Enhancement - P4)

Reviewers

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 17479

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

Using diff file

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

Webrev

Link to Webrev Comment

@bridgekeeper
Copy link

bridgekeeper bot commented Jan 18, 2024

👋 Welcome back cjplummer! 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 openjdk bot changed the title 8324066 8324066: "clhsdb jstack" should not by default scan for j.u.c locks because it can be very slow Jan 18, 2024
@openjdk
Copy link

openjdk bot commented Jan 18, 2024

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

  • serviceability

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.

@openjdk openjdk bot added the serviceability serviceability-dev@openjdk.org label Jan 18, 2024
@openjdk openjdk bot added the rfr Pull request is ready for review label Jan 18, 2024
@mlbridge
Copy link

mlbridge bot commented Jan 18, 2024

Webrevs

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems to be a change that will impact the end user of these tools. Instead of disabling j.u.c.locks by default and proving an option to turn them on, you should provide an option to turn them off, and our tests can use that. What you proposed makes sense for an initial design of the tool, but not for a change after the fact.

@plummercj
Copy link
Contributor Author

@dholmes-ora I understand your point. There are pros and cons to both approaches, and I think that needs to be considered. One advantage of my approach is preventing users from accidentally stumbling into this is issue, and wondering why jstack won't complete. I think this is more likely than being confused by the change (expecting locks and not seeing them). Another advantage is consistency with bin/jstack and "jhsdb jstack" in that the locks are not included by default.

@dholmes-ora
Copy link
Member

You will need a Release Note to document the change.

I also wonder if we should be looking at a different way to track j.u.c lock usage, as searching the full heap does not seem at all reasonable.

@plummercj
Copy link
Contributor Author

I also wonder if we should be looking at a different way to track j.u.c lock usage, as searching the full heap does not seem at all reasonable.

Good question. It looks like bin/jstack does the same, but there is much less cost to doing this within hotspot than with using SA:

void ConcurrentLocksDump::dump_at_safepoint() {
  // dump all locked concurrent locks
  assert(SafepointSynchronize::is_at_safepoint(), "all threads are stopped");

  GrowableArray<oop>* aos_objects = new (mtServiceability) GrowableArray<oop>(INITIAL_ARRAY_SIZE, mtServiceability);

  // Find all instances of AbstractOwnableSynchronizer
  HeapInspection::find_instances_at_safepoint(vmClasses::java_util_concurrent_locks_AbstractOwnableSynchronizer_klass(),
                                              aos_objects);
  // Build a map of thread to its owned AQS locks
  build_map(aos_objects);

  delete aos_objects;
}

@plummercj
Copy link
Contributor Author

Ping! I still need 2 reviews. Thanks!

break;
}
}
if (addressString != null)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Did we break already, is this if not needed?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are two nested loops. If we did not break out of the inner loop (which is scanning words in the given line), then addressString might still be null and we need to search the next line. If we don't do this check and break here, then we will always search the next line even if addressString was found.

Copy link
Contributor

@kevinjwalls kevinjwalls left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me, I agree with the consistency and not giving users the possibly long/slow operation unless requested. (Unless or until we have a fast method for this.)

if (line.contains(key)) {
String[] words = line.split(key + "|[, ]");
for (String word : words) {
word = word.replace("<","").replace(">","");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
word = word.replace("<","").replace(">","");
word = word.replace("<", "").replace(">", "");

@plummercj
Copy link
Contributor Author

Thanks for the review Kevin. Can I get one more review please? Thanks!

String addressString = null;
for (String line : lines) {
if (line.contains(key)) {
String[] words = line.split(key + "|[, ]");
Copy link

@alexmenkov alexmenkov Jan 31, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

String.split() expect regexp as an argument
Not sure how this code works (without escaping '$' and parentheses).
I think it would be clearer to use standard regexp pattern/matcher, something like

Pattern pattern = Pattern.compile("\\s+- <0x([0-9a-fA-F]+)>, \\(a java/util/concurrent/locks/ReentrantLock\\$NonfairSync\\)");
for (String line: lines) {
    Matcher matcher = pattern.matcher(line);
    if (matcher.find()) {
        addressString = matcher.group(1);
        break;
    }
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think key doesn't really matter when doing the split. key is mainly for finding the right line. The split is for tokenizing that line into words, and the only parts that matters for that are ' ' and the ',' being used as word delimiters. I think key should just be removed from the regex. I think the source of the bug is code copied from ClhsdbInspect.java:

                    // Escape the token "Method*=" because the split method uses
                    // a regex, not just a straight String.
                    String escapedKey = key.replace("*","\\*");
                    String[] words = line.split(escapedKey+"|[ ]");

In this case key is Method*=. The code works and the escaping and searching for key is necessary because we are looking for something like Method*=<0x00000000ffc2ed70>, but I think this could have been simplified by including = in the split pattern rather than all of escapedKey.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, I see now.
In this case "[, ]" separator should work fine.
I still think that use of Matcher is much clear - regexp defines what you are looking for and extract the value you need. Also there is no need to split jstackOutput into lines - the whole jstack output can be passed to Pattern.matcher.
But I don't force you if you prefer to extract the address manually.

@openjdk
Copy link

openjdk bot commented Jan 31, 2024

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

8324066: "clhsdb jstack" should not by default scan for j.u.c locks because it can be very slow

Reviewed-by: kevinw, amenkov

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

  • 5b9b176: 8324174: assert(m->is_entered(current)) failed: invariant
  • 0cc8e5b: 8325042: remove unused JVMDITools test files
  • f292053: 8323621: JDK build should exclude snippet class in java.lang.foreign
  • 62c9530: 8324238: [macOS] java/awt/Frame/ShapeNotSetSometimes/ShapeNotSetSometimes.java fails with the shape has not been applied msg
  • 1f2922a: 8320342: Use PassFailJFrame for TruncatedPopupMenuTest.java
  • 2cd1ba6: 8324981: Shenandoah: Move commit and soft max heap changed methods into heap
  • 1733d2e: 8303374: Implement JEP 455: Primitive Types in Patterns, instanceof, and switch (Preview)
  • 6697160: 8320712: Rewrite BadFactoryTest in pure Java
  • 725314f: 8324771: Obsolete RAMFraction related flags
  • ec6c35c: 8324970: Serial: Refactor signature of maintain_old_to_young_invariant
  • ... and 139 more: https://git.openjdk.org/jdk/compare/dadd9cd1e8434cffaafc7406a864eaa55954cfb8...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.

@openjdk openjdk bot added the ready Pull request is ready to be integrated label Jan 31, 2024
@plummercj
Copy link
Contributor Author

Thanks for the reviews Kevin and Alex!

/integrate

@openjdk
Copy link

openjdk bot commented Feb 1, 2024

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

  • 6b09a79: 8324974: JFR: EventCompilerPhase should be created as UNTIMED
  • 70e7cdc: 8323670: A few client tests intermittently throw ConcurrentModificationException
  • ac1cd31: 8325096: Test java/security/cert/CertPathBuilder/akiExt/AKISerialNumber.java is failing
  • 8e45182: 8324834: Use _LARGE_FILES on AIX
  • cab74b0: 8324287: Record total and free swap space in JFR
  • 6b84f9b: 8325001: Typo in the javadocs for the Arena::ofShared method
  • cd11059: 8325053: Serial: Move Generation::save_used_region to TenuredGeneration
  • d9331bf: 8324845: management.properties text "interface name" is misleading
  • 68206b5: 8324585: JVM native memory leak in PCKS11-NSS security provider
  • 1aba78f: 8324937: GHA: Avoid multiple test suites per job
  • ... and 153 more: https://git.openjdk.org/jdk/compare/dadd9cd1e8434cffaafc7406a864eaa55954cfb8...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Feb 1, 2024
@openjdk openjdk bot closed this Feb 1, 2024
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Feb 1, 2024
@openjdk
Copy link

openjdk bot commented Feb 1, 2024

@plummercj Pushed as commit 192349e.

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
integrated Pull request has been integrated serviceability serviceability-dev@openjdk.org
Development

Successfully merging this pull request may close these issues.

5 participants