RFR: 8333182: Add truncated tracing mode for TraceBytecodes

[Coleen Phillimore]

On Wed, 29 May 2024 15:37:07 GMT, Claes Redestad <redestad at openjdk.org> wrote:

> 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](https://github.com/cl4es/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.

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 line 99:

> 97:   void trace(const methodHandle& method, address bcp, uintptr_t tos, uintptr_t tos2, outputStream* st) {
> 98:     ResourceMark rm;
> 99:     bool methodChange = _current_method != method();

nit, can you change this variable name to method_changed for the C++ coding style.

-------------

Marked as reviewed by coleenp (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/19457#pullrequestreview-2091075004
PR Review Comment: https://git.openjdk.org/jdk/pull/19457#discussion_r1622558243