Messen und Optimieren Benchmarking, Profiling und Tuning von Java Anwendungen

1. Messen und OptimierenBenchmarking, Profiling und Tuning von Java Anwendungen Daniel Klein Michael Piechullek 14. Februar 2005

2. Übersicht • Benchmarking • Profiling • Tuning Strategien • Profiling Tools

3. BenchmarkingÜbersicht • Code-Fragmente, Programmteile oder ganze Anwendungen werden auf bestimmte Kriterien getestet • Verschiedene Arten von Benchmarks: Mikrobenchmark, Makrobenchmark • In der Regel ist kein gutes Mittelmaß zu finden: Entweder testen Benchmarks einzelne Instruktionen ganz genau oder Anwendungen und/oder Systeme als ein ganzes.

4. BenchmarkingMikrobenchmarking • Wird in der Regel benutzt um die Geschwindigkeit einzelner Instruktionen oder Funktionen zu testen. • Eine Instruktion/Funktion wird oft auf Grund der Schnelligkeit viele tausend mal ausgeführt um zuverlässige Ergebnisse erhalten zu können.  Entspricht nicht unbedingt der Praxis. • Mögliche Verfälschungen der Messergebnisse auf Grund einer ungenauen Zeitbasis beachten!Zum Beispiel System.getMilliSeconds(): • Laufzeit ca. 1/2 ms, also muss der Benchmark mindestens 100 ms laufen um die Messungenauigkeit nur für das abfragen der Zeit auf unter 1% zu drücken. (Besser: Laufzeiten von 1 s und mehr.) • Auch liefert System.getMilliSeconds() nicht immer ein aktuelles Ergebnis. Auf manchen Systemen nur ein Update alle 10-50 ms! (Besonders kleinere Mobilgeräte wie Palm PCs oder Mobiltelefone.)

5. BenchmarkingMakrobenchmarking • Testet in der Regel Anwendungen als ganzes • Ergebnisse sind aber auch Abhängig von Systemfaktoren: Verfügbarer Speicher, VM, Hardware, andere Software die parallel läuft.(Für Tests am besten Zielsystem verwenden.) • Makrobenchmarks versuchen automatisiert den Arbeitsablauf des Benutzers zu simulieren. (Möglichst mit reellen Daten.) • Laufzeit deutlich länger als bei Mikrobenchmark: Minuten, Stunden oder sogar Tage üblich.

6. ProfilingÜbersicht • Warum ist die Anwendung langsam? • Was tunen? • Was messen? • Was man nicht messen kann: Empfundene Geschwindigkeit

7. ProfilingWarum ist die Anwendung langsam? • Weil sie nicht den Erwartungen entspricht! • Lösung: • Überprüfen ob die Erwartungen nicht evtl. zu hoch gesteckt sind. (Gerade nicht-Techniker neigen zur Übertreibung.) • Vor dem optimieren ein Soll definieren. • Optimieren in der richtigen Reihenfolge bis Ziel erreicht ist…

8. ProfilingWas tunen? • We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil.– Donald Knuth • Vorzeitiges oder übertriebenes optimieren macht es nur noch schlimmer.  Überlegen ob Optimierung wirklich Sinn macht. • Unwichtiges zu optimieren braucht endlos viel Zeit und bringt so gut wie keine Verbesserungen • Stattdessen: Lokalisieren von Stellen an denen die Anwendung Schwachstellen aufweist

9. ProfilingWas tunen? • Erster Schritt: Algorithmen(mehr dazu später) • Zweiter Schritt: „Glue Logic“Engpässe („Bottlenecks“) finden.Verbindungen zwischen verschiedenen Modulen können die Software ausbremsen obwohl sie einzelnen schon optimiert worden sind. • Dritter Schritt: FeintuningNur wenn unbedingt nötig!Aufwand > Nutzen • Letzte Chance: Hardware tauschen… ;-)

10. ProfilingWas messen? • Lässt sich nicht unbedingt pauschal beantworten, jede Anwendung ist anders. • Immer sinnvoll: • Ausführungsgeschwindigkeit • Anzahl der Objekte • Speicherverbrauch • Anzahl Garbage Collections • Je nach Anwendung sinnvoll: • Datendurchsatz von/zur Festplatte • Datendurchsatz im Netzwerk • Anzahl der Netzwerk Pakete und/oder Anfragen • Antwortzeit für die bearbeitung einer Anfrage (Server) • etc…

11. ProfilingWas man nicht messen kann:Empfundene Geschwindigkeit • Eine nicht zu vernachlässigende Komponente, wichtig für alle GUIs. • Reagiert die Oberfläche zu langsam macht die gesamte Anwendung für den Bennutzer den Eindruck langsam zu sein. • Auch wichtig: Bei längeren Wartezeiten den Benutzer informieren. • Problem: Solche Eindrücke sind nur schwer automatisiert zu testen. Praktische Tests mit Personen durchführen!(Am besten mit der selben Hardware wie später für den Regelbetrieb vorgesehen.)

12. Tuning StrategienÜbersicht Einige übliche Tuningmöglichkeiten: • Bessere Algorithmen • Objekterzeugung • Garbage Collection • Methodenaufrufe minimieren

13. Tuning StrategienBessere Algorithmen • Beste Optimierungschancen • Nicht der Code wird optimiert, sondern die Logik • Fragen: • Ist der verwendete Algorithmus geeignet für die Anforderungen der Anwendung? • Gibt es eine schnellere Alternative? • Wie viel Zeitaufwand bedeutet die Implementierung einer möglichen Alternative, und wie viel Performanceunterschied könnte Sie bringen?

14. Tuning StrategienObjekterzeugung • Bei neueren VMs kein großes Problem mehr da schnelle O(1) Allokation • Trotzdem Erzeugung von übermäßig vielen Objekten vermeiden • Zum Beispiel: Objektpools verwenden, nur mit unveränderlichen Klassen arbeiten wenn sinnvoll • Das Erzeugen unnötig vieler Objekte, führt zur erhöhter Aktivität des Garbage Collectors

15. Tuning StrategienGarbage Collection • Bei neueren VMs kein großes Problem mehr (da schneller Generational Garbage Collector) • Das Einsammeln kurzlebiger Objekte ist schnell • Trotzdem Erzeugung von übermäßig vielen Objekten vermeiden

16. Tuning StrategienMethodenaufrufe minimieren • Methodenaufrufe erzeugen einen (wenn auch minimalen) Overhead • Durch wiederholtes Aufrufen summiert sich der Overhead jedoch • Bei neueren VMs nicht sehr relevant, da HotSpot Compiler via inlining optimieren kann.(In der Regel sogar deutlich besser als der Programmierer.)Aber die Möglichkeiten sind begrenzt: Rekursive Algorithmen, zum Beispiel, lassen sich so nicht bedeutend beschleunigen.

17. Tuning StrategienFazit • Kleinere Codeoptimierungen lohnen sich durch HotSpot Compiler kaum noch. Bei anderen (einfacheren) VMs weiterhin sinnvoll • Generell Ressourcen schonendes Programmieren immer sinnvoll • Rules of Optimization: Rule 1: Don’t do it.Rule 2: (for experts only): Don’t do it yet.– M. A. Jackson

18. Profiling ToolsÜbersicht • Unzählige Tools verfügbar • Teilweise sehr teure, kommerzielle Tools, aber auch kostenlose oder Open Source Tools • Umfang und Funktionalität der Software oft ziemlich ähnlich • Für diese Präsentation: Fokus auf Techniken und Tools die jederzeit zur Verfügung stehen, sowie ein kommerzielles Tool als Beispiel

19. Profiling Tools Taskmanager

20. Profiling Tools Manuelles Zeit messen private static final Stack profilingStack= new Stack(); /** * Start profiling by remembering the actual system time. * NOTE: This profiler is NOT able to handle multithreaded usage. */ public static final void startProfiling() { profilingStack.push( new Long(System.currentTimeMillis()) ); } /** * Stop profiling and return elapsed time. * @return The time elapsed since the call of startProfiling(). */ public static final long stopProfiling() { // first, remember the stop time, to avoid delays long stopTime= System.currentTimeMillis(); // check if there is at least one element left on the stack if( profilingStack.empty() ) throw new java.lang.IllegalStateException( "The count of profiling start and stop doesn't match!" ); // get start value long startTime= ((Long)profilingStack.pop()).longValue(); return stopTime - startTime; } Benutzung: profiler.startProfiling();testMethod()long duration= profiler.stopProfiling();System.out.println( duration ); Ab Java 5: Genaueres Timing mittels System.nanoTime();

21. Profiling Tools „static“ Zähler in der Klasse zum zählen der Instanzen public class StaticTest extends InstanceCounter { public StaticTest() { System.out.println( count ); } public static void main(String[] args ) { new StaticTest(); new StaticTest(); new StaticTest(); new StaticTest(); new StaticTest(); new StaticTest(); } public abstract class InstanceCounter { public static int count; public InstanceCounter() { count++; } public void finalize() { count--; } }

22. Profiling Tools „Verbose“ Ausgabe der VM

23. Profiling Tools Xprof Parameter der VM (benutzt JVMPI) C:\work\studium\Software Tools WPF>java -Xprof -jar NetFlow.jar Flat profile of 0.36 secs (27 total ticks): main Interpreted + native Method 7.7% 2 + 0 java.util.Hashtable.get 3.8% 0 + 1 sun.awt.windows.WDesktopProperties.init 3.8% 0 + 1 sun.awt.windows.WComponentPeer.pShow 3.8% 0 + 1 java.io.WinNTFileSystem.checkAccess 3.8% 0 + 1 java.util.zip.ZipFile.open 3.8% 0 + 1 java.util.zip.ZipFile.getEntry 3.8% 1 + 0 java.io.ExpiringCache$Entry.<init> 3.8% 1 + 0 java.nio.ByteBufferAsShortBufferB.get 3.8% 1 + 0 java.awt.Insets.<init> 3.8% 1 + 0 sun.java2d.loops.GraphicsPrimitiveMgr$2.compare 3.8% 1 + 0 javax.swing.JRootPane.createLayeredPane 3.8% 1 + 0 java.lang.Class.searchFields 3.8% 1 + 0 java.util.Properties.enumerate 3.8% 1 + 0 java.nio.ByteBuffer.get 3.8% 1 + 0 sun.java2d.loops.GraphicsPrimitiveMgr.register 3.8% 1 + 0 java.lang.ClassLoader.loadClass 3.8% 0 + 1 sun.awt.windows.WDesktopProperties.initIDs 3.8% 1 + 0 sun.font.CompositeFont.getSlotFont 3.8% 1 + 0 javax.swing.JTextField.<init> 3.8% 1 + 0 java.lang.reflect.Method.invoke 3.8% 1 + 0 java.io.Win32FileSystem.normalize 3.8% 1 + 0 java.awt.Component.show 3.8% 1 + 0 sun.nio.ch.IOUtil.readIntoNativeBuffer 3.8% 1 + 0 java.awt.color.ColorSpace.getInstance 3.8% 1 + 0 sun.nio.cs.ISO_8859_1$Decoder.decodeArrayLoop 100.0% 20 + 6 Total interpreted Thread-local ticks: 3.7% 1 Blocked (of total) Flat profile of 36.20 secs (3332 total ticks): AWT-Windows Interpreted + native Method 99.9% 0 + 3329 sun.awt.windows.WToolkit.eventLoop 0.0% 1 + 0 sun.awt.AWTAutoShutdown.isReadyToShutdown 0.0% 1 + 0 java.awt.EventQueue.wakeup 0.0% 0 + 1 sun.awt.windows.WToolkit.init 100.0% 2 + 3330 Total interpreted Flat profile of 35.82 secs (3307 total ticks): DestroyJavaVM Thread-local ticks: 100.0% 3307 Blocked (of total)

24. Profiling Tools Monitoring and Management Extensions (JMX/MX Beans) • Neu ab Java 5 • Bietet Schnittstelle zum abfragen und setzen von Informationen über die virtuelle Maschine zur Laufzeit. • Offene APIs: Java Management Extensions (JSR-003) und JMX Remote API (JSR-160) • Monitoring Lokal oder Remote (+ Verschlüsselung) • Management Tool(s) direkt bei JDK dabei • Via Beans in eigene Anwendung integrierbar • Erweiterbar

25. Profiling Tools Monitoring and Management Extensions (JMX/MX Beans) • Verfügbare Standard Beans: • ClassLoadingMXBean • CompilationMXBean • GarbageCollectorMXBean • MemoryMXBean • MemoryManagerMXBean • MemoryPoolMXBean • OperatingSystemMXBean • RuntimeMXBean • ThreadMXBean

26. Profiling Tools JVM Stat (benutzt JMX) C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -options -class -compiler -gc -gccapacity -gccause -gcnew -gcnewcapacity -gcold -gcoldcapacity -gcpermcapacity -gcutil -printcompilation C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -class 2836 1000 Loaded Bytes Unloaded Bytes Time 30 36,4 0 0,0 0,02 30 36,4 0 0,0 0,02 30 36,4 0 0,0 0,02 30 36,4 0 0,0 0,02 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -compiler 2836 1000 Compiled Failed Invalid Time FailedType FailedMethod 50 0 0 0,03 0 50 0 0 0,03 0 50 0 0 0,03 0 50 0 0 0,03 0 50 0 0 0,03 0 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -gccapacity 2836 1000 NGCMN NGCMX NGC S0C S1C EC OGCMN OGCMX OGC OC PGCMN PGCMX PGC PC YGC FGC 640,0 4992,0 640,0 64,0 64,0 512,0 1408,0 60544,0 1408 ,0 1408,0 8192,0 65536,0 8192,0 8192,0 2 0 640,0 4992,0 640,0 64,0 64,0 512,0 1408,0 60544,0 1408 ,0 1408,0 8192,0 65536,0 8192,0 8192,0 2 0 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -gc 2836 1000 S0C S1C S0U S1U EC EU OC OU PC PU YGC YGCT FGC FGCT GCT 64,0 64,0 64,0 0,0 512,0 149,4 1408,0 390,1 8192,0 187,9 2 0,014 0 0,000 0,014 64,0 64,0 64,0 0,0 512,0 149,4 1408,0 390,1 8192,0 187,9 2 0,014 0 0,000 0,014 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -gcnew 2836 1000 S0C S1C S0U S1U TT MTT DSS EC EU YGC YGCT 64,0 64,0 64,0 0,0 1 31 32,0 512,0 149,4 2 0,014 64,0 64,0 64,0 0,0 1 31 32,0 512,0 149,4 2 0,014 64,0 64,0 64,0 0,0 1 31 32,0 512,0 149,4 2 0,014 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -gcutil 2836 1000 S0 S1 E O P YGC YGCT FGC FGCT GCT 100,00 0,00 29,17 27,71 2,29 2 0,014 0 0,000 0,014 100,00 0,00 29,17 27,71 2,29 2 0,014 0 0,000 0,014 100,00 0,00 29,17 27,71 2,29 2 0,014 0 0,000 0,014 C:\Programme\Java\jdk1.5.0_01\bin>jstat.exe -printcompilation 2836 1000 Compiled Size Type Method 50 104 1 java/awt/GradientPaintContext cycleFillRaster 50 104 1 java/awt/GradientPaintContext cycleFillRaster 50 104 1 java/awt/GradientPaintContext cycleFillRaster 50 104 1 java/awt/GradientPaintContext cycleFillRaster 50 104 1 java/awt/GradientPaintContext cycleFillRaster 55 111 1 java/util/HashMap get 55 111 1 java/util/HashMap get 58 30 1 java/awt/Component inside 84 468 1 sun/java2d/SunGraphics2D getCompClip 86 0 1 java/lang/Object hashCode 86 0 1 java/lang/Object hashCode 90 13 1 java/util/Hashtable isEmpty 102 723 1 java/awt/Toolkit$SelectiveAWTEventListener eventDispatched 135 29 1 java/awt/EventQueue noEvents 145 11 1 java/awt/geom/LineIterator next 145 11 1 java/awt/geom/LineIterator next 145 11 1 java/awt/geom/LineIterator next 145 11 1 java/awt/geom/LineIterator next

27. Profiling Tools JConsole (benutzt JMX)

28. Profiling Tools JConsole

29. Profiling Tools JConsole

30. Profiling Tools JConsole

31. Profiling Tools Visual GC (benutzt JMX)

32. Profiling Tools Borland OptimizeIt

33. Profiling Tools Borland OptimizeIt

34. Profiling Tools Borland OptimizeIt

35. Profiling Tools Borland OptimizeIt

36. Profiling Tools Borland OptimizeIt – Code Coverage

37. Bücher und Artikel • Schreiber, Hendrik: Performant Java Programmieren; Addison-Wesley, 1. Auflage, 2002(Deutsch) • Shirazi, Jack: Java Performance Tuning; O’Reilly, First edition, September 2000 (Englisch) • So wie unzählige Artikel im Internet (Qualität und Belegbarkeit oft fraglich)

38. Vielen Dank für Ihre Aufmerksamkeit !