Feature Request: Provide a means to capture contents of String arguments and return values with Xtrace

[paulcheeseman]

It's not currently possible to capture the contents of String arguments and return values when tracing methods with Xtrace. All you get is the address of the String object.

For example:

11:19:45.789 0x8aff00              mt.0            > java/lang/String.equals(Ljava/lang/Object;)Z bytecode method, this = 0xdfff3d68
11:19:45.789 0x8aff00              mt.18            - this: java/lang/String@00000000DFFF3D68 method arguments: (java/lang/String@00000000DFFF3D90)

and:

11:21:37.654 0x8aff00              mt.6            < java/lang/StringBuilder.toString()Ljava/lang/String; bytecode method
11:21:37.654 0x8aff00              mt.28           - return value: java/lang/String@00000000FFF2C408

There are many situations in which it would be useful to be able to capture the actual contents of the String objects - something like this, for example:

11:19:45.789 0x8aff00              mt.0            > java/lang/String.equals(Ljava/lang/Object;)Z bytecode method, this = 0xdfff3d68
11:19:45.789 0x8aff00              mt.18            - this: java/lang/String@00000000DFFF3D68[Hello world] method arguments: (java/lang/String@00000000DFFF3D90[Hello World])

The only alternatives right now are to modify the application code (to add println() calls), either by changing the source code and rebuilding or instrumenting the code with an agent, or to trigger a core dump on the relevant method call and retrieve the String(s) from that.

I suspect there would be a significant performance cost associated with retrieving the String contents, so this certainly isn't something that we would want to enable by default, but it would be great to have the option. The alternative approaches are almost certainly costlier - modifying application code is typically not trivial (especially in production), third party code often cannot be modified at all, and writing a core dump typically suspends the application for at least several seconds.

It might also be useful to be able to trace the contents of primitive arrays as well (e.g. char[] and byte[]).

It's very likely that this functionality has been considered and rejected in the past, but I couldn't find any previous conversations on this topic. In the worst case this Github issue can at least provide a record of why this isn't feasible.

[pshipton]

@keithc-ca @tajila fyi

[gacholio]

The immediate problem I see with this is that the string data may be huge. I don't know that tracepoints can handle data that's larger than the trace buffer blocks.

[keithc-ca]

We already have Trc_BCU_internalDefineClass_FullData which captures the bytecode for an entire class.
We could capture the length and a prefix of strings, byte and char arrays (with an option to control the length of that prefix).

[paulcheeseman]

The immediate problem I see with this is that the string data may be huge. I don't know that tracepoints can handle data that's larger than the trace buffer blocks.

Yes, I thought that might be a problem too.

We could capture the length and a prefix of strings, byte and char arrays (with an option to control the length of that prefix).

Yes, I was thinking of something similar to how strace's -s option works, e.g. with the default string length of 32:

21927 write(3, "0x7F\n", 5)             = 5
21927 write(2, "java version \"1.8.0_321\"", 24) = 24
21927 write(2, "\n", 1)                 = 1
21927 write(2, "Java(TM) SE Runtime Environment "..., 84) = 84
21927 write(2, "\n", 1)                 = 1
21927 write(2, "IBM J9 VM (build 2.9, JRE 1.8.0 "..., 172) = 172
21927 write(2, "\n", 1)                 = 1
21927 write(2, "JCL - 20220120_01 based on Oracl"..., 46) = 46
21927 write(2, "\n", 1)                 = 1

I guess the maximum string length would be about the same size as the thread's trace buffer (probably slightly smaller)?

[jasonkatonica]

We have a client who we are trying to help audit their use of cryptography. We wanted to print the algorithm passed into a particular method to create a very primative audit trace.

In this case we wanted to audit the javax/crypto/Cipher.getInstance(String) method and print the String value passed as an argument to the method. I have had some success with a trace similar to follows :

-Xtrace:'print=mt,maximal=mt,trigger=method{javax/crypto/Cipher.getInstance,jstacktrace}' -Xjit:'exclude={javax/crypto/},dontinline={javax/crypto/}' PKCS12Example.java

which results in something like the following:

16:33:43.659*0x17000              mt.3        > javax/crypto/Cipher.getInstance(Ljava/lang/String;)Ljavax/crypto/Cipher; bytecode static method
16:33:43.660 0x17000       j9trc_aux.0        - jstacktrace:
16:33:43.660 0x17000       j9trc_aux.1        - [1] javax.crypto.Cipher.getInstance (Cipher.java:534)
16:33:43.660 0x17000       j9trc_aux.1        - [2] sun.security.pkcs12.PKCS12KeyStore.lambda$engineLoad$1 (PKCS12KeyStore.java:2086)
16:33:43.660 0x17000       j9trc_aux.1        - [3] sun.security.pkcs12.PKCS12KeyStore$$Lambda.0x0000000000000000.tryOnce (Bytecode PC: 13)
16:33:43.660 0x17000       j9trc_aux.1        - [4] sun.security.pkcs12.PKCS12KeyStore$RetryWithZero.run (PKCS12KeyStore.java:257)
16:33:43.660 0x17000       j9trc_aux.1        - [5] sun.security.pkcs12.PKCS12KeyStore.engineLoad (PKCS12KeyStore.java:2084)
16:33:43.660 0x17000       j9trc_aux.1        - [6] sun.security.util.KeyStoreDelegator.engineLoad (KeyStoreDelegator.java:228)
16:33:43.660 0x17000       j9trc_aux.1        - [7] java.security.KeyStore.load (KeyStore.java:1500)
16:33:43.660 0x17000       j9trc_aux.1        - [8] com.ibm.example.pkcs12.PKCS12Example.main (PKCS12Example.java:18)
16:33:43.660 0x17000       j9trc_aux.1        - [9] java.lang.invoke.LambdaForm$DMH.0x000000005032ba10.invokeStatic (LambdaForm$DMH)
16:33:43.660 0x17000       j9trc_aux.1        - [10] java.lang.invoke.LambdaForm$MH.0x00000000506f65b0.invoke (LambdaForm$MH)
16:33:43.660 0x17000       j9trc_aux.1        - [11] java.lang.invoke.LambdaForm$MH.0x00000000506f6b50.invokeExact_MT (LambdaForm$MH)
16:33:43.660 0x17000       j9trc_aux.1        - [12] jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl (DirectMethodHandleAccessor.java:154)
16:33:43.660 0x17000       j9trc_aux.1        - [13] jdk.internal.reflect.DirectMethodHandleAccessor.invoke (DirectMethodHandleAccessor.java:103) (Compiled Code)
16:33:43.660 0x17000       j9trc_aux.1        - [14] java.lang.reflect.Method.invoke (Method.java:586)
16:33:43.660 0x17000       j9trc_aux.1        - [15] com.sun.tools.javac.launcher.Main.execute (Main.java:484)
16:33:43.660 0x17000       j9trc_aux.1        - [16] com.sun.tools.javac.launcher.Main.run (Main.java:208)
16:33:43.660 0x17000       j9trc_aux.1        - [17] com.sun.tools.javac.launcher.Main.main (Main.java:135)
16:33:43.674 0x17000              mt.9        < javax/crypto/Cipher.getInstance(Ljava/lang/String;)Ljavax/crypto/Cipher; bytecode static method

However this does not print out the actual arguments to the method which we are attempting to record so we were unable to achieve our goal. The feature request in this issue would allow us to do this.

[h3110n3rv3]

@tajila