Python: Performance Test Framework

Auf der Suche nach immer besseren Programmen, kommt man früher oder später nicht umhin, unterschiedliche Implementierungen miteinander zu vergleichen. Und da das schnell unübersichtlich wird, möchte ich an dieser Stelle einen Ansatz vorstellen, der Euch wieder mehr Spaß am Testen und Vergleichen bringt.

Testen und Vergleichen beschreiben dabei auch schon die beiden wesentlichen Anforderungen.

  • Testen: Programmalternativen erzeugen unterschiedliche Testergebnisse
  • Vergleichen: Die Aufbereitung der Testergebnisse verdeutlicht wesentliche Vor-/Nachteile

In diesem Artikel geht es dabei allein um die Erzeugung der Testergebnisse.

Testen mit System

Tests tragen seit je her zur Verbesserung von Leistung und Qualität bei. So auch in der Softwareentwicklung, wo unter dem Begriff Unit Test das systematische und automatisierte Prüfen von Komponenten Anwendung findet. Die Testgetriebene Entwicklung (TDD) geht sogar einen Schritt weiter. Sie macht den zu erfüllenden Testfall zum Ausgangspunkt und nutzt ihn zugleich als Leitmotiv.

Unter Python können Entwickler schon mit Bordmitteln ganz einfach Tests entwickeln und laufen lassen. Die System Bibliothek unittest macht es möglich. Vielfältige Dokumentation zum Thema runden das Bild ab und ich fange direkt bei der Nutzung für Performance Tests an.

Performance Tests

Leistungstests sind im Grunde Erweiterungen von Unit Tests. Wo Unit Tests nur die Richtigkeit von Programmablauf und Ergebnissen klarstellen, liefern Leistungstests zusätzliche Informationen zu verschiedenen Leistungskenngrößen wie z.B. allen voran: Die benötigte Ausführungszeit.

Hierfür habe ich in nachfolgendem Beispiel auf der unittest System Bibliothek aufgebaut und die Klasse TestCase so erweitert, dass nun Ausführungszeiten zusammen mit:

  • mod:test_ist_gen_1.py
  • cls:{self.__class__.__name__}
  • fun:{method.__name__}
  • time:{time.perf_counter()-startTime}

Name der Modul Quell Datei
Name der Test Fall Klasse
Name der Test Methode
Ausführungszeit


.. ausgegeben werden.

Inhaltlich werden nur 2 verschiedene Tests dargestellt, die einmal eine Liste mit 10 Mio. [15-16] fortlaufenden Zahlen generiert und einmal mit 20 Mio [18-19].

Datei: test_list_gen_1.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import unittest, time

class PerformanceTestCase(unittest.TestCase):
    def _callTestMethod(self, method):
        startTime = time.perf_counter() 
        method()
        print( f"mod:test_list_gen_1.py; cls:{self.__class__.__name__}; " \
               f"fun:{method.__name__}; time:{time.perf_counter()-startTime}" )
        
class ListGenPerformanceTestCase1(PerformanceTestCase):
    def test_ListGen_10M(self):
        list( range(10*1000*1000) )
        
    def test_ListGen_20M(self):
        list( range(20*1000*1000) )

if __name__ == '__main__':
    unittest.main()

Wie sonst auch, nutze ich für die Tests das PyDevEclipse Plug-In, welches einen eigenen Python Unit-test Run Modus zur Verfügung stellt. Der Aufruf erfolgt z.B. über das Menü:

Run/Run As/2 Python unit-test.

Und belohnt uns direkt mit der Ausgabe der Test Ergebnisse.

Was ich, wenn wir später unterschiedliche Module entwickeln, besonders hilfreich finde ist, dass die Ausgabe des Modul Datei Namens in der Konsole auch gleich einen blau unterstrichenen Link erzeugt, der bei Klick direkt das Editor Fenster für die entsprechende Quell Datei öffnet.

Und hiermit ist eigentlich auch schon alles Wesentliche gesagt, wenn man nur wenige Test Fälle hat und die Ergebnisse nicht weiterverarbeiten will.


Aber für die bessere Wiederverwendbarkeit lohnt es sich, etwas Refactoring zu betreiben. Hierzu verlagern wir einfach die Klasse PerformanceTestCase in eine neue Datei und ermitteln den Namen der Test Modul Datei nun relativ zum Arbeitsverzeichnis [11-12]. Somit lassen sich auch Tests in Unterverzeichnissen gut lokalisieren.

Datei: performance_test.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import unittest, time, os, sys

class PerformanceTestCase(unittest.TestCase):
    def _callTestMethod(self, method):
        startTime = time.perf_counter() 
        method()
        module = os.path.relpath( sys.modules[self.__class__.__module__].__file__, 
                                  os.path.curdir )
        print( f"mod:{module}; cls:{self.__class__.__name__}; " \
               f"fun:{method.__name__}; time:{time.perf_counter()-startTime}" )

Der eingangs beschriebene Test Fall gestaltet sich somit wie folgt:

Datei: test_list_gen_2.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import performance_test, unittest

class ListGenPerformanceTestCase2(performance_test.PerformanceTestCase):
    def test_ListGen_10M(self):
        list( range(10*1000*1000) )
        
    def test_ListGen_20M(self):
        list( range(20*1000*1000) )

if __name__ == '__main__':
    unittest.main()

Und liefert erwartungsgemäß:

Wenn man sich die Ausgabe:

mod:test_list_gen_2.py; cls:ListGenPerformanceTestCase2; fun:test_ListGen_10M; time:0.2875997
mod:test_list_gen_2.py; cls:ListGenPerformanceTestCase2; fun:test_ListGen_20M; time:0.5423842

.. etwas genauer ansieht, fällt schnell das Schema ins Auge und erinnert an CSV. Hier werden einzelne Spaltenwerte durch Semikolon getrennt und zur besseren Lesbarkeit noch ein Leerzeichen eingefügt. Aber CSV ist ein Dateiformat. Und wir müssen für die Dateiausgabe performance_test.py noch etwas anpassen.

Nachfolgend lässt sich nun mit setLogFile [7-8] festlegen, in welche Datei die Performance Logs geschrieben werden sollen und wenn ein setLogFile.Name [19] gesetzt ist, wird die Log Zeile an diese Datei angehängt [20-21] zusätzlich zur Bildschirmausgabe [18].

Datei: performance_test.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import unittest, time, os, sys

def setLogFile(fileName=None, path="log"):
    setLogFile.Name = f"{os.path.join( path, fileName )}" if fileName else None

class PerformanceTestCase(unittest.TestCase):
    def _callTestMethod(self, method):
        startTime = time.perf_counter() 
        method()
        module = os.path.relpath( sys.modules[self.__class__.__module__].__file__,
                                  os.path.curdir )
        line = f"mod:{module}; cls:{self.__class__.__name__}; " \
               f"fun:{method.__name__}; time:{time.perf_counter()-startTime}"
        print(line)
        if hasattr(setLogFile, 'Name') and setLogFile.Name:
            with open(setLogFile.Name, "a+") as logFile:
                logFile.write(line + "\n")

Das unittest Framework erlaubt es uns auch setUp und tearDown Code zu spezifizieren, der im Falle von setUpModule() [7-8] und tearDownModule() [10-11] jeweils vor Laden der Modul Datei bzw. nach Beendigung der darin enthaltenen Tests und Entladen des Moduls ausgeführt wird. Hier zur Initialisierung/Bereinigung der Testumgebung setzen wir einfach den Namen der Log Datei.

Datei: test_list_gen_3.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import performance_test, unittest

def setUpModule():
    performance_test.setLogFile("test_list_gen_3.log")

def tearDownModule():
    performance_test.setLogFile(None)

class ListGenPerformanceTestCase3(performance_test.PerformanceTestCase):
    def test_ListGen_10M(self):
        list( range(10*1000*1000) )
        
    def test_ListGen_20M(self):
        list( range(20*1000*1000) )

if __name__ == '__main__':
    unittest.main()

Die Konsolen Ausgabe ändert sich nicht wesentlich. Daher nachfolgend nur die Ergebnis Log Datei:

Nun fehlt nur noch die Möglichkeit, selbstdefinierte Leistungskenngrößen in das Test Ergebnis mit aufzunehmen. Aber das holen wir mit dieser Ergänzung nach:

Datei: performance_test.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import unittest, time, os, sys

def setLogFile(fileName=None, path="log"):
    setLogFile.Name = f"{os.path.join( path, fileName )}" if fileName else None

class PerformanceTestCase(unittest.TestCase):
    def _callTestMethod(self, method):
        def _log(line):
            print(line)
            if hasattr(setLogFile, 'Name') and setLogFile.Name:
                with open(setLogFile.Name, "a+") as logFile:
                    logFile.write(line + "\n")            
        
        startTime = time.perf_counter() 
        module = os.path.relpath( sys.modules[self.__class__.__module__].__file__,
                                  os.path.curdir )

        try: 
            r = method()
            r_values = [f"; {k}:{r[k]}" for k in r] if type(r) is dict else []
            _log( f"mod:{module}; cls:{self.__class__.__name__}; " \
                  f"fun:{method.__name__}; time:{time.perf_counter()-startTime}" + 
                  "".join(r_values) )
        except Exception as e:
            _log( f"mod:{module}; cls:{self.__class__.__name__}; " \
                  f"fun:{method.__name__}; err:{e.__class__.__name__}({e})" )
            raise

Was sicher gleich ins Auge fiel, war der in try/except [22-31] gefasste Code für den Test Methoden Aufruf [23] und das Loggen seines Ergebnisses [25-27]. Dabei wurde im Erfolgsfall das Test Ergebnis (vom Typ Dictionary) mit seinen Schlüsseln und Werten im gleichen CSV Schema [24] wie zuvor an die Log Ausgabe mit angehängt [27]. Sollte die Testmethode eine Ausnahme erzeugen, loggen wir anders als sonst nur Modul, Klasse, Methode und unter dem Feld Namen err den Typ der Exception samt Value mit [29-30].

Alles, was dafür bei der Definition des Test Falles nachfolgend benötigt wird, ist entweder die Rückgabe eines Dictionary mit den ermittelten Leistungskenngrößen [19] oder wie im Beispiel auch demonstriert, das Auftreten einer Exception [23].

Datei: test_list_gen_4.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
'''
Created on 28.09.2020
@author: Mike Ziebeck
'''
import performance_test, unittest, sys

def setUpModule():
    performance_test.setLogFile("test_list_gen_4.log")

def tearDownModule():
    performance_test.setLogFile(None)

class TestException(Exception):
    pass

class ListGenPerformanceTestCase4(performance_test.PerformanceTestCase):
    def test_ListGen_10M(self):
        result = list( range(10*1000*1000) )
        return {"len": len(result), "size": sys.getsizeof(result)}
        
    def test_ListGen_20M(self):
        list( range(20*1000*1000) )
        raise TestException("Demonstrating Exceptions")

if __name__ == '__main__':
    unittest.main()

.. liefert nun

  1. Timing mit Leistungskenngrößen der erzeugten Datenstruktur
    • (len = Anzahl der Elemente; size = Speicher Verbrauch)
  1. Namen und Wert des aufgetretenen Fehlers. (err)

Die mitgeloggten Einträge sind folglich:

Da wir nun schon eine kleine Anzahl an Test Fällen zusammen bekommen haben, macht es Sinn, einmal darüber nachzudenken, wie alle Tests in einem Rutsch absolviert werden können.

Mit PyDev geht es ganz einfach über das Kontext Menu des Projektes. Hier PY_performance_test.

Doch ach du Schreck! Wir hatten eigentlich nur einen einzigen Fehler erwartet. Stattdessen erschlägt uns das hier:

Ganz ans Ende der Konsolen Ausgabe gescrollt, offenbart uns die Zusammenfassung, dass 4 statt 1 Test fehlgeschlagen sind. Aber die Fehlermeldung verrät uns auch, was schiefgelaufen ist.

FileNotFoundError: [Errno 2] No such file or directory: 'log\\test_list_gen_4.log'

.. und zwar ließ sich wohl die Log Datei nicht finden. Da aber diese - bei Fehlen einfach erstellt wird, kann eigentlich nur der Verzeichnis Name die Ursache sein. Ein Blick in die durch unseren Test Lauf erzeugte RUN Konfiguration:

… offenbart das falsch gesetzte Arbeitsverzeichnis, was korrigiert:

… nun erwartungsgemäß den einen provozierten Fehler liefert – zusammen mit Anzahl und Ausführungsdauer aller Test Fälle.

Per Kommandozeile startet man den Testlauf aus dem Projekt Verzeichnis übrigens mit: Python -m unittest

Jeder Punkt im rot markierten Rahmen steht für einen erfolgreichen Test. Das E steht für den fehlerhaften Test.

Und das war auch schon mein einfacher Weg hin zu Performance Tests und der Erzeugung von Log Dateien mit verschiedenen Leistungskenngrößen unter Python. Den Quellcode des Projektes zusammen mit frisch erzeugten Log Dateien gibt es unter dem nachfolgenden Link und ich wünsche Euch nun weiterhin viel Spaß beim automatisierten Testen.

Datei: PY_performance_test (12).zip