Feature request: add unique object ID to -Xtrace constructor output and make available in DTFJ

[kgibm]

As background, -Xtrace method trace on a class constructor along with a jstacktrace trigger is a great way to find who is leaking something. This is particularly useful for issues such as objects that aren't closed by an application properly and end up accumulating in a finalizer list so that it's difficult to figure out who created or owns the objects by the time of the OOM as they're all just GC roots waiting to be finalized. For example with socket objects:

-Xtrace:print=mt,methods=com/ibm/jsse2/av.<init>(),trigger=method{com/ibm/jsse2/av.<init>,jstacktrace}

Leads to:

08:43:59.307 0x1f799048200              mt.1        > com/ibm/jsse2/av.<init>([CII)V compiled method, this = 0x7ff42cb57ef8
08:43:59.307 0x1f799048200       j9trc_aux.0        - jstacktrace:
08:43:59.307 0x1f799048200       j9trc_aux.1        - [1] com.ibm.jsse2.av.<init> (av.java:12) (Compiled Code)
[...]
08:43:59.307 0x1f799048200              mt.7        < com/ibm/jsse2/av.<init>([CII)V compiled method

Often, this data alone is enough to determine the leaker through statistical inference (i.e. aggregating by the top stack frames after the constructor and sorting by the aggregate count); however, we've hit an issue where there are hundreds of unique callers and such an inference search has not been fruitful.

It would be nice if the -Xtrace method entry line of the constructor printed a globally unique identifier for the object which was then made available through DTFJ. This would allow, for example, a jdmpview or MAT query which then listed all the objects in the finalizer list with their unique identifier and that would allow easy correlation to the -Xtrace jstacktraces.

Currently, the -Xtrace method entry line prints the object address but this may be moved by the GC so it's not helpful for this example because by the time of the OOM, it has almost surely been moved by the GC (e.g. from nursery into tenured).

I know that the object's identity hash code is available from DTFJ, if it has been previously calculated at runtime, but I believe this would just be the result of the hashCode of the object which may not be unique.

I'm imagining output something like this with new output at the end of the line:

08:43:59.307 0x1f799048200              mt.1        > com/ibm/jsse2/av.<init>([CII)V compiled method, this = 0x7ff42cb57ef8 (unique ID ZZZZZ)

And then a DTFJ API on the JavaObject to get this unique ID.

This might require something like a GUID generator which might not be cheap but this would presumably only be called lazily by diagnostics such as -Xtrace so it should not have much performance impact, although I can imagine adding a field to the JavaObject might affect memory and cache utilization.

[georgejxu]

do we need to consider multiple constructor situation? agree performance is not a concern and we only track certain object so the scope is small.

[DanHeidinga]

JVMTI already gives you the capability to associate tags with objects - https://docs.oracle.com/javase/7/docs/platform/jvmti/jvmti.html#SetTag

If performance isn't a concern, then this can be handled by writing an agent that uses capabilities already present in jvmti

[kgibm]

@DanHeidinga Interesting, thanks Dan. We would still like the integration into -Xtrace to print that tag as otherwise we're back to the same point of no way to correlate GC roots on a finalizer list to -Xtrace jstacktrace. Maybe -Xtrace itself could call the SetTag lazily on the constructor.

@georgejxu Each -Xtrace method entry line is unique for each instantiation.

[pshipton]

@keithc-ca @tajila fyi. I've assigned it to the backlog for now.

[DanHeidinga]

@kgibm Once you're in the land of jvmti, it's infinitely more powerful than what trace can do which means you have complete control on what you want logged at each site.

Adding tags to objects - and printing them - is significantly beyond the intended design of -Xtrace. It's meant to be a lightweight tracing mechanism, not replace JVMTI functionality.

That said, if you developed an agent that was able to do the tagging, tracing, and reporting, we could look at including it in OpenJ9 similar to the support historically provided for -Xhealthcenter (which maps to an agent as well)

[kgibm]

@DanHeidinga The JVMTI agent could do the tagging and print the stacks on method entry, but then we would have to rewrite many parts -Xtrace such as allowing the user to specify the methods to trace (with wildcards), the various triggers (for this use case, only jstacktrace is needed, but I could imagine where other dump types would be useful), the low-overhead method trace output files, rolling of those files, etc.

Is the issue with adding this to -Xtrace that the trace engine doesn't immediately have access to a JVMTI-like context (with setTag/getTag)?

I was imagining something like this additional logic in Xtrace:

if method is constructor
  uuid = getTag(obj)
  if uuid is null
    uuid = generateUUID()
    setTag(obj, uuid)
  end
  printf("> %s, this = 0x%x (unique ID 0x%x)", methodName, objAddress, uuid)
end

[georgejxu]

I guess uuid does not get into the core, right? and would be nice if we have that. or still relies on address and method name.

[kgibm]

@georgejxu Right, unless there exists UUID code we would need to add that, so I didn't mean to imply that this would be a trivial change, but it seems surgical enough.

[DanHeidinga]

I believe there are extensions for controlling trace from jvmti. I think all the pieces are there they just need to be put together in the right sequence.

edit: add link to jvmti references https://www.eclipse.org/openj9/docs/interface_jvmti/

[georgejxu]

I am hoping that we can generate an UI id from the existing information into the trace, and we can do the same thing in dtfj to generate the same information (aka an ID)... this way, we can avoid to inject information into the core itself. Maybe this is easier or if it is possible.?

[kgibm]

@georgejxu I think what Dan is proposing is to have a separate agent which hooks into specified constructors, creates the UUID, sets the tag, prints out the tag to address mapping to trace, and then enable that custom tracepoint along with method entry for the specified constructors and jstacktrace trace points. Then we can correlate the UUID to the object address, and then correlate the object address to the -Xtrace output, and then correlate that to the jstacktrace. I'm presuming the tag will then be available through DTFJ in a core dump.

[georgejxu]

thanks @DanHeidinga ! got it @kgibm