Does java have any mechanism for a VM to trace method calls on itself, without using javaagent, etc?

Question

I want to build call graphs on the fly, starting at an arbitrary method call or with a new thread, which ever is easier, from within the running JVM itself. (this piece of software is going to be a test fixture for load testing another piece of software that consumes call graphs)

I understand there are some SPI interfaces, but it looks like you need to run -javaagent flag with them. I want to access this directly in the VM itself.

Ideally, I'd like to get a callback for entry and exit of each method call, parameters to that method call, and time in that method. Within a single thread obviously.

I know AOP could probably do this, but I'm just wondering if there are tools within the JDK that would allow me to capture this.

Answer 1

There is no such API provided by the JVM— even for agents started with -javaagent. The JVM TI is a native interface provided for native agents started with the -agent option or for debuggers. Java agents might use the Instrumentation API which provides the lowlevel feature of class instrumentation but no direct profiling capability.

There are two types of profiling implementations, via sampling and via instrumentation.

Sampling works by recording stack traces (samples) periodically. This does not trace every method call but still detect hot spots as they occur multiple times in the recorded stack traces. The advantage is that it does not require agents nor special APIs and you have the control over the profiler’s overhead. You can implement it via the ThreadMXBean which allows you to get stack traces of all running threads. In fact, even a Thread.getAllStackTraces() would do but the ThreadMXBean provides more detailed information about the threads.

So the main task is to implement an efficient storage structure for the methods found in the stack traces, i.e. collapsing occurrences of the same method into single call tree items.

Here is an example of a very simple sampler working on its own JVM:

import java.lang.Thread.State;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.util.*;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;

public class Sampler {
  private static final ThreadMXBean TMX=ManagementFactory.getThreadMXBean();
  private static String CLASS, METHOD;
  private static CallTree ROOT;
  private static ScheduledExecutorService EXECUTOR;

  public static synchronized void startSampling(String className, String method) {
    if(EXECUTOR!=null) throw new IllegalStateException("sampling in progress");
    System.out.println("sampling started");
    CLASS=className;
    METHOD=method;
    EXECUTOR = Executors.newScheduledThreadPool(1);
    // "fixed delay" reduces overhead, "fixed rate" raises precision
    EXECUTOR.scheduleWithFixedDelay(new Runnable() {
      public void run() {
        newSample();
      }
    }, 150, 75, TimeUnit.MILLISECONDS);
  }
  public static synchronized CallTree stopSampling() throws InterruptedException {
    if(EXECUTOR==null) throw new IllegalStateException("no sampling in progress");
    EXECUTOR.shutdown();
    EXECUTOR.awaitTermination(Long.MAX_VALUE, TimeUnit.DAYS);
    EXECUTOR=null;
    final CallTree root = ROOT;
    ROOT=null;
    return root;
  }
  public static void printCallTree(CallTree t) {
    if(t==null) System.out.println("method not seen");
    else printCallTree(t, 0, 100);
  }
  private static void printCallTree(CallTree t, int ind, long percent) {
    long num=0;
    for(CallTree ch:t.values()) num+=ch.count;
    if(num==0) return;
    for(Map.Entry<List<String>,CallTree> ch:t.entrySet()) {
      CallTree cht=ch.getValue();
      StringBuilder sb = new StringBuilder();
      for(int p=0; p<ind; p++) sb.append(' ');
      final long chPercent = cht.count*percent/num;
      sb.append(chPercent).append("% (").append(cht.cpu*percent/num)
        .append("% cpu) ").append(ch.getKey()).append(" ");
      System.out.println(sb.toString());
      printCallTree(cht, ind+2, chPercent);
    }
  }
  static class CallTree extends HashMap<List<String>, CallTree> {
    long count=1, cpu;
    CallTree(boolean cpu) { if(cpu) this.cpu++; }
    CallTree getOrAdd(String cl, String m, boolean cpu) {
      List<String> key=Arrays.asList(cl, m);
      CallTree t=get(key);
      if(t!=null) { t.count++; if(cpu) t.cpu++; }
      else put(key, t=new CallTree(cpu));
      return t;
    }
  }
  static void newSample() {
    for(ThreadInfo ti:TMX.dumpAllThreads(false, false)) {
      final boolean cpu = ti.getThreadState()==State.RUNNABLE;
      StackTraceElement[] stack=ti.getStackTrace();
      for(int ix = stack.length-1; ix>=0; ix--) {
        StackTraceElement ste = stack[ix];
        if(!ste.getClassName().equals(CLASS)||!ste.getMethodName().equals(METHOD))
          continue;
        CallTree t=ROOT;
        if(t==null) ROOT=t=new CallTree(cpu);
        for(ix--; ix>=0; ix--) {
          ste = stack[ix];
          t=t.getOrAdd(ste.getClassName(), ste.getMethodName(), cpu);
        }
      }
    }
  }
}

---

Profilers hunting for every method invocation without going through the debugging API use instrumentation to add notification code to every method they are interested in. The advantage is that they never miss a method invocation but on the other hand they are adding a significant overhead to the execution which might influence the result when searching for hot spots. And it’s way more complicated to implement. I can’t give you a code example for such a byte code transformation.

The Instrumentation API is provided to Java agents only but in case you want to go into the Instrumentation direction, here is a program which demonstrates how to connect to its own JVM and load itself as a Java agent:

import java.io.*;
import java.lang.instrument.Instrumentation;
import java.lang.management.ManagementFactory;
import java.nio.ByteBuffer;
import java.nio.charset.Charset;
import java.nio.charset.StandardCharsets;
import java.util.UUID;
import java.util.zip.ZipEntry;
import java.util.zip.ZipOutputStream;

// this API comes from the tools.jar of your JDK
import com.sun.tools.attach.*;

public class SelfAttacher {

  public static Instrumentation BACK_LINK;

  public static void main(String[] args) throws Exception {
 // create a special property to verify our JVM connection
    String magic=UUID.randomUUID().toString()+'/'+System.nanoTime();
    System.setProperty("magic", magic);
 // the easiest way uses the non-standardized runtime name string
    String name=ManagementFactory.getRuntimeMXBean().getName();
    int ix=name.indexOf('@');
    if(ix>=0) name=name.substring(0, ix);
    VirtualMachine vm;
    getVM: {
      try {
      vm = VirtualMachine.attach(name);
      if(magic.equals(vm.getSystemProperties().getProperty("magic")))
        break getVM;
      } catch(Exception ex){}
 //   if the easy way failed, try iterating over all local JVMs
      for(VirtualMachineDescriptor vd:VirtualMachine.list()) try {
        vm=VirtualMachine.attach(vd);
        if(magic.equals(vm.getSystemProperties().getProperty("magic")))
          break getVM;
        vm.detach();
      } catch(Exception ex){}
 //   could not find our own JVM or could not attach to it
      return;
    }
    System.out.println("attached to: "+vm.id()+'/'+vm.provider().type());
    vm.loadAgent(createJar().getAbsolutePath());
    synchronized(SelfAttacher.class) {
      while(BACK_LINK==null) SelfAttacher.class.wait();
    }
    System.out.println("Now I have hands on instrumentation: "+BACK_LINK);
    System.out.println(BACK_LINK.isModifiableClass(SelfAttacher.class));
    vm.detach();
  }
 // create a JAR file for the agent; since our class is already in class path
 // our jar consisting of a MANIFEST declaring our class as agent only
  private static File createJar() throws IOException {
    File f=File.createTempFile("agent", ".jar");
    f.deleteOnExit();
    Charset cs=StandardCharsets.ISO_8859_1;
    try(FileOutputStream fos=new FileOutputStream(f);
        ZipOutputStream os=new ZipOutputStream(fos)) {
      os.putNextEntry(new ZipEntry("META-INF/MANIFEST.MF"));
      ByteBuffer bb = cs.encode("Agent-Class: "+SelfAttacher.class.getName());
      os.write(bb.array(), bb.arrayOffset()+bb.position(), bb.remaining());
      os.write(10);
      os.closeEntry();
    }
    return f;
  }
 // invoked when the agent is loaded into the JVM, pass inst back to the caller
  public static void agentmain(String agentArgs, Instrumentation inst) {
    synchronized(SelfAttacher.class) {
      BACK_LINK=inst;
      SelfAttacher.class.notifyAll();
    }
  }
}

Answer 2

You can modify bytecode of each method adding routine to log method's enter/exit events. Javassist will help you http://www.csg.ci.i.u-tokyo.ac.jp/~chiba/javassist/

Also check out a nice tutorial: https://today.java.net/pub/a/today/2008/04/24/add-logging-at-class-load-time-with-instrumentation.html