Skip to main content

Dynamic Method Tracing in Java: The Implementation

In the last blog entry, I talked about the need for a tool in Java that can be configured easily to log method calls without redeploying a binary, attaching a debugger, or obtaining root in order to trace system calls. In this blog, I'll dive into some of how the tool was implemented.

A caveat: I knocked this tool together in my spare time one afternoon while working on a bunch of other things, so it's a bit rough around the edges. I'm also not a particularly experienced C programmer, so apologies if my code is a bit rough. 

However, it's already proven useful to me, and hopefully either the tool itself or the approach will be useful to others. I found a general lack of detailed information about using JVMTI when doing research.

OnLoad: Config, capabilities, events, and callbacks

The main entrypoint to a native JVMTI agent is the Agent_OnLoad function. I want to do three main things when my agent is loaded:

  1. Load the configuration file so we know which breakpoints to set.
  2. Let JVMTI know which capabilities the agent needs, and ensure the JVM supports them.
  3. Let JVMTI know I'm interested in receiving events when classes are about to be loaded and when breakpoints occur, and register callback functions for these.

The configuration file's implementation is a bit out of scope for this blog. I wrote a quick, dirty, and exceptionally rough yaml parser in C (yes, I know... I must have been bored). You can look at config.c if you're truly interested in the sordid details of this. But ignoring that, here are the more interesting parts of OnLoad:

  
JNIEXPORT jint JNICALL 
Agent_OnLoad(JavaVM *vm, char *options, void *reserved) {
  char *option = strtok(options, ",");
  // ...
  // Load the config file using options from `option`. Also parse out an option for
  // a log file to write to.
  // .. 
  
  fprintf(stderr, "mlogagent: Loaded agent\n");

  // Get a JVMTI env object, which is used to make function calls into JVMTI
  jvmtiEnv *env;
  assert(JVMTI_ERROR_NONE == (*vm)->GetEnv(vm, (void **)&env, JVMTI_VERSION));

  // Let JVMTI know we are going to be registering breakpoints and accessing local
  // variables. If these capabilities are not supported by the JVM, then the AddCapabilities
  // function will return an error code, and our agent will terminate the VM.
  jvmtiCapabilities capabilities = { 0 };
  capabilities.can_generate_breakpoint_events = 1;
  capabilities.can_access_local_variables = 1;
  assert(JVMTI_ERROR_NONE == (*env)->AddCapabilities(env, &capabilities));

  // Register callbacks for ClassPrepare and Breakpoint events. We'll dig into these callback
  // functions soon.
  jvmtiEventCallbacks callbacks = { 0 };
  callbacks.ClassPrepare = &ClassPrepareCallback;
  callbacks.Breakpoint = &BreakpointCallback;
  assert(JVMTI_ERROR_NONE == (*env)->SetEventCallbacks(env, &callbacks, sizeof(callbacks)));

  // Tell JVMTI to enable breakpoint and class prepare events so our callbacks will be invoked.
  assert(JVMTI_ERROR_NONE == (*env)->SetEventNotificationMode(env, 
    JVMTI_ENABLE, JVMTI_EVENT_BREAKPOINT, NULL));
  assert(JVMTI_ERROR_NONE == (*env)->SetEventNotificationMode(env, 
    JVMTI_ENABLE, JVMTI_EVENT_CLASS_PREPARE, NULL));

  return JNI_OK;
}
  

Registering method breakpoints

The next step is to attach breakpoints to methods we're interested in. We do this when the ClassPrepare event is fired, which happens just before the JVM loads a class. In our case, the implementation of this is a bit complicated by the fact that we have a config file that drives setting the breakpoints, but at the core, we just need to find the class we're interested in, find the method we care about, then attach a breakpoint to it. Here's a simplified version of the code:

  
void JNICALL ClassPrepareCallback(jvmtiEnv *jvmti_env, JNIEnv *jni, jthread thread, jclass klass) {
  // Avoid re-entrancy, and return early if we already attached.
  if (in_prepare || attached) {
    return;
  }
  
  in_prepare = true;

  jclass clazz = (*jni)->FindClass(jni, classConfig->name);
  // In case we don't find the class, don't throw an exception
  (*jni)->ExceptionClear(jni);
  if (clazz != NULL) {
    attachMethodBreakpoint(jvmti_env, jni, clazz);
    (*jni)->DeleteLocalRef(jni, clazz);
    attached = true;
  }

  in_prepare = false;
}

void attachMethodBreakpoint(jvmtiEnv *jvmti_env, JNIEnv *jni, jclass clazz) {
  // Look for the method. Here,
  //    methodName is something like "someMethod"
  //    methodSignature is something like "(Lfrodo/Test$RealFile;)Ljava/lang/String;"
  jmethodID mid = (*jni)->GetMethodID(jni, clazz, methodName, methodSignature);
  if (mid != NULL) {
    // Actually set the method breakpoint
    assert(JVMTI_ERROR_NONE == (*jvmti_env)->SetBreakpoint(jvmti_env, mid, 0));
  } else {
    fprintf(stderr, "mlogagent: Can't find the method\n");
  }
}
  

The last part is to handle the method breakpoint callback when it happens. In the real program, we keep track of methodIDs we've registered breakpoints for, so that when we get this event we can quickly determine which method triggered the breakpoint, and look up information about how to display it in the config. In the real code, this is one of the more complex parts of the implementation, since it uses a bunch of JNI in order to generate a string to represent the method parameter we're interested in. For this simplified example, I'm just going to show what the callback looks like, how to extract a parameter, and how to print the first few frames of the stack trace.

  
// Called when a breakpoint is hit.
void JNICALL BreakpointCallback(jvmtiEnv *jvmti_env, JNIEnv *jni, jthread thread, jmethodID method, jlocation location) {
  // Get hold of the parameter. In this example, we just get the first parameter.
  // Which parameter is first depends on whether this is a static or instance method. 
  // For instance methods, the first parameter is a synthetic parameter representing
  // the current instance of the class. So here, we get the first "real" parameter.
  int parameterPos = 1;
  
  jobject the_parameter;
  assert(JVMTI_ERROR_NONE == (*jvmti_env)->GetLocalObject(jvmti_env, thread, 0, parameterPos, &the_parameter));
  
  // TODO: something that displays the parameter... See the full code for details.
  
  // Show a simplified stack trace.
  jvmtiFrameInfo frames[8];
  jint count;
  jvmtiError err;

  err = (*jvmti_env)->GetStackTrace(jvmti_env, thread, 0, 8, frames, &count);
  if (err == JVMTI_ERROR_NONE && count >= 1) {
    char *methodName;
    // fout is the output log file
    fprintf(fout, "  trace: ");
    for (int i = 0; i < count; i++) {
      err = (*jvmti_env)->GetMethodName(jvmti_env, frames[i].method, &methodName, NULL, NULL);
      if (err == JVMTI_ERROR_NONE) {
        fprintf(fout, "<- %s", methodName);
      }
    }
    fprintf(fout, "\n");
  }

  fflush(fout);
}

Compiling and running the agent

To compile the agent, you need to add to your compiler's include path header files from the java runtime you're compiling for. The location of these vary from system to system. On my system, I use a command something like this:


gcc -shared \
  -I/usr/local/java-runtime/impl/8/include \
  -I/usr/local/java-runtime/impl/8/include/darwin \
  mlogagent.c \
  -o /tmp/libmlogagent.dylib
          

To use the agent in a running java program, we pass the -agentpath argument to java with the path of the agent, and any options we want to pass in:

          
java -agentpath:/tmp/libmlogagent.dylib=config=test.conf,file=/tmp/out.txt \
   -cp classes frodo.Test

Summing up

So we've seen how to write a fairly basic JVMTI agent that can log method calls. It's pretty efficient - in an example application which makes thousands of method calls a second, there's no perceptible performance impact when the agent is enabled. You can find full source for the tool on github.

I'd like to experiment more with this tool, perhaps making it more flexible and customizable. Some of the things I want to poke around with are:

  • Rewriting it in Rust. This has advantages like me not having to reinvent a configuration file parser from scratch because I'm too lazy to pull in third party C libraries, as well as likely making it easier to maintain and extend the code in future.
  • Looking into whether it'd be easier to do the same thing with a java-based agent or JDI, and seeing whether the performance characteristics of these are different.
  • Adding much more flexibility around logging various bits of context when a breakpoint is hit. For example, it'd be useful to have the option to log fields, and all of the parameters instead of just one.

You can find the code for this tool in github.

Comments

  1. Lovely pair of posts -- thank you!

    You might update part 2 with a footnote reference linking to the GitHub repository, as you did for part 1, so the reader does not need to jump back to find the link.

    ReplyDelete
    Replies
    1. Thanks for the feedback Brian! That's a great idea - added the footnote.

      Delete

Post a Comment

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…