Dynamic method tracing in in Java


Are you a printf debugger? I certainly am. IDE based Debuggers (or tools like jdb / gdb) have their place, and I use them a lot too. But I often want to know when and why some function is called in contexts where attaching a debugger isn't an option.

As one example, a lot of people at my current company use IntelliJ / Android Studio. Like other large companies, we have a gigantic monorepo. Understanding how and why the IDE accesses the filesystem can help us understand performance problems. Everyone experiences slightly different behavior with the filesystem depending on what has been changed, and what's being cached. I'd like to turn on verbose logging of filesystem operations remotely for particular users so we can diagnose issues they're having, and I want to do this in a way that doesn't degrade performance.

Just add logging (or println!)

This is often a simple and good choice, although it often leads to this kind of thing:

`public void doSomethingInteresting(Thingy t) { if (Config.shoudLogInterestingThings()) { LOG.info("doSomethingInteresting(%s)", t); }

// Actually do something interesting }`

That's ok, it's not too onerous. You need to know where you want to add logging upfront before you deploy your app. If you want to change the places where you log dynamically, you're going to have to redeploy your app. Also, if the calls you want to log are not in code owned by you (e.g. in an upstream library, or the JDK itself), this approach may be difficult and require you to build a third party library from source with modifications.

Just use dtruss / strace?

Tools like strace or dtruss monitor system calls. Brendan Gregg details many useful dtrace recipes he wrote in dtrace scripts that ship with Mac OS X for monitoring this kind of thing. You can use dtruss to monitor system I/O calls like stat64().

One problematic thing with this approach on Mac OS X is that these trace scripts need to run as root. In addition, you must turn off system integrity protection for them to yield useful results. This is fine if you're just debugging locally on your own machine. But you can't really do that remotely on people's machines.

Another problem is that often the output of dtruss is voluminous, and there's little context about where system calls were invoked from up at the Java level.

Enter jvmti!

Java has a number of tools that can be used to instrument or inspect code execution in a running VM. You can write a Java-based instrumentation agent to intercept class loading and rewrite the instructions in a class before it is used. I'll cover some interesting examples of using this in a future blog post.

The Java Platform Debugger Architecture (JPDA) includes tools that also make inspecting and manipulating a running VM possible. The high level Java Debug Interface (JDI) is the main way to integrate a debugger into the VM. It communicates with a remote VM using the Java Debug Wire Protocol (JDWP).

That's an awful lot of acronyms. I'm going to mention one more: the Java Virtual Machine Tool Interface (JVMTI) which is the low level foundation of the JPDA, and which is used by the standard implementation of JDWP in the JVM. JVMTI has a number of functions, but useful to our problem is the ability register and be notified when breakpoints occur, and inspect the state of the running VM.

Configurable debugging

My goal was to be able to control method logging with a small configuration file that could be updated on developers machines independent of binary rollouts. Imagine I have some super simple code that looks like this:

`package frodo;

public class Example { public static void main(String[] args) { new Test().run(); }

public void run() { System.out.println(someMethod(new RealFile("/foo"))); System.out.println(someMethod(new RealFile("/bar"))); }

public String someMethod(RealFile file) { return "Hello " + file.getPath(); }

private static class RealFile { private final String path;

RealFile(String path) { this.path = path; }

public String getPath() { return path; }

public String toString() {
  return "A file called " + getPath();

} }`

I'd like to turn on logging for someMethod with a configuration like this:

`# This is the class I care about

  • frodo/Test

    And this is a method I want to log with its super ugly JVM signature

    • someMethod(Lfrodo/Test$RealFile;)Ljava/lang/String;

      Please show me an abbreviated stack trace for each call

      • showTrace: true

        And use the getPath() method to convert the parameter to a String

      • displayMethod: getPath`

This would log the following output for the above example:

someMethod: /foo trace: <- someMethod <- run <- main someMethod: /bar trace: <- someMethod <- run <- main

There are lots of ways this can be extended to be more flexible / configurable, but this is enough for the basic requirement.

Part 2 of this blog post, dives into the implementation of this jvmti agent. You can find the code for this tool in github.