Tag: traceformat

Using Java internal trace

I was trying to understand a class load problem, and needed to use Java internal virtual machine trace to see what was happening.

You specify -Xtrace options at start up. Even with limiting options, I had over 2 millions lines of trace output – and the Java application had not fully started!

There are lots of components you can specify see here. I used

 -Xtrace:maximal={j9jcl,j9shr,j9prt,omrport},output=/u/tmp/java/trace.bin

where

  • j9jcl is Java class libraries
  • j9shr is shared classes libraries
  • j9prt is VM port libraries… the platform specific (ported) code
  • omrport is the OMR ported code. (OMR is a set of common components, such as threads and garbage collection)

I haven’t used it,but you can say do something when this trace point is triggered, stop (suspend) tracing.

-Xtrace:trigger=tpnid{abc.123,suspend}

In the example trace output

07:49:24.699384689 0x000000002167f200 omrport.657 Event J9 VM NLS message: Failed to find class org/springframework/boot/loader/launch/PropertiesLauncher in shared cache for class-loader id 0.

where the trace point is omrport.657

You can put the definitions in a file -Xtrace:properties=<filename>

I have a trace file – now what?

You can format the trace file on z/OS, but I downloaded the file (in binary) to my Linux machine, because a) I have more disk space, 2) the java formatting is faster, 3) I have better tools to look at the data. You need the save level of Java (or better) to format all the fields. If there is a mismatch, some fields will not be formatted. The traceformat command is described here.

Format the data

/home/colinpaice/Downloads/jdk-21.0.6+7/bin/traceformat -verbose trace.bin trace.txt

It produced

Writing formatted trace output to file trace.txt
Processing 245.45312Mb of binary trace data
Processed 10.0Mb (4%), burst speed: 1.9344624Mb/s, average: 1.9344624Mb/s
Processed 20.0Mb (8%), burst speed: 2.4675941Mb/s, average: 2.1687446Mb/s
Processed 30.0Mb (12%), burst speed: 3.4868424Mb/s, average: 2.4814205Mb/s
...

I wrote the blog post Finding the needle in a field of hay, to help extract the records of interest.

On the traceformat command you can specify

  • -indent: Indents trace messages at each Entry trace point and outdents trace messages at each Exit trace point. The default is not to indent the messages.
  • -threads: Filters the output for the given thread IDs only. thread id is the ID of the thread, which can be specified in decimal or hex (0x) format. Any number of thread IDs can be specified, separated by commas.

Looking at the data

I used the commands grep -n …., tail -n +999, head -n 500, less as described here. But for detailed analysis I piped the output into a file, and used an editor on the output. This meant the lines did not wrap, I could annotate (and save) the trace, and highlight interesting records.

Because some of the lines are very long, I split interesting lines so all of the data was displayed in the window, and I did not need to scroll.