Wenn’s mal wieder länger dauert… Profiling Robot Framework

Tests, die man typischerweise mit Hilfe des Robot Framework realisiert (z.B. User Acceptance Tests), neigen dazu, nicht ganz so flott durchzulaufen wie vielleicht Unit-Tests. In aller Regel reden wir hier von Stunden und nicht mehr von Minuten. Egal, ob man diese Tests vielleicht in die Nacht verschieben kann, lästig ist es trotzdem. Auch die parallele Ausführung auf mehreren Testclients bekämpft nur die Symptome.

Wie man es auch nimmt, von Zeit zu Zeit wäre es einfach verdammt nützlich feststellen zu können, wo der Robot die Zeit liegen lässt. Zeit für Profiling!

Das standardmäßig erstellte output.xml-Log-File enthält eigentlich alle benötigten Informationen. Jedes ausgeführte Keyword ist dort mit einem Tag enthalten. Dieses Tag enthält als geschachteltes Element ein status-Tag, in dem die Anfangs- und Endzeit der Keyword-Ausführung verzeichnet sind. Fehlen also nur noch Werkzeuge zur Aufbereitung und Auswertung dieses Informationen…

time2csv.py aus dem Robot Framework

Ein Werkzeug ist Bestandteil des Robot Framework, wird allerdings nur in der Source-Distribution ausgeliefert. Das Python-Script „times2csv.py “ berechnet die Laufzeit jedes Keywords und stellt es innerhalb der Aufrufhierarchie dar. Die Daten werden als CSV-Datei geschrieben und eignen sich gut für eine Darstellung und Auswertung in Excel oder einer anderen Tabellenkalkulationen.

Diese Form der Auswertung ist natürlich dann gut geeignet, wenn man einen konkreten Abschnitt seiner Testsuite analysieren will. Man muss also bereits den konkreten „Flaschenhals“ entdeckt oder zumindest einen Verdächtigen bestimmt haben. Ansonsten geht man in den Informationen unter, insbesondere bei umfangreichen Testsuiten. (Bei der Auswertung eines typischen Logs in einem Projekt hatten die erstellten drei Dateien insgesamt ~2,3 Mio. Zeilen Umfang, die größte mit fast 900.000 Zeilen…)

Robot Framework mit robot_profiler.py analysieren

Was aber tun, wenn man noch keine Ahnung hat, wo die Zeit bleibt oder wenn man den Verdacht hat, in einigen Keywords immer nur etwas Zeit zu verlieren, was sich dann erst durch eine hohe Aufrufanzahl negativ auswirkt? Für diese Situation braucht man eine andere Auswertung: Die aufsummierte Laufzeit je Keyword und die durchschnittliche Laufzeit je Keyword.

Für diesen Zweck habe ich ein kleines Python-Script geschrieben. Es ist in GitHub verfügbar.

Das Script kennt die folgenden Kommandozeilenparamenter:

usage: robot_profiler.py [-h] [-e ENCODING] [-s SEPARATOR] [-l LOCALE]
                         input_file_name [output_file_name]

positional arguments:
  input_file_name       The output.xml file to read from.
  output_file_name      The file to write the profiler data to.

optional arguments:
  -h, --help            show this help message and exit
  -e ENCODING, --encoding ENCODING
                        Encoding for output file.
  -s SEPARATOR, --separator SEPARATOR
                        Separator used in output file.
  -l LOCALE, --locale LOCALE
                        Locale used for number formatting.

Wird keine Ausgabedatei angegeben, wird der Name (und Pfad) der Eingabedatei genommen und die Extension auf ‚.csv‘ gesetzt.

Die Parameter -e, -s und -l sind optional. Hier kann das Encoding, der Spaltentrenner und die gewünschte Lokalisierung für das Zahlenformat festgelegt werden. Die Default-Werte sind so festgelegt, dass die Ausgabedatei als CSV-Datei direkt mit Excel geöffnet werden kann (wohl der häufigste Anwendungsfall…): Als Encoding wird cp1252 verwendet (also Windowsstandard) und als Trenner wird das Semikolon eingesetzt (im Gegensatz zum Komma wird es von Excel beim Öffnen mit Doppelklick als Trenner erkannt). Wenn man eine TSV-Datei (tab separated values) benötigt, so kann man das mit -s \t erreichen. Die Lokalisierung hat keinen expliziten Default, so dass das Script den Plattformstandard verwendet. Bei der Lokalisierung ist zu beachten, dass die Werte u.U. plattformabhängig sind. So ist „Deutsch“ unter Linux als de_DE kodiert, unter Windows aber als German…

Für die Ausführung dieses Scripts mit Output-Dateien von ‚echten‘ Testläufen (also alles, was nicht zu trivialen Testzwecken gedacht ist) würde ich immer natives Python empfehlen, denn leider ist Jython hinsichtlich des Speicherverbrauches wohl eher ineffizient und langsam (falls es überhaupt durchläuft und nicht mit einem Fehler aussteigt…). Falls kein Python zur Hand ist oder man Python nicht extra installieren will, kann man immer noch auf PortablePython ausweichen.

Das Script erzeugt eine Ausgabedatei, die in aller Regel mit einem Doppelklick in MS Excel geöffnet werden kann. Neben dem (vollqualifizierten) Keyword-Bezeichner sind die Anzahl der Aufrufe, die Gesamtausführungszeit und die durchschnittliche Ausführungszeit aufgeführt.

Wenn man sich nun auf die Suche nach einem Flaschenhals macht, würde ich vorschlagen, die Liste in eine Tabellenkalkulation zu laden, nach der durchschnittlichen Laufzeit absteigend zu sortieren und dann alle Durchschnittswerte kleiner 1 Sekunde wegfiltern zu lassen. Die Ergebnisliste ist dann hoffentlich übersichtlich genug für eine eingehende Untersuchung.

Viel Spaß beim Testen 🙂

Links

• time2csv.py – http://code.google.com/p/robotframework/wiki/ExecutionTimeReportingTool
• robot_profiler.py – https://github.com/jzdunek/robot-profiler