Zustandsforschung

In manchen Situationen kommt der Einsatz eines professionellen Profiling-Tools nicht in Frage. Das kann beispielsweise dann vorkommen, wenn es gilt, eine durch diverseste Firewalls geschützte Java-Applikation zu profilen und in der Firma, in der man arbeitet kein entsprechendes Tool eingesetzt werden kann oder darf (oder wenn der für das Tool zuständige “Experte” nicht greifbar oder nicht kooperativ ist).

Die JVM bringt aber auch ein eingebautes Profiling mit, das zwar nicht mit dem was eben die “richtigen” Profiler liefern vergleichbar ist, aber eben doch ganz brauchbar, wenn es darum geht herauszufinden, warum eine Applikation lahm ist. Die Funktion nennt sich hprof und viele kennen das vielleicht als Methode, um Heap-Dumps zu erzeugen. Aber das Ding kann noch mehr: um zu zeigen, wie man damit Performance-Probleme erkennen kann, verwende ich hier ein einfaches Beispiel, das Fibonacci-Zahlen rekursiv berechnet (der Source-Code für das Beispiel ist hier verlinkt).

Das hier ist die Java-Klasse, mit der wir die entsprechenden Daten erzeugen:

package example;
 
public class Fib {
 
	public long calculate(long n) {
		if(n == 0) {
			return 0;
		}
		if(n == 1) {
			return 1;
		}
		return calculate(n-1) + calculate(n-2);
	}
 
	public static void main(String[] args) {
		Fib fib = new Fib();
		System.out.println(fib.calculate(Long.valueOf(args[0])));
	}
 
}

Ruft man nun diese Klasse mit folgenden Parametern auf, erhält man eine Datei java.hprof.txt, die jede Menge Stack-Traces und am Ende eine Tabelle mit Profiling-Informationen enthält:

java -agentlib:hprof=cpu=times,depth=100 example.Fib 20

Den vollständigen Satz an möglichen Optionen erhält man mit java -agentlib:hprof=help oder im Artikel HPROF: A Heap/CPU Profiling Tool in J2SE 5.0.

Die Tabelle am Ende der Datei sieht ungefähr so aus:

CPU TIME (ms) BEGIN (total = 96) Wed Dec 07 16:53:53 2011
rank   self  accum   count trace method
   1 15.63% 15.63%    5020 301386 example.Fib.calculate
   2  9.38% 25.00%    4760 301385 example.Fib.calculate
   3  8.33% 33.33%    3632 301387 example.Fib.calculate
   4  7.29% 40.62%    2942 301384 example.Fib.calculate
   5  6.25% 46.87%    2026 301388 example.Fib.calculate
   6  5.21% 52.08%    1024 301389 example.Fib.calculate
   7  5.21% 57.29%     512 301390 example.Fib.calculate
   8  2.08% 59.38%     174 300332 java.lang.StringBuffer.append
   9  2.08% 61.46%    1152 301383 example.Fib.calculate
  10  1.04% 62.50%     256 301375 java.lang.Long.<init>
  11  1.04% 63.54%     256 301374 java.lang.Number.</init><init>
  12  1.04% 64.58%       1 301231 java.util.Hashtable.get
  13  1.04% 65.63%       5 301162 java.lang.StringBuilder.toString
  14  1.04% 66.67%       1 301111 java.io.FilePermissionCollection.<clinit>
  15  1.04% 67.71%       1 301031 java.io.Win32FileSystem.normalize
  16  1.04% 68.75%       1 300988 sun.net.www.protocol.file.FileURLConnection.getPermission
  17  1.04% 69.79%       1 300986 java.io.FilePermission.init
  18  1.04% 70.83%       1 300982 java.io.FilePermission$1.run
  19  1.04% 71.88%      44 300950 java.lang.StringBuffer.append
  20  1.04% 72.92%       1 300886 sun.net.www.protocol.file.Handler.createFileURLConnection
...

Hier kann man schon sehen, dass unsere Methode calculate() wohl nicht die schnellste ist. Außerdem sieht man noch, dass die langen Laufzeiten in dieser Methode in unterschiedlichen Threads immer mal wieder vorkommen.

Jetzt kann man in der gleichen Datei nach der Nummer, die in der Spalte trace steht suchen und findet dazu für die erste Zeile folgenden Thread

TRACE 301386:
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.calculate(Fib.java:Unknown line)
example.Fib.main(Fib.java:Unknown line)

Hier kann man dann ablesen, dass es sich wohl um den rekursiven Aufruf handelt, der hier das meiste der Performance auffrisst. Wenn man Glück hat, dann stehen da auch noch die Zeilennummern dabei – warum das hier nicht der Fall ist, weiß ich ehrlich gesagt nicht.

Weil diese java.hprof.txt-Files gerne mal ziemlich riesig werden können und die Sucherei in den Files nicht wirklich Spass macht, habe ich ein kleines Python-Skript geschrieben, das die Files in eine HTML-Seite umwandelt, in der man per Klick von der Liste zu den Threads springen kann und wo man auch bestimmte Klassen ausfiltern kann, von denen man schon weiß, dass die nix mit dem Problem zu tun haben. Das Skript habe ich hprof2html getauft und es kann hier heruntergeladen werden: https://github.com/zustandsforschung/hprof2html