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

8291641: Optimize StackTraceElement.toString() #9665

Closed
wants to merge 12 commits into from

Conversation

schlosna
Copy link
Contributor

@schlosna schlosna commented Jul 27, 2022

I would like to contribute an optimized version of StackTraceElement#toString() that uses a single StringBuilder throughout creation to avoid intermediate String allocations. StackTraceElement#toString() is used in a number of JDK code paths including Throwable#printStackTrace(), as well as many JDK consumers may transform StackTraceElement toString() in logging frameworks capturing throwables and exceptions, and diagnostics performing dumps.

Given this usage and some observed JFR profiles from production services, I'd like to reduce the intermediate allocations to reduce CPU pressure in these circumstances. I have added a couple benchmarks for a sample Throwable#printStackTrace() converted to String via StringWriter and individual StackTraceElement toString. The former shows ~15% improvement, while the latter shows ~40% improvement.

Before

Benchmark                               Mode  Cnt       Score      Error  Units
StackTraceElementBench.printStackTrace  avgt   15  167147.066 ± 4260.521  ns/op
StackTraceElementBench.toString         avgt   15     132.781 ±    2.095  ns/op

After

Benchmark                               Mode  Cnt       Score      Error  Units
StackTraceElementBench.printStackTrace  avgt   15  142909.133 ± 2290.720  ns/op
StackTraceElementBench.toString         avgt   15      78.939 ±    0.469  ns/op

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

Reviewers

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 9665

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

Using diff file

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

@bridgekeeper
Copy link

bridgekeeper bot commented Jul 27, 2022

👋 Welcome back schlosna! 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
Copy link

openjdk bot commented Jul 27, 2022

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

  • core-libs

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 core-libs core-libs-dev@openjdk.org label Jul 27, 2022
@carterkozak
Copy link
Contributor

I think there's another angle to consider here:
This wasn't an issue using java 8 and earlier because the data encapsulated by StackTraceElement was available using the public API, this meant that logging frameworks were free to implement custom formatters that could be used in place of the toString implementation without losing features and optimizing for niche use-cases (e.g. allocation avoidance).
In recent java versions, the StackTraceElement string value is based on data that's not available using the public API (whether the classloader is builtin, and whether the module is from java.base). String matching can get around this at a potential correctness cost.

It would be helpful for my uses if the new internal attributes were exposed in some way from StackTraceElement, however I understand why that isn't desirable from an API design standpoint.
I suspect a public appendTo(Appendable) is a more feasible API addition as it encapsulates the functionality without awareness of what a builtin classloader is, and roughly matches prior art within Throwable.printStackTrace. I'd love to get an opinion from someone more closely involved with openjdk core-libs development :-)

@merykitty
Copy link
Member

If the objective of this patch is to optimise StackTraceElement::toString(), then I would suggest the most efficient method of calculating the length and encoding of the result, filling the backing buffer then using the package-private constructor of java.lang.String to construct the final result.

And if you want to propose exposing StackTraceElement::appendTo(Appendable), then I think it should be a separate patch instead.

Thanks.

@schlosna schlosna force-pushed the ds/StackTraceElement branch 2 times, most recently from 0c27cb3 to de0a337 Compare August 1, 2022 02:13
@schlosna schlosna force-pushed the ds/StackTraceElement branch from de0a337 to aca4428 Compare August 1, 2022 02:59
@schlosna
Copy link
Contributor Author

schlosna commented Aug 1, 2022

Thanks for the reviews and comments! To @merykitty 's point, I am now focusing this PR on optimizing StackTraceElement.toString() only -- additional changes can follow on in subsequent PRs.

I tested out a couple alternative implementations, and have currently landed on precomputing the StringBuilder capacity as seen in current state of this PR (commit aca4428 ). This shaves a bit more off the StackTraceElementBench.toString microbenchmark compared to not precomputing the StringBuilder capacity. The trade off is more readability and more complex code as there are 2 passes -- one to precompute length and one to build the resulting String.

Benchmark                               Mode  Cnt       Score     Error  Units
StackTraceElementBench.printStackTrace  avgt   15  143218.862 ± 840.141  ns/op
StackTraceElementBench.toString         avgt   15      66.566 ±   0.288  ns/op

Alternately, I computed the length and collected into a char[] then converted to String as seen in commit de0a337 . This ends up similar to the presized StringBuilder, with even more complex code, so doesn't seem worth going that route.

Benchmark                               Mode  Cnt       Score      Error  Units
StackTraceElementBench.printStackTrace  avgt   15  133324.365 ± 1133.849  ns/op
StackTraceElementBench.toString         avgt   15      68.701 ±    1.574  ns/op

I did not write up an implementation to buffer & encode to a byte[] and create a resulting string from that via the String constructors or newStringUTF8NoRepl. I'm not sure that paying the complexity of UTF-16 handling directly would be worth improvement removing the char[] -> byte[] conversion & copy, especially in most common case of Latin 1 StackTraceElement contents.

@stsypanov
Copy link
Contributor

@schlosna I've filed https://bugs.openjdk.org/browse/JDK-8291641 for this. Please use id 8291641 and rename the ticket to 8291641: Optimize StackTraceElement.toString()

@schlosna schlosna changed the title [patch] Optimize StackTraceElement.toString() 8291641: Optimize StackTraceElement.toString() Aug 1, 2022
@openjdk openjdk bot added the rfr Pull request is ready for review label Aug 1, 2022
@mlbridge
Copy link

mlbridge bot commented Aug 1, 2022

@merykitty
Copy link
Member

Since constructing a String from a StringBuilder requires an array copy anyway, you don't need to be exact in the capacity of the builder and overshooting is fine. This can simplify the length calculation a lot. Thanks.

@openjdk-notifier
Copy link

@schlosna Please do not rebase or force-push to an active PR as it invalidates existing review comments. All changes will be squashed into a single commit automatically when integrating. See OpenJDK Developers’ Guide for more information.

@schlosna
Copy link
Contributor Author

schlosna commented Aug 2, 2022

Good call @merykitty , I updated with my take on simplifying the length estimate, let me know if that reads better.

JMH as of d3774a6 for comparison to previous, so still a ~50% improvement over existing state on my x64 test environment (Intel(R) Xeon(R) Platinum 8259CL CPU @ 2.50GHz).

Benchmark                               Mode  Cnt       Score     Error  Units
StackTraceElementBench.printStackTrace  avgt   15  144011.319 ± 959.263  ns/op
StackTraceElementBench.toString         avgt   15      67.874 ±   0.485  ns/op

Copy link
Member

@merykitty merykitty left a comment

Choose a reason for hiding this comment

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

Otherwise looks good to me, thanks

+ declaringClass.length() + 1
+ methodName.length() + 1
+ Math.max("Unknown Source".length(), Objects.requireNonNullElse(fileName, "").length()) + 1
+ Integer.stringSize(lineNumber) + 1;
Copy link
Member

Choose a reason for hiding this comment

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

Integer.stringSize(lineNumber) can be further simplify to 11

Copy link
Contributor Author

Choose a reason for hiding this comment

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

inlined as 12 (combined with 1 for trailing ))

@RogerRiggs
Copy link
Contributor

Are there existing tests that validate the formatted results?
If so, add this bug id to @bug tag of each test.
If not, please add a test.

@schlosna
Copy link
Contributor Author

schlosna commented Aug 2, 2022

Thanks @RogerRiggs , I added the bug ID to the existing StackTraceElement SerialTest which validates the structure of StackTraceElement.toString()

* @bug 6479237 8291641
* @summary Test the format of StackTraceElement::toString and its serial form

Copy link
Contributor

@RogerRiggs RogerRiggs left a comment

Choose a reason for hiding this comment

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

LGTM

@openjdk
Copy link

openjdk bot commented Aug 2, 2022

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

8291641: Optimize StackTraceElement.toString()

Reviewed-by: rriggs, mchung

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

  • cb37282: 8291752: AArch64: Remove check_emit_size parameter from trampoline_call
  • 37d3146: 8289002: Minimal x86_64 VM build fails with GCC 11: 'this' pointer is null
  • ecfa38f: 8281966: Absolute path of symlink is null in JFileChooser
  • 83dc2e3: 8292062: misc javax/swing tests failing
  • 4913380: 8292007: Do not include vmSymbol.hpp in method.hpp
  • 6397d56: 8151430: (fs) BasicFileAttributeView.setTimes should support setting file create time on OS X
  • 57e0da1: 8292132: ProblemList jdk/internal/misc/TerminatingThreadLocal/TestTerminatingThreadLocal.java
  • 17c77b5: 8292119: ProblemList java/awt/image/multiresolution/MultiresolutionIconTest.java on linux-x64 and windows-all
  • d889264: 8290836: Improve test coverage for XPath functions: String Functions
  • ae1a9a0: 8292060: Make ClassFileVersionTest.java version adapting
  • ... and 25 more: https://git.openjdk.org/jdk/compare/ae52053757ca50c4b56989c9b0c6890e504e4088...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 (@RogerRiggs, @mlchung) 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).

@openjdk openjdk bot added the ready Pull request is ready to be integrated label Aug 2, 2022
@schlosna
Copy link
Contributor Author

schlosna commented Aug 2, 2022

/integrate

@openjdk openjdk bot added the sponsor Pull request is ready to be sponsored label Aug 2, 2022
@openjdk
Copy link

openjdk bot commented Aug 2, 2022

@schlosna
Your change (at version c93ac5a) is now ready to be sponsored by a Committer.

@openjdk openjdk bot removed the sponsor Pull request is ready to be sponsored label Aug 6, 2022
@schlosna
Copy link
Contributor Author

schlosna commented Aug 6, 2022

/integrate

@openjdk openjdk bot added the sponsor Pull request is ready to be sponsored label Aug 6, 2022
@openjdk
Copy link

openjdk bot commented Aug 6, 2022

@schlosna
Your change (at version c9ae389) is now ready to be sponsored by a Committer.

@@ -355,27 +354,46 @@ public boolean isNativeMethod() {
* @revised 9
* @see Throwable#printStackTrace()
*/
@Override
Copy link

@maxmielchen maxmielchen Aug 8, 2022

Choose a reason for hiding this comment

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

The override makes no difference.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

ack. I can remove if necessary, but stylistically prefer to mark overridden methods as such (and automatically enforce via static analysis )

Copy link
Member

@mlchung mlchung 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. Minor suggestions.

+ Objects.requireNonNullElse(moduleVersion, "").length() + 1
+ declaringClass.length() + 1
+ methodName.length() + 1
+ Math.max("Unknown Source".length(), Objects.requireNonNullElse(fileName, "").length()) + 1
Copy link
Member

Choose a reason for hiding this comment

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

I suggest to define a static variable = "Unknown Source" be used here and line 387. Same for "Native Method" which can also be accounted for.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

pulled out to private static final fields

if (!dropClassLoaderName() && classLoaderName != null &&
!classLoaderName.isEmpty()) {
s += classLoaderName + "/";
int estimatedLength = Objects.requireNonNullElse(classLoaderName, "").length() + 1
Copy link
Member

Choose a reason for hiding this comment

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

Nit: suggest to refactor this and define a private static length(String s) method.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

updated

@openjdk openjdk bot removed the sponsor Pull request is ready to be sponsored label Aug 9, 2022
@schlosna
Copy link
Contributor Author

/integrate

@openjdk openjdk bot added the sponsor Pull request is ready to be sponsored label Aug 10, 2022
@openjdk
Copy link

openjdk bot commented Aug 10, 2022

@schlosna
Your change (at version 5bdc66f) is now ready to be sponsored by a Committer.

@mlchung
Copy link
Member

mlchung commented Aug 10, 2022

/sponsor

@openjdk
Copy link

openjdk bot commented Aug 10, 2022

Going to push as commit 9825c33.
Since your change was applied there have been 35 commits pushed to the master branch:

  • cb37282: 8291752: AArch64: Remove check_emit_size parameter from trampoline_call
  • 37d3146: 8289002: Minimal x86_64 VM build fails with GCC 11: 'this' pointer is null
  • ecfa38f: 8281966: Absolute path of symlink is null in JFileChooser
  • 83dc2e3: 8292062: misc javax/swing tests failing
  • 4913380: 8292007: Do not include vmSymbol.hpp in method.hpp
  • 6397d56: 8151430: (fs) BasicFileAttributeView.setTimes should support setting file create time on OS X
  • 57e0da1: 8292132: ProblemList jdk/internal/misc/TerminatingThreadLocal/TestTerminatingThreadLocal.java
  • 17c77b5: 8292119: ProblemList java/awt/image/multiresolution/MultiresolutionIconTest.java on linux-x64 and windows-all
  • d889264: 8290836: Improve test coverage for XPath functions: String Functions
  • ae1a9a0: 8292060: Make ClassFileVersionTest.java version adapting
  • ... and 25 more: https://git.openjdk.org/jdk/compare/ae52053757ca50c4b56989c9b0c6890e504e4088...master

Your commit was automatically rebased without conflicts.

@openjdk openjdk bot added the integrated Pull request has been integrated label Aug 10, 2022
@openjdk openjdk bot closed this Aug 10, 2022
@openjdk openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review sponsor Pull request is ready to be sponsored labels Aug 10, 2022
@openjdk
Copy link

openjdk bot commented Aug 10, 2022

@mlchung @schlosna Pushed as commit 9825c33.

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

@schlosna schlosna deleted the ds/StackTraceElement branch August 10, 2022 17:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
core-libs core-libs-dev@openjdk.org integrated Pull request has been integrated
Development

Successfully merging this pull request may close these issues.

7 participants