Jeder Software Architekt oder Entwickler kann in die Situation kommen, dass die implementierte Lösung partout nicht performt, wie man sich vorgestellt hat. Die heutige Informatikwelt ist so komplex, dass es oft schwer fällt, genau sagen zu können, wo eine Applikation langsam wird und eine gewisse Zeit benötigt für einen Request. Wenn man eine Webapplikation hat, die als VM in einer geteilten Serverlandschaft läuft, und welche dann mit etlichen Threads eine bestimmte Aufgabe in einer Datenbank vornehmen muss, wie soll man da noch wissen, wo Zeit verloren geht? Oder liegt es vielleicht doch an diesem unscheinbaren Webservice Aufruf, der mir eigentlich zu einer ID nur den Kundennamen geben soll? Oder ist die Datenbank nicht richtig indexiert?

Gelobt seien Monitoring Tools

Glücklich kann sich dann schätzen, wer ein Monitoring Tool verwenden kann, welches bei einem Aufruf genau auflistet, welche Zeit von einer Komponente zur nächsten vergeht. Am Besten noch hübsch mit grünen/gelben/roten Balken visualisiert.

Falls man dieses Glück nicht hat, muss man sich selber helfen. Der erste Schritt dabei ist, herauszufinden, wo die Zeit verloren geht. Dazu erstellt man möglichst viele Logging Einträge in seinem System, welche detailliert Aufschluss geben soll.

Nutzt man etwa in Java eine Logging Library wie SLF4J gibt es die Möglichkeit, Logging Einträge nur auszugeben, wenn der DEBUG Modus eingeschalten ist. So kann man die Applikation im Normalmodus im INFO Modus mit einer geringen Anzahl von Logeinträgen laufen lassen. Muss man nun die Performance untersuchen, setzt man den Logging Level auf DEBUG und erhält gleich viel mehr Einträge in seinem Applikationslog.

START und ENDE loggen

An möglichst vielen Stellen soll dabei jeweils ein START und ein END Logeintrag erstellt werden, um die vergangene Zeit herausfinden zu können.

Hier etwa sehen wir, dass die Kontoerstellung genau 100 Millisekunden gedauert hat:

21.10.2016 – 04.40.20.103 – T1400 – START Konto erstellen
21.10.2016 – 04.40.20.203 – T1400 – ENDE Konto erstellen

Dies hört sich trivial an, doch habe ich schon viele Beispiele gesehen, wo zwar der START Eintrag, jeder weitere Logeintrag aber nur in einem Fehlerfall geschrieben wurde. Der „Normalfall“, der erfolgreiche Fall wurde einfach vergessen. Oder es wurde gesagt: „Ist ja logisch, wenn der folgende START Eintrag kommt, der vorherige zu Ende“. Warum einfach, wenn es auch kompliziert geht?

Threads nicht vergessen

Vergessen Sie auch nicht, dass mehrere Threads in dasselbe Logfile schreiben können, wenn Sie nur ein Logfile pro Applikation oder pro Server haben. In diesem Fall gibt man beim Logeintrag die Thread-ID gleich mit an, um die Einträge auseinanderhalten zu können – Im Beispiel oben etwa sind die beiden Einträge vom Thread mit der ID T1400 gschrieben worden.

Auch müssen Sie aufpassen, dass sich in Ihrem Code kein „Synchronized“ Block befindet, welcher als Flaschenhals fungiert und die Threadverarbeitung so bremst.

Klick mich für das Bild in gross

Die roten Pfeile in diesem Bild sollen jeweils ein START und ENDE Paar darstellen. Natürlich ist der Einsatz dieser Logeinträge pro Applikation individuell.

Wenn ich mal einen konkreten Fall dokumentieren kann werde ich diesen hier anfügen.