8333182: Add truncated tracing mode for TraceBytecodes #19457

cl4es · 2024-05-29T15:37:07Z

We routinely use -XX:+TraceBytecodes to instrument what's going on during application startup. However, much of the information traced in this mode is not really used, and adding a mode which truncates non-relevant information would be helpful to speed up instrumentation, especially on larger apps.

To illustrate, running -XX:+TraceBytecodes on a version of netty can produce more than 844MB of output:

14759490 bytecodes executed in 151.1s (0.098MHz)
[BytecodeCounter::counter_value = 14759531]

A sample output block looks like this:

[34051] static jobject sun.reflect.annotation.AnnotationParser.parseAnnotations2(jobject, jobject, jobject, jobject)
[34051] 14759490    58  astore #9
[34051] 14759491    60  aload #9
[34051] 14759492    62  invokestatic 57 
... 19 more lines
[34051] 14759512    41  invokestatic 47 <sun/reflect/annotation/AnnotationParser.parseAnnotation2(Ljava/nio/ByteBuffer;Ljdk/internal/reflect/ConstantPool;Ljava/lang/Class;Z[Ljava/lang/Class;)Ljava/lang/annotation/Annotation;> 

[34051] static jboolean sun.reflect.annotation.AnnotationParser.contains(jobject, jobject)
[34051] 14759513     0  nofast_aload_0
[34051] 14759514     1  astore_2
[34051] 14759515     2  aload_2
...

This PR add a develop flag, TraceBytecodesTruncated meant to be used in addition to TraceBytecodes. It has the effect that all but the first bytecode in each method transition as well as returns and throws will be omitted. With the patch the output may look like this:

[42243] static jobject sun.reflect.annotation.AnnotationParser.parseAnnotations2(jobject, jobject, jobject, jobject)
[42243] 14858715    58  astore

[42243] static jboolean sun.reflect.annotation.AnnotationParser.contains(jobject, jobject)
[42243] 14858737     0  nofast_aload_0
[42243] 14858772    35  ireturn

This truncated output is sufficient for certain purposes such as when digesting the output with bytestacks.

Running the same application with the patch and the added flag, -XX:+TraceBytecodes -XX:+TraceBytecodesTruncated generates a file that is 177MB, and in about a third of the time:

14867664 bytecodes executed in 52.4s (0.284MHz)
[BytecodeCounter::counter_value = 14867704]

This enhancement would greatly speed up some of our diagnostics, and enable using these tools on even larger apps.

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-8333182: Add truncated tracing mode for TraceBytecodes (Enhancement - P4)

Reviewers

David Holmes (@dholmes-ora - Reviewer)
Frederic Parain (@fparain - Reviewer) ⚠️ Review applies to cab354e9
Coleen Phillimore (@coleenp - Reviewer) ⚠️ Review applies to cab354e9

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 19457

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

Using diff file

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

Webrev

Link to Webrev Comment

bridgekeeper · 2024-05-29T15:38:06Z

👋 Welcome back redestad! 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 · 2024-05-29T15:38:56Z

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

8333182: Add truncated tracing mode for TraceBytecodes

Reviewed-by: dholmes, fparain, coleenp

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

8338946: 8332935: Crash: assert(*lastPtr != 0) failed: Mismatched JNINativeInterface tables, check for new entries
4785461: 7022325: TEST_BUG: test/java/util/zip/ZipFile/ReadLongZipFileName.java leaks files if it fails
2453002: 8331977: Crash: SIGSEGV in dlerror()
51b2f80: 8332923: ObjectMonitorUsage.java failed with unexpected waiter_count
d29d5bf: 8333290: NMT report should not print Metaspace info if Metaspace is not yet initialized
c0ce7d8: 8333046: Clean codes in sun.security.util.math
10eb1cb: 8331879: Clean up non-standard use of /// comments in java.base
2cae9a0: 8314480: Memory ordering spec updates in java.lang.ref
9fd0e73: 8332110: [macos] jpackage tries to sign added files without the --mac-sign option
8aeada1: 8331159: VM build without C2 fails after JDK-8180450
... and 51 more: https://git.openjdk.org/jdk/compare/43a2f17342af8f5bf1f5823df9fa0bf0bdfdfce2...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 · 2024-05-29T15:39:18Z

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

hotspot-runtime

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.

mlbridge · 2024-05-29T15:43:10Z

Webrevs

01: Full - Incremental (9d9dd986)
00: Full (cab354e9)

dholmes-ora

I was surprised not to find a RFE to convert TraceBytecodes to Unified Logging. That would solve your problem as you could just reclassify the too-verbose "logging" statements. Not to put you on-the-spot @cl4es but do you have a sense for how difficult a conversion to UL would be? :)

cl4es · 2024-05-30T08:16:59Z

The tracer code isn't all that large or convoluted, but some of the printing code is shared with Method::print_codes_on, which is used in a number of places in product code. Some of the use cases of that, like the one in idealGraphPrinter.cpp, doesn't seem easily portable to UL since we're streaming the output into some XML document. Of course we could disentangle all that if we accept a bit of code duplication.

Porting to UL also adds a bit of (optional) logging to each line, growing the output and requiring parser changes. Perhaps there are some ways to tame UL to output exactly - or almost exactly - the same thing, but regardless it definitely complicates parsing. That also begs the question if we need to retain -XX:+TraceBytecodes and the exact format it outputs in case there are other consumers out there. I don't know.

I don't have a strong opinion. I do really want this feature in ASAP (to speed up my work and make the startup tracing useful on larger apps), but I have no idea how high of a priority it is to port this to UL.

dholmes-ora

Okay it sounds like UL is not a feasible short term solution here., so being able to truncate the verbose output seems reasonable.

cl4es · 2024-05-31T08:20:00Z

Thanks!

cl4es · 2024-05-31T14:04:03Z

Any second reviewer for this? Or is it trivial enough to go ahead with one?

coleenp · 2024-05-31T14:26:45Z

Its not really trivial. I'll have a look today.

fparain

LGTM.

coleenp

This seems fine. I had the same question that David did about using UL, but this is simpler. Most of the Trace* options in the runtime were converted to UL but where they have a specific format, it was too cumbersome so we didn't do it.

src/hotspot/share/interpreter/bytecodeTracer.cpp

cl4es · 2024-06-02T20:28:44Z

Thanks for reviewing, everyone!

/integrate

openjdk · 2024-06-02T20:29:04Z

Going to push as commit 769b3e4.
Since your change was applied there have been 61 commits pushed to the master branch:

8338946: 8332935: Crash: assert(*lastPtr != 0) failed: Mismatched JNINativeInterface tables, check for new entries
4785461: 7022325: TEST_BUG: test/java/util/zip/ZipFile/ReadLongZipFileName.java leaks files if it fails
2453002: 8331977: Crash: SIGSEGV in dlerror()
51b2f80: 8332923: ObjectMonitorUsage.java failed with unexpected waiter_count
d29d5bf: 8333290: NMT report should not print Metaspace info if Metaspace is not yet initialized
c0ce7d8: 8333046: Clean codes in sun.security.util.math
10eb1cb: 8331879: Clean up non-standard use of /// comments in java.base
2cae9a0: 8314480: Memory ordering spec updates in java.lang.ref
9fd0e73: 8332110: [macos] jpackage tries to sign added files without the --mac-sign option
8aeada1: 8331159: VM build without C2 fails after JDK-8180450
... and 51 more: https://git.openjdk.org/jdk/compare/43a2f17342af8f5bf1f5823df9fa0bf0bdfdfce2...master

Your commit was automatically rebased without conflicts.

openjdk · 2024-06-02T20:29:09Z

@cl4es Pushed as commit 769b3e4.

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

Add truncated tracing mode for TraceBytecodes

cab354e

openjdk bot added the hotspot-runtime hotspot-runtime-dev@openjdk.org label May 29, 2024

cl4es marked this pull request as ready for review May 29, 2024 15:39

openjdk bot added the rfr Pull request is ready for review label May 29, 2024

dholmes-ora reviewed May 30, 2024

View reviewed changes

dholmes-ora approved these changes May 31, 2024

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label May 31, 2024

fparain approved these changes May 31, 2024

View reviewed changes

coleenp approved these changes May 31, 2024

View reviewed changes

src/hotspot/share/interpreter/bytecodeTracer.cpp Outdated Show resolved Hide resolved

foreign languages

9d9dd98

dholmes-ora approved these changes Jun 2, 2024

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Jun 2, 2024

openjdk bot closed this Jun 2, 2024

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Jun 2, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

8333182: Add truncated tracing mode for TraceBytecodes #19457

8333182: Add truncated tracing mode for TraceBytecodes #19457

cl4es commented May 29, 2024 •

edited by openjdk bot

Loading

bridgekeeper bot commented May 29, 2024

openjdk bot commented May 29, 2024 •

edited

Loading

openjdk bot commented May 29, 2024

mlbridge bot commented May 29, 2024 •

edited

Loading

dholmes-ora left a comment

cl4es commented May 30, 2024

dholmes-ora left a comment

cl4es commented May 31, 2024

cl4es commented May 31, 2024

coleenp commented May 31, 2024

fparain left a comment

coleenp left a comment

cl4es commented Jun 2, 2024

openjdk bot commented Jun 2, 2024

openjdk bot commented Jun 2, 2024

8333182: Add truncated tracing mode for TraceBytecodes #19457

8333182: Add truncated tracing mode for TraceBytecodes #19457

Conversation

cl4es commented May 29, 2024 • edited by openjdk bot Loading

Progress

Issue

Reviewers

Reviewing

Webrev

bridgekeeper bot commented May 29, 2024

openjdk bot commented May 29, 2024 • edited Loading

openjdk bot commented May 29, 2024

mlbridge bot commented May 29, 2024 • edited Loading

Webrevs

dholmes-ora left a comment

Choose a reason for hiding this comment

cl4es commented May 30, 2024

dholmes-ora left a comment

Choose a reason for hiding this comment

cl4es commented May 31, 2024

cl4es commented May 31, 2024

coleenp commented May 31, 2024

fparain left a comment

Choose a reason for hiding this comment

coleenp left a comment

Choose a reason for hiding this comment

cl4es commented Jun 2, 2024

openjdk bot commented Jun 2, 2024

openjdk bot commented Jun 2, 2024

cl4es commented May 29, 2024 •

edited by openjdk bot

Loading

openjdk bot commented May 29, 2024 •

edited

Loading

mlbridge bot commented May 29, 2024 •

edited

Loading