Auf Spurensuche in der Java-VM mit BTrace und YouDebug

In der jüngeren Vergangenheit ist in der Java-Welt eine Art von Werkzeugen entstanden, die sich zwischen den Extremen „Debugging“ und „Profiling“ ansiedelt. Diese Werkzeuge erlauben es, das Verhalten von Anwendungen hinsichtlich eines sonst verdeckten Charakterzuges zu beobachten. Im Folgenden sollen zwei dieser Tracing-Werkzeuge an Hand von Beispielen vorgestellt werden.

Tracing-Werkzeuge sind im Bereich der Systemadministration bereits bestens bekannt. So protokolliert beispielsweise das Linux-Werkzeug „strace“ alle Systemaufrufe eines Anwendungssystems in menschenlesbarer Form. Tracing-Werkzeuge, die Ähnliches für Java-Anwendungen leisten wollen, können sich der JPDA (Java Platform Debugger Architecture) bedienen. Über die JPDA-Schnittstelle JDI (Java Debug Interface) kann mittels eines Agenten, der in Java geschrieben ist, auf VM-Interna zugegriffen werden (Abbildung 1).

Abbildung 1: Die Java Platform Debugger Architecture (JPDA)

Dieser Agent kann all das tun, was auch ein Entwickler in einer Debug-Session tun könnte – nur wird das „Handeln“ des Agenten durch ein Skript vorherbestimmt. Jeder Sun-SDK-Installation liegen unter /demo/jpda/examples einige Beispiel-Anwendungen für JPDA bei. Das einfachste Beispiel ist „Trace“ im Paket com.sun.tools.example.trace. Diese Trace-Anwendung ist bereits in die Bibliothek „tools.jar“ einkompiliert und kann für erste Experimente sofort genutzt werden.

Java-Tracer

Zwei Open-Source-Projekte, die in die Kategorie „Tracing-Werkzeuge“ fallen, sind BTrace und YouDebug. Beide Projekte werden auf Kenai gehostet [1] [2]. Für BTrace existieren Plugins, die eine Einbindung in VisualVM und NetBeans ermöglichen. YouDebug stammt aus derselben Feder wie „Hudson“ und integriert Groovy zur Steuerung von Tracing-Sessions. Beide Werkzeuge sollen auf folgende Anwendungsfälle hin untersucht werden:

  • Überwachung einer Methodenausführung
  • Ausgabe der Methodenparameter
  • Berechnung der Ausführungszeit
  • Manipulation eines Methodenparameters

Als Untersuchungsgegenstand soll das Logging-System von EclipseLink dienen. Das Tracing soll – ähnlich wie bei den Unix-Werkzeugen – gemeinsam mit dem zu untersuchenden Programm gestartet werden.

BTrace

Für BTrace ist der Ausgangspunkt eines Tracings die Definition eines Messpunktes (Probe-Point). Solche Messpunkte können beispielsweise das Betreten oder das Verlassen von Methoden, das Ablaufen eines Timers oder ein Variablenzugriff sein. An diese Messpunkte können Skripte gebunden werden (Trace-Actions), welche die jeweiligen Messungen durchführen. Ein solches Skript wird als statische Methode (Action-Method) in einer @BTrace-annotierten Java-Klasse definiert. Folgendes Beispiel soll der Veranschaulichung dienen:

@BTrace
public class LogTraces {

   @OnMethod(clazz = 
              "org.eclipse.persistence.logging.AbstractSessionLog", 
             method = "log")
   public static void hit(AnyType[] args) {
      BTraceUtils.println( "Hit log method in AbstractSessionLog");
   }
}

Dieses Skript besagt, dass, wann immer eine Methode „log“ in der Klasse „org.eclipse.persistence.logging.​AbstractSessionLog“ betreten wird, der Text „Hit log method in AbstractSessionLog“ ausgegeben werden soll. Der Klassenname „LogTraces“ und der Methodenname „hit“ sind willkürlich. Nicht willkürlich ist die Methoden-Signatur: Der Parameter „AnyType[] args“ bewirkt, dass Log-Methoden mit beliebigen Methoden-Signaturen erfasst werden. Der Parameter „args“ enthält dann alle aktuellen Parameter-Werte.

Möchte man nur Methoden mit der Signatur „log(int, String)“ erfassen, sähe die Action-Methode wie folgt aus:

@OnMethod(clazz =
              "org.eclipse.persistence.logging.AbstractSessionLog",
           method = "log")
public static void hit2(int level, String message) {
   BTraceUtils.println(
                     "Hit log method in AbstractSessionLog:");
   BTraceUtils.println(
      BTraceUtils.strcat(
         BTraceUtils.strcat("level: ", BTraceUtils.str(level)),
         BTraceUtils.strcat(", message: ", message)
         )
      );
}

Die wesentliche Änderung zum vorhergehenden Beispiel ist die veränderte Methoden-Signatur. Darüber hinaus wurde die Implementierung der Action-Methode so erweitert, dass sie gleichzeitig auch den Inhalt der Parameter ausgibt. Hierbei ist es nicht möglich, den Plus-Operator für String-Verkettungen zu nutzen – man muss in diesem Fall auf die statische Methode „BTraceUtils.strcat(String, String)“ ausweichen.

Möchte man eine Variable vom Typ „Array“ ausgeben lassen, so existiert hierfür eine weitere Helfermethode – die Benutzung von Schleifen ist aus Performance-Gründen in einer Action-Methode untersagt. Auf das erste Beispiel angewendet,sähe die Action-Methode damit folgendermaßen aus:

@OnMethod(clazz =
              "org.eclipse.persistence.logging.AbstractSessionLog",
          method = "log")
public static void hit(AnyType[] args) {
   BTraceUtils.println("Hit log method in AbstractSessionLog:");
   BTraceUtils.printArray(args);
   BTraceUtils.jstack();
}

In diesem Beispiel wird zusätzlich mittels „BTraceUtils.jstack()“ ein Stack-Trace ausgegeben. Auf diese Weise lässt sich einfach nachvollziehen, welche andere Methode die Log-Methode aufgerufen hat.

Für die Berechnung der Ausführungszeit von Methoden hat die BTrace-Bibliothek bereits Vorkehrungen getroffen: @Duration injiziert die Ausführungszeit in Nanosekunden als Parameter. Zur Verfügung steht diese Information bei der Rückkehr aus einer Methode (? @Location(Kind.RETURN)):

import static com.sun.btrace.BTraceUtils.println;
import static com.sun.btrace.BTraceUtils.str;
import static com.sun.btrace.BTraceUtils.strcat;

@OnMethod(clazz =
             "org.eclipse.persistence.logging.AbstractSessionLog",
          method = "log",
          location = @Location(Kind.RETURN))
public static void hit3(@Duration long duration, 
                          int level, String message) {
   println(strcat("executing log method took [ns]: ", 
                       str(duration)));
}

Eine manuelle Berechnung der Ausführungszeit ist auch möglich. Die Startzeit muss per Thread in einem Thread-Local-Store (? @TLS) abgelegt werden:

@TLS
private static long startTime;

@OnMethod(clazz =
              "org.eclipse.persistence.logging.AbstractSessionLog",
          method = "log",
          location = @Location(Kind.ENTRY))
public static void hit3in(int level, String message) {
   startTime = BTraceUtils.timeNanos();
}

@OnMethod(clazz =
              "org.eclipse.persistence.logging.AbstractSessionLog",
          method = "log",
          location = @Location(Kind.RETURN))
public static void hit3out(int level, String message) {
   long duration = BTraceUtils.timeNanos() - startTime;
   BTraceUtils.println(
      BTraceUtils.strcat("executing log method took [ns]: ",
         BTraceUtils.str(duration))
   );
}

Möchte man die Ausführungszeiten aggregieren, um beispielsweise einen Durchschnitt zu berechnen, kann man auch hier auf bestehende Helfermethoden zurückgreifen. Die einzelnen Messpunkte werden in einer „Aggregation“ gesammelt:

private static Aggregation logDurationAvg =
      BTraceUtils.newAggregation(AggregationFunction.AVERAGE);

@OnMethod(clazz =
              "org.eclipse.persistence.logging.AbstractSessionLog",
          method = "log",
          location = @Location(value = Kind.RETURN,
                               clazz = "/.*AbstractSessionLog$/",
                               method = "/(?!log$).*/"))
public static void hit3out(@Duration long duration) {
   BTraceUtils.addToAggregation(logDurationAvg, duration);
}

@OnMethod(clazz = "de.buschmais.example.ELMain",
          method = "main",
          location = @Location(Kind.RETURN))
public static void exit(String[] args) {
   BTraceUtils.println("- - Summary - - - - - - - - - - - -");
   BTraceUtils.printAggregation("avg-log", logAvg);
}

Die Angabe von „@Location(value = Kind.RETURN, clazz = "/.*AbstractSessionLog$/", method = "/(?!log$).*/")“ bewirkt hier, dass die Ausführungsdauer nur dann für die Berechnung herangezogen wird, wenn die aufrufende Methode nicht auch „log“ heißt. Wenn eine Log-Methode eine andere Log-Methode aufruft, würde die Ausführungszeit sonst mehrfach in die Berechnung einfließen.

Der letzte Anwendungsfall – die Manipulation von Methodenparametern – ist mit BTrace nicht möglich. Innerhalb eines BTrace-Skripts kann man zwar Zugriff auf Klassen- und Instanz-Felder erlangen, nicht aber auf Methodenparameter. Darüber hinaus wird durch die BTrace-Umgebung jeder Versuch vereitelt, Felder zu manipulieren und damit das untersuchte Programm zu beeinflussen. Mittels „unsafe=true“ beim Kompilieren und Verwenden eines Action-Skripts kann diese Kontrolle abgeschaltet werden.

Für die Anwendung von BTrace-Skripten wird ein Werkzeug namens „btrace“ mitgeliefert. Mit seiner Hilfe kann man sich an einen laufenden Java-Prozess per PID koppeln und die Untersuchungen durchführen. Die Action-Skript-Klasse wird durch dieses Werkzeug automatisch kompiliert und per Class-Retransformation in den untersuchten Java-Prozess eingewoben. BTrace setzt hierfür auf ein proprietäres Verfahren außerhalb der JPDA.

Möchte man allerdings das BTrace-Skript gleichzeitig mit der Anwendung ausführen, muss dieses vorkompiliert werden. Hierfür wird ein Werkzeug namens „btracec“ mitgeliefert. Beim Starten der zu untersuchenden Anwendung muss ein Java-Agent als JavaVM-Startparameter angegeben werden („-javaagent:btrace-agent.jar“). Dieser erhält dabei eine Referenz auf das vorkompilierte Skript. Alternativ kann man auch das Werkzeug „btracer“ mit entsprechenden Start-Parametern nutzen.

YouDebug

Im Gegensatz zu BTrace nutzt das YouDebug-Werkzeug ausschließlich die JDI-Schnittstelle für das Erlangen der Trace-Informationen. Um dem Anwender den lästigen Compile-Schritt zu ersparen, wird das Trace-Script nicht in Java, sondern in Groovy formuliert. YouDebug vereinfacht die Skript-Programmierung durch einen Groovy-spezifischen JDI-Adapter.

Das Grundprinzip eines YouDebug-Skripts ist die Definition unterschiedlicher Breakpoints. Innerhalb einer Closure wird dabei die Tracing-Aktion festgehalten:

vm.methodEntryBreakpoint(
      "org.eclipse.persistence.logging.AbstractSessionLog",
      "log") {
   println "Hit log method in AbstractSessionLog";
};

Dieser Breakpoint erfasst alle Log-Methoden – unabhängig von ihrer Methoden-Signatur – in der Klasse „AbstractSessionLog“. Möchte man nur eine bestimmte Methode untersuchen, ist etwas mehr Programmieraufwand als bei BTrace notwendig. Durch die enge Beziehung zum JDI-API und der somit verfügbaren Dokumentation ist dieser Schritt jedoch gut zu meistern [3]:

def intType = vm.virtualMachine.mirrorOf(1).type();
def stringType = vm.ref("java.lang.String");
def signature = [intType, stringType];

vm.methodEntryBreakpoint(
      "org.eclipse.persistence.logging.AbstractSessionLog",
      "log") {
   com.sun.jdi.StackFrame stackFrame = thread.frame(0);
   argumentTypes =
                stackFrame.location().method().argumentTypes();
   if (argumentTypes == signature) {
      printf("level: %d, message: %s%n",
              stackFrame.argumentValues[0].value(),
              stackFrame.argumentValues[1].value());
      thread.dumpThread();
   }
};

Ähnlich zum BTrace-Beispiel wird nicht nur der Inhalt der Methoden-Parameter ausgegeben, sondern gleichzeitig noch der Call-Stack auf die Konsole herausgeschrieben.

Auch für die Berechnung der Ausführungszeit einer Methode ist Handarbeit notwendig. Zu beachten ist hier unbedingt, dass im Gegensatz zu BTrace die untersuchende VM von der untersuchten VM getrennt ist. Das Konstrukt eines ThreadLocals muss daher nachgebaut werden:

def startTimes = new HashMap<String, Long>();

vm.methodEntryBreakpoint(
      "org.eclipse.persistence.logging.AbstractSessionLog",
      "log") {
   startTimes.put(vm.currentThread.name(),
                       System.nanoTime());
};

vm.methodExitBreakpoint(
      "org.eclipse.persistence.logging.AbstractSessionLog",
      "log") {
   duration = System.nanoTime() - startTimes.get(
                                        vm.currentThread.name());
   printf ("executing log method took %d ns%n", duration);
};

Möchte man ähnlich zum BTrace-Skript eine doppelte Zeiterfassung vermeiden, so kann man über das Konstrukt „thread.frame(1).location().method().name()“ an den Methoden-Namen der aufrufenden Methode gelangen. Betrachtet man allerdings die erfassten Messwerte, wird schnell der negative Einfluss des Tracings auf das Zeitverhalten der Anwendung deutlich. Da eine sinnvolle Interpretation der Zeiten nicht möglich ist, soll im Weiteren von der Berechnung der Durchschnittszeiten Abstand genommen werden.

Der letzte zu betrachtende Anwendungsfall – die Manipulation der Ziel-VM – kann mit YouDebug spielend gemeistert werden. Alle sichtbaren und benannten Variablen der Zielmethode werden in den Scope der Groovy-Closure eingeblendet:

def intType = vm.virtualMachine.mirrorOf(1).type();
def stringType = vm.ref("java.lang.String");
def signature = [intType, stringType];

vm.methodEntryBreakpoint(
      "org.eclipse.persistence.logging.AbstractSessionLog",
      "log") {
   com.sun.jdi.StackFrame stackFrame = thread.frame(0);
   argumentTypes =
               stackFrame.location().method().argumentTypes();
   if (argumentTypes == signature) {
      // 'level' heißt der Methoden-Parameter
      level = 6; // = WARNING
   }
};

Bei Namenskonflikten kann per Pseudovariable „delegate“ ein Zugriff auf die Variablen der Ziel-VM erlangt werden. Für das Beispiel wäre der Aufruf folglich „delegate.level“. Ist das untersuchte Programm ohne Debug-Informationen kompiliert worden, ist ein Zugriff per Position als delegate.“@0″ möglich. Die Manipulation von Methoden-Parametern ist dann allerdings ausgeschlossen.

Das Rüsten einer Anwendung für die Untersuchung mit YouDebug unterscheidet sich nicht von der Vorbereitung für Remote-Debugging. Per VM-Parameter muss lediglich der JPDA-Debug-Agent aus dem Java-SDK aktiviert werden:

-agentlib:jdwp=transport=dt_socket,address=5005,
   server=y,suspend=y

Das Argument „suspend=y“ bewirkt, dass erst beim Start der Debug-Session auch das Programm gestartet wird. Das YouDebug-Skript kann wie folgt ausgeführt werden:

java -jar youdebug-1.3-jar-with-dependencies.jar
   -socket 5005
   LogDebug.ydb

Fazit

BTrace und YouDebug unterscheiden sich in der Herangehensweise für das Tracing einer Java-Anwendung. BTrace-Skripte werden per Byte-Code-Instrumentierung in die Ziel-VM gewoben und gemeinsam mit dem untersuchten Programm ausgeführt. Zeitmessungen sind daher relativ verlässlich, die Manipulierbarkeit der Ziel-VM wird jedoch auf ein Minimum beschränkt. YouDebug-Skripte hingegen sind mit einer Remote-Debug-Session vergleichbar. Die Möglichkeiten, auf die Ziel-VM Einfluss zu nehmen, sind daher fast unbegrenzt. Zeitmessungen dürfen aber keinesfalls in absoluter Form interpretiert werden, da die Ziel-VM im Debug-Modus stark ausgebremst wird.

Die unterschiedliche Arbeitsweise der Tracing-Werkzeuge führt auch dazu, dass bei YouDebug erste Messergebnisse relativ schnell vorliegen. BTrace hingegen führt zunächst eine Retransformation aller geladenen Klassen der Ziel-VM durch, bevor mit einer Messung begonnen werden kann. Dieser Vorgang kann bei Application-Server-Anwendungen zu einer erheblichen Startverzögerung führen.

Beide Werkzeuge unterscheiden sich auch in der Qualität der verfügbaren Dokumentation. Obwohl YouDebug selbst nur wenig Dokumentation mitbringt, kann über die JDI-Dokumentation alles Wesentliche erschlossen werden. Die BTrace-Dokumentation stützt sich stark auf die mitgelieferten Beispiele. Allerdings sind in der aktuellen Version 1.1.2 nicht alle Beispiele compile-fähig.

Als Fazit lässt sich festhalten, dass Tracing-Werkzeuge eine interessante Bereicherung des Werkzeugkastens eines Java-Entwicklers darstellen. Sie bieten sich immer dann an, wenn ein Re-kompilieren der Anwendung mit zusätzlichen Sysout-Printlns zu aufwändig wäre, um an die gewünschten Informationen zu gelangen. Anders als bei den Pendants aus der Unix-Welt ist der Rüstaufwand jedoch nicht zu unterschätzen.

Quellen

[1] BTrace: http://kenai.com/projects/btrace/
[2] YouDebug: http://youdebug.kenai.com/
[3] Java Debug Interface: http://java.sun.com/javase/6/docs/jdk/​api/jpda/jdi/

Diesen Artikel können Sie sich auch als PDF herunterladen:
Download Auf Spurensuche in der Java-VM

Kommentare sind abgeschaltet.