Performanceanalyse mit JVisualVM – evil synchronized

In einem meiner kleinen Projekte werden an einer Stelle etliche Threads gestartet, die jeweils ein Bild einlesen, skalieren und wieder auf die Platte schreiben. – Die ganze Zeit hat mich schon das Gefühl beschlichen, dass das zu langsam läuft, untersucht hatte ich das bisher nur nie. Nachdem genau diese Funktionalität heute definitv zu langsam war, kam ich um eine Analyse wohl doch nicht mehr herum. Also erst mal untersuchen, was da vor sich geht:

  • Programm gestartet,
  • JVisualVM gestartet (zu finden im bin-Verzeichnis einer JDK-Installation),
  • VisualVM auf das laufende Programm verbunden, und die Threads anzeigen lassen
  • kritische Funktion im Programm gestartet

Und siehe da: die Threads werden gestartet, aber nur immer genau einer ausgeführt (siehe Bild). Alle anderen Threads die laufen sollten stehen auf “Monitor”. Das ist leicht daran zu erkennen, dass zwar alle PictureScaleWorker ausgeführt werden, aber niemals gleichzeitig alle grün (also im Running State) sind sondern immer nur einer. Na das sollte ja nicht so sein!

Aber was machen die eigentlich und worauf warten die? Also erst mal einen Thread Dump erstellen (Button oben rechts), vielleicht bringt der ja ein paar Infos:

Dann zu einem der betreffenden Threads scrollen und nachsehen, ob dort etwas auffällig ist.

Thread.State: BLOCKED (on object monitor)
at de.locked.gallery.utils.ImageUtils.read (ImageUtils.java:83)

Blocked on object monitor – das sieht nach einem synchronized aus. Und betreffende Zeile 83 ist tatsächlich synchronized – was ich bei einem der letzten Refactorings offenbar übersehen habe. Mittlerweile ist die Synchronisierung auf dieser Methode zum Glück nicht mehr nötig und ich kann die Einschränkung ohne Gewissenbisse entfernen. Und siehe da, auf einmal laufen auch alle Threads gleichzeitig, was auf 8 Kernen doch einen spürbaren Unterschied macht. – Willkommen im Multi-Core Zeitalter.

Ohne die JVisualVM wäre ich früher oder später wohl auch an die Stelle gekommen – aber ich bezweifle ernsthaft dass ich die Stelle innerhalb weniger Minuten gefunden hätte.

Dazu auch ein interessantes Video.