In einigen kürzlich geführten Diskussionen nahm ich eine Verwirrung über den Unterschied zwischen den Messverfahren Sampling und Instrumentierung wahr.
Häufig wird über die Vor- und Nachteile der Verfahren gesprochen ohne zu verstehen, wie diese funktionieren. Einige Tools, wie zum Beispiel der rechts abgebildete JProfiler 7 , fragen direkt beim Start das gewünschte Verfahren ab.
Doch wie kann man die für das Problem passende Strategie wählen, ohne die zu Grunde liegenden Konzepte zu verstehen?
Gehen wir also erstmal einen Schritt zurück und fragen uns, wie man überhaupt die Performanz eines Computerprogramms messen kann:
a) Wir fügen dem echten Anwendungscode eine Art Messcode hinzu, welcher uns genau ermittelt, wie lang der echte Code zur Ausführung benötigte.
b) Wir nutzen einen externen Beobachter, welcher den echten Anwendungscode bei der Ausführung beobachtet und mitteilen kann, welcher Code zu bestimmten Zeitpunkten ausgeführt wurde.
Beide Verfahren funktionieren und liefern Ergebnisse. Dennoch sind sie fundamental verschieden. In diesem Post werde ich deshalb versuchen sie zu demonstrieren.
Die genutzen Beispiele basieren auf Java und der JVM, lassen sich aber grundsätzlich auch auf andere Sprachen, insbesondere auf .Net und seiner CLR, übertragen.
Wie können wir in Java Messcode hinzufügen?
Code hinzuzufügen scheint die scheinbar einfachere Variante zu sein, gibt es doch eine Vielzahl von etablierten Verfahren um Performancemesscode in die Anwendung zu integrieren:
- Manuell hinzugefügte System.out.println-Ausgaben für wichtige Methoden. Die Ausführungszeit wird direkt in das Log geschrieben.
- Verwendung von selbstgeschriebenen javax.management Beans, welche Ausführungszeiten speichern. Diese werden manuell ermittelt und können toolgestütz abgefragt werden.
- Durch Verwendung von AOP Bibliotheken werden Aspekte zur Ausführungszeitmessung erstellt.
- Mittels eines JVMTI-Agenten werden über Standard APIs Codemodifikationen und Zeitmessungen durchgeführt.
Natürlich ist diese Aufzählung nicht vollständig, und die Verfahren überschneiden sich teilweise, jedoch verwenden alle diese Verfahren zusätzlichen Code vor und nach dem gemessenen Code. Die einfachen Verfahren verwenden üblicherweise Dateilogging oder JMX (JSR-3 , JSR-250 ). JMX wurde zwar dafür entworfen, Metriken zu sammeln und dynamisch Konfigurationsänderungen vorzunehmen, jedoch muss bei der Entwicklung die Verwendung direkt vorgesehen werden.
Die ausgereifteren Methoden sind dagegen dynamischer und erfordern keine direkte Einprogrammierung. Sie fügen Code mittels „Instrumentierung“ dynamisch hinzu, meist unter der Verwendung von Bytecode-Modifikation.
Wie kann in Java Code beobachtet werden?
Idealerweise beobachtet man von außerhalb der Laufzeitumgebung (der JVM). Zwar wurde JMX in JSR-160 auch extern verfügbar gemacht, jedoch ist JMX, wie bereits erläutert, zu oberflächlich und erfordert zusätzliche Programmierung. Andere Management APIs erlauben uns zwar den Status der JVM Abzufragen, ermöglichen aber keine Analyse von Codegeschwindigkeit. Um eine bessere, pseudoexterne, Beobachtung durchführen zu können, erzeugen wir also direkt in der beobachteten JVM einen Thread, welcher diese Beobachtungsaufgabe übernimmt.
Dieser Thread sieht sich von Zeit zu Zeit die anderen laufenden Threads an und misst ihre Aktivität. Das Intervall zwischen diesen Beobachtungen sollte jedoch relativ kurz gewählt werden um viele Details zu sehen. Diese externe Beobachtung wird „Sampling“ genannt. Dabei wird auf der Zeitachse gesampelt, d. h. es es wird nicht ständig, dafür jedoch über alle Anfragen oder Threads gemessen.
Da ich in diesem Beitrag die beiden Verfahren mittels einfach zu verstehendem Code vergleiche, sind die Implementierungen nicht besonders clever oder optimieriert.
Beispielcode
Vorausgehend kann der verwendete Code als ZIP Attachment , oder von SamplingVsInstrumentation auf meinem privaten GitHub heruntergeladen werden.
Wir haben eine Klasse namens Demo, welche unseren gesamten Produktionscode enthält. Die Methoden simulieren eine gewisse Laufzeit und sind praktischerweise anhand der erwarteten Ausführungszeit benannt: method100ms()
Dies erlaubt die einfachere Auswertung der Ausgaben. Leider sind in echtem Code die Methoden nie mit ihrer Ausführungszeit benannt. 🙂
Es gibt auch eine Methode namens method0ms(), welche trotz Ihres Namens zwar Code ausführt, jedoch sehr viel schneller als eine Millisekunde ist.
Der DemoRunner besitzt zwei Methoden, um diesen Code von der Demo Klasse aufzurufen:
a) mixedDemo() wird die Methoden [100, 1, 100, 500, 1, 100, 1, 50, 50] aufrufen.
b) massDemo() wird die Methode method0ms 100 Millionen Mal aufrufen.
Als können wir das Beispiel so starten:
1public static void main(final String[] args) {
2 mixedDemo();
3 massDemo();
4}
Wir können diesen Code laufen lassen, wissen jedoch nicht, wie lange er zur Ausführung gebraucht hat. Wir können aber eine einfache externe Beobachtung durchführen: Mit Hilfe einer Stoppuhr.
Auf meiner Maschine (Dell E6420, Intel 2520 2,5Ghz 4 Core CPU, 64bit Win, Java 1.6.0_27) benötigt mixedDemo() etwa eine Sekunde. Die vielen 0 ms Aufrufe schlagen mit fast 3 Sekunden zu Buche.
Wollen wir genauer messen, so fügen wir einen einfachen Messcode hinzu:
1public static void main(final String[] args) {
2 long start = System.currentTimeMillis();
3 mixedDemo();
4 long end = System.currentTimeMillis();
5 System.out.printf("%s Demo completed in %dms%n", DemoType.MIXED, end - start);
6
7 start = System.currentTimeMillis();
8 massDemo();
9 end = System.currentTimeMillis();
10 System.out.printf("%s Demo completed in %dms%n", DemoType.MASS, end - start);
11}
Dies liefert uns:
1Running Demo with [100, 1, 100, 500, 1, 100, 1, 50, 50] methods 2MIXED Demo completed in 967ms 3Running Demo with 100000000 0ms methods 4MASS Demo completed in 2781ms
Messung erzeugt Overhead
Jede Messung wird die Ergebnisse verzerren. Allgemein spricht man davon, dass der wahre Wert durch sogenannte systematische Fehler sowie zufällige Fehler beeinflusst wird.
Systematische Fehler werden durch Messwerkzeuge hervorgerufen und können in gewissem Maße gemessen oder geschätzt werden. Zufällige Fehler sind jedoch nicht vorhersagbar.
Wenn die CPU Messcode anstelle von echtem Code ausführt sprechen wir in der Regel von „Overhead“, welcher systematische Fehler hervorruft. Jedoch verhindert die verbrauchte CPU Zeit auch möglicherweise die nebenläufige Ausführung von anderem Code und erzeugt so zufällige Fehler, sowohl im gemessenen, als auch im ungemessenen Code. Insbesondere kritisch ist die von aussen messbare Verlangsamung von Transaktionen im System. Erhöhter Ressourcenverbrauch ist in der Regel akzeptabel.
Instrumentierung
Um besser zu sehen was der Demo Code tatsächlich tut, werde ich einen Instrumentierungsagenten auf Basis von AOP mit Hilfe von aspectj loadtime weaving bauen. Dadurch wird vor bestimmten Codestellen mittels einer sogenannten „pointcut expression“ Messcode eingefügt.
aspectj wird dann den Bytecode der Klassen modifzieren, sobald diese geladen werden. Der pointcut-Ausdruck beschreibt die Signatur der zu instrumentierenden Methode.
Ich verwende in diesem Fall einen @Around advice , dem ein sogenannter JoinPoint, also eine Referenz auf die eigentlich auszuführende Codestelle, übergeben wird. Aspectj selbst nutzt einen JVMTI-Agenten um die Bytecodemodifikation für mich durchzuführen. Ich schreibe lediglich den Aspekt in dem ich messe.
Der interessante Teil des codes sieht so aus:
1@Around(" call(void de.codecentric.performance.Demo.method* (..)) ")
2public void aroundDemoMethodCall(final ProceedingJoinPoint thisJoinPoint) throws Throwable {
3 long start = System.currentTimeMillis();
4 thisJoinPoint.proceed();
5 long end = System.currentTimeMillis();
6 String currentMethod = thisJoinPoint.getSignature().toString();
7 if (executionPath.size() < MAX_EXECUTION_PATH) {
8 executionPath.add(currentMethod);
9 }
10 MethodStatistics statistics = methodStatistics.get(currentMethod);
11 if (statistics == null) {
12 statistics = new MoreMethodStatistics(currentMethod);
13 methodStatistics.put(currentMethod, statistics);
14 }
15 statistics.addTime(end - start);
16 overhead += System.currentTimeMillis() - end;
17}
Direkt im Around Advice muss ich schon explizit angeben welche Methoden ich abfangen möchte: call(void de.codecentric.performance.Demo.method* (..)).
Ich speichere zuerst die Startzeit, bevor ich an den eigentlichen Code delegieren. Sobald dieser durchgelaufen ist speichere ich die Endzeit.
Anschließend speichere ich diesen Methodennamen in einem „execution path“, solange dieser das Maximum noch nicht erreicht hat. Ferner ermittele und speichere ich Statistiken für diese Methode. Zuletzt speichere ich die Zeit, die ich für diese Messungen benötigt habe in einem Feld namens „overhead“.
Lasse ich die Demo mit Instrumentierung laufen, so erhalte ich:
1Running Demo with [100, 1, 100, 500, 1, 100, 1, 50, 50] methods 2MIXED Demo completed in 950ms 3Trace Aspect recorded following results: 4 void de.codecentric.performance.Demo.method500ms() 501ms (min: 501ms, max: 501ms) - 1 invocations 5 void de.codecentric.performance.Demo.method100ms() 303ms (min: 101ms, max: 101ms) - 3 invocations 6 void de.codecentric.performance.Demo.method50ms() 102ms (min: 51ms, max: 51ms) - 2 invocations 7 void de.codecentric.performance.Demo.method1ms() 6ms (min: 2ms, max: 2ms) - 3 invocations 8Code Execution Path: 9 void de.codecentric.performance.Demo.method100ms() 10 void de.codecentric.performance.Demo.method1ms() 11 void de.codecentric.performance.Demo.method100ms() 12 void de.codecentric.performance.Demo.method500ms() 13 void de.codecentric.performance.Demo.method1ms() 14 void de.codecentric.performance.Demo.method100ms() 15 void de.codecentric.performance.Demo.method1ms() 16 void de.codecentric.performance.Demo.method50ms() 17 void de.codecentric.performance.Demo.method50ms() 18Agent internal Overhead 2ms 19Agent Overhead 91ms 20 21Running Demo with 100000000 0ms methods 22MASS Demo completed in 7261ms 23Trace Aspect recorded following results: 24void de.codecentric.performance.Demo.method0ms() 2892ms (min: 0ms, max: 2ms) - 100000000 invocations 25Code Execution Path: 26 void de.codecentric.performance.Demo.method0ms() 27 void de.codecentric.performance.Demo.method0ms() 28 [...] 29 void de.codecentric.performance.Demo.method0ms() 30 void de.codecentric.performance.Demo.method0ms() 31Execution Path incomplete! 32Agent internal Overhead 2836ms 33Agent Overhead 4ms
Wir können deutlich sehen, dass die Instrumentierung die Ausführungsreihenfolge sowie genaue Ausführungszeiten korrekt ermittelt hat.
Jedoch sehen wir im zweiten Beispiel ein Problem. Der Ausführungspfad wäre sehr sehr lang gewesen. Um keinen OutOfMemoryError zu erzeugen, musste ich den Pfad limitieren.
Und der Overhead?
Mein Code misst selbständig Overhead, jedoch ist auch diese Messung ungenau. Zum einen ist da der interne overhead, also die Zeit, die der Agent zum Speichern der Statistiken benötigt. Ich habe ihn intern genannt, da er nicht wirklich von der Laufzeit der gemessenen Methode zu trennen ist.
Und dann gibt es den externen overhead, welcher die Zeit zum Starten und Stoppen des Agenten beinhaltet.
Nun ist der Overhead im ersten Beispiel relativ gering, lediglich das Ausgeben der Ergebnisse benötigte etwas Zeit. Dieser Teil ist im zweiten Lauf zwar schneller, jedoch war der interne Overhead enorm. Und es gibt auch noch ein Problem mit der korrekten Ermittlung des Overheads. Die Gesamtzeit minus die Methodenzeit sind ingesamt 7261ms – 2892ms = 4369 ms. Jedoch behauptet der Agent, nur für das Fehlen von 2836ms verantwortlich zu sein. Die fehlende Zeit ist zum einen der Messungenauigkeit, zum anderen dem nicht gemessenen Zusatzcode (wie dem Methodenaufruf von aroundDemoMethodCall(JoinPoint)) geschuldet.
Sampling
Mein Sampling Code ist trivial. Er erzeugt einen Daemon Thread, welcher alle 10 ms in den Main Thread schaut und die Aktivität aufzeichnet. Der interessante Teil ist dieser:
1@Override
2public void run() {
3 lastSample = System.currentTimeMillis();
4 while (true) {
5 try {
6 Thread.sleep(interval);
7 } catch (InterruptedException e) {
8 Thread.currentThread().interrupt();
9 }
10
11 String currentMethod = getCurrentMethod();
12 long currentSample = System.currentTimeMillis();
13
14 addMeasurementsIfStillInMethod(currentMethod, currentSample);
15
16 lastMethod = currentMethod;
17 lastSample = currentSample;
18
19 overhead += System.currentTimeMillis() - currentSample;
20 }
21}
22
23private void addMeasurementsIfStillInMethod(final String currentMethod, final long currentSample) {
24 if (currentMethod.equals(lastMethod)) {
25 MethodStatistics statistics = methodStatistics.get(currentMethod);
26 if (statistics == null) {
27 statistics = new MethodStatistics(currentMethod);
28 methodStatistics.put(currentMethod, statistics);
29 }
30 statistics.addTime(currentSample - lastSample);
31 } else {
32 if (executionPath.size() < MAX_EXECUTION_PATH) {
33 executionPath.add(getParentMethod() + " > " + currentMethod);
34 }
35 }
36}
37
38private String getCurrentMethod() {
39 StackTraceElement topOfStack = monitoredThread.getStackTrace()[0];
40 return formatStackElement(topOfStack);
41}
Der Agent schläft also das vorgegebene Intervall und sucht nach dem Erwachen die aktuell vom Main Thread ausgeführte Methode mittels monitoredThread.getStackTrace()[0]. Dann nimmt er die aktuelle Zeit um herauszufinden wie lange er seit dem letzten Mal wirklich geschlafen hat (zwar sollte dies immer um die 10ms sein, jedoch kann dies auch abweichen!). Dann ermittelt der Agent ob die zuletzt beobachtete Methode immernoch ausgeführt wird. Das ist deshalb wichtig, da nur so der Agent die geschlafene Zeit auf diese Methode aufgerechnet werden kann. Taucht eine neue Methode auf speichern wir diese wieder im Execution Path. Auch hier beachten wir ein eventuelles Limit.
Zuletzt setzen wir den neuen Zustand und berechnen unseren Overhead.
1Agent monitoring thread main with sampling interval of 10ms 2Running Demo with [100, 1, 100, 500, 1, 100, 1, 50, 50] methods 3MIXED Demo completed in 916ms 4Agent stopped - Results: 5 void de.codecentric.performance.Demo.method500ms() 488ms 6 void de.codecentric.performance.Demo.method100ms() 285ms 7 void java.lang.Thread.sleep() 101ms 8Code Execution Path: 9 void de.codecentric.performance.Demo.runCode() > void de.codecentric.performance.Demo.method100ms() 10 void de.codecentric.performance.Demo.runCode() > void de.codecentric.performance.Demo.method500ms() 11 void de.codecentric.performance.Demo.runCode() > void de.codecentric.performance.Demo.method100ms() 12 void de.codecentric.performance.Demo.method50ms() > void java.lang.Thread.sleep() 13Agent internal Overhead 4ms 14Agent Overhead 36ms 15Agent monitoring thread main with sampling interval of 10ms 16 17Running Demo with 100000000 0ms methods 18MASS Demo completed in 2959ms 19Agent stopped - Results: 20 void de.codecentric.performance.Demo.method0ms() 2736ms 21Code Execution Path: 22 void de.codecentric.performance.DemoRunner.massDemo() > void de.codecentric.performance.DemoRunner.massDemo() 23 void de.codecentric.performance.Demo.runCode() > void de.codecentric.performance.Demo.method0ms() 24Agent internal Overhead 0ms 25Agent Overhead 0ms
Wir können gut sehen, dass der Agent durch das Sampling die Ausführungen von einer Millisekunde verpasst hat. Jedoch sehen wir etwas neues: ein Thread.sleep(), welches wir bei der Instrumentierung nicht gesehen haben. Da Sampling über den Stacktrace sehr einfach an die Aufrufhierarchie, z.B. an die aufrufende Methode mittels monitoredThread.getStackTrace()[1] kommt, finden wir heraus, dass die Methode method50ms in wirklichkeit ein Thread.sleep() aufruft.
Doch es fehlen nicht nur die 1 ms Aufrufe, auch sind dadurch die aufeinander folgenden zwei 100 ms Aufrufe als eine 200ms lange Ausführung gesehen worden. Dies glättet quasi die Daten automatisch, indem es die irrelevanten Ausführungen überspringt. Die Ursache dafür ist klar: der Agent kann nichts sehen was kürzer als sein Sampling Intervall ist. Doch es gibt noch andere interesssante Punkte bei der Wahl des Sampling Intervalls zu beachten. Ein gutes Paper zu diesem Thema ist: „Evaluating the Accuracy of Java Profilers “
Wir können beim zweiten Beispiel sehen, dass das Sampling ebensogut die Laufzeit ermittelt hat. Insbesondere gibt es auch kein Problem mit der Execution Path Länge.
Overhead zum Zweiten
Im ersten Beispiel ist der Overhead vergleichbar mit dem der Instrumentierung. Jedoch ist der Overhead im zweiten Beispiel drastisch geringer. Uns fehlen nur 223ms (2959ms – 2736ms), jedoch scheint dies nicht wesentlich in den agenteninternen Messungen zu liegen. Auch läuft der Agent in einem eigenen Thread, weshalb er nicht die Ausführung des gemessenen Codes verlängert und auf Mehrkernsystemen effizienter arbeiten kann.
Zusammenfassung
Sowohl Instrumentierung als auch Sampling haben unterschiedliche Charakteristiken mit ihren eigenen Vor- und Nachteilen.
Diese sind durch die konzeptuellen Unterschiede bedingt und können zwar durch cleveren Aufbau der Agenten vermindert, jedoch nie ganz beseitigt werden.
Instrumentierung
- Hat Zugriff auf die Ausführungsanzahl, genaue tatsächliche/max/min/durchschnittliche Ausführungszeit und genaue Ausführungsreihenfolge.
- Benötigt Konfiguration der zu messenden Codestellen. Konfiguration muss ausbalanciert sein und massenhaft aufgerufene Methoden, sowie Methoden deren Ausführungszeit kürzer als die Messcodezeit ist, ausschließen.
- Produziert erheblich größere Datenmengen.
Sampling
- Stabiler Overhead, der hauptsächlich durch das Samplingintervall, nicht durch den gemessenen Code, bestimmt wird.
- Ausführungshotspots werden anstelle einer feingranularen Codereihenfolge gemessen.
- Kann unbekannten Code aufspüren.
- Läuft effizient auf Mehrkernsystemen.
War dieser Beitrag hilfreich?
Weitere Beiträge
von Fabian Lange
26.3.2015 Dein Job bei codecentric?
Jobs
Agile Developer und Consultant (w/d/m)
Alle Standorte
Gemeinsam bessere Projekte umsetzen.
Wir helfen deinem Unternehmen.
Du stehst vor einer großen IT-Herausforderung? Wir sorgen für eine maßgeschneiderte Unterstützung. Informiere dich jetzt.
Hilf uns, noch besser zu werden.
Wir sind immer auf der Suche nach neuen Talenten. Auch für dich ist die passende Stelle dabei.
Blog-Autor*in
Fabian Lange
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.
Du hast noch Fragen zu diesem Thema? Dann sprich mich einfach an.