Skip to main content

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.

Comments

Popular posts from this blog

Java Blooper #2: Must be a Better Way...

The post you're reading is ancient, and yet slightly inexplicably popular :) I've recently started blogging again in 2020 with some fresh content. Check out some of the new topics about blogging again, dynamic method invocation, and aapt2.It's Monday, which means it's time for another blooper... What's wrong with this code? boolean hasThing( List things, Thing thing ) { for ( int i=0; i < things.size(); i++ ) { if ( thing.equals( things.get( i ) ) ) { return true; } } return false; } Update: Minor edit to add missing parenthesis from if statement that got "lost in translation" en-route to the blog :)

Configuring Mac OS X Terminal

The post you're reading is ancient, and yet slightly inexplicably popular :) I've recently started blogging again in 2020 with some fresh content. Check out some of the new topics about blogging again, dynamic method invocation, and aapt2.I recently installed Leopard (Mac OSX 10.5) on a new mac. There are a few factory settings I usually change on a new installation, although by far fewer than I do typically with Windows. One of them is the default keyboard configuration for Ctrl+Left Arrow, Ctrl+Right Arrow, Page Up, Page Down, Home, and End in Terminal. The default settings drive me a bit potty since I'm used to using Linux and emacs every day at work.Changing them is easy, fortunately. Just visit Keyboard under Settings in Terminal->Preferences, and modify the following keys, so that their action matches the value shown. You can edit the keystroke for an item by double clicking on it, selecting "send string to shell", and typing the indicated keys.KeyActio…

Java Blooper #1: Ternary Insanity

The post you're reading is ancient, and yet slightly inexplicably popular :) I've recently started blogging again in 2020 with some fresh content. Check out some of the new topics about blogging again, dynamic method invocation, and aapt2.From time to time, we all write code that could be clearer. Sometimes in the rush of solving a problem, we don't pay attention to the micro details of the code flowing from our fingertips. Other times, we refactor some existing code, and don't necessarily take the opportunity to clean up as much as we could.I find it useful sometimes when reading code to think about whether it could be rewritten in a more straightforward way, and if so whether any lessons can be learned about writing tight and expressive, and most importantly, readable code.Over the next few weeks, I'm going to blog weekly examples of some Java code bloopers that I've seen. All the examples are real and have been observed "in the wild". However some…