Von Performancebedenken und Messorgien

Da ja Datensammelwut heutzutage schon zum guten Ton gehört und Spionage eh grad hip ist, dachte ich mir, ich möchte gerne mal wissen, was für Nasen sich so auf meinem Blog rumtreiben.

Eure hochgeheimen IPs hole ich mir mit Hilfe des request-Moduls von Flask und um das ganze auch über einen längeren Zeitraum nachvollziehbar zu machen, wollte ich meine Loggingfunktionalität um das Schreiben von Logfiles erweitern.

Und jetzt kommt auch schon die alles entscheidende Frage: Wie macht man sowas?

Also jetzt nicht, wie macht man sowas generell, sondern wie macht man das am schicksten? Und am schnellsten?

Die simpelste Methode ist natürlich, bei jedem Seitenaufruf einfach händisch einen Eintrag in die Logdatei zu schreiben. Dies hat aber den Nachteil, dass die Zeiten für den schreibenden Dateizugriff zu der Ladezeit bei jedem Seitenaufruf dazukommen. Sowas ist natürlich nicht unbedingt erstrebenswert. (Ja ich weiß... Ich Heuchler brauch mich garnicht aufregen. Ich lad ja auch Bootstrap und jQuery mit...)

Die Logeinträge zu puffern und alle n Zeiteinheiten mal den Puffer in die Datei zu kippen, klingt da schon wesentlich interessanter, allerdings müsste ich mich da schon wieder mit zu vielen Dingen befassen um das ordentlich selbst zu coden. Multithreading und Threadsafety sind mir für meinen kleinen Blog dann doch etwas zu viel Aufwand.

Dann gibt es da noch das logging-Modul von Python. Das macht die ganze Logginggeschichte so einfach, wie ein print()-Statement und loggt angeblich auch asynchron. Angeblich...

Die Frage nach den Performanceunterschieden ist damit immer noch nicht vom Tisch, daher müssen handfeste empirische Messergebnisse her! Man war ja schließlich mal auf ner Technischen Universität...

Der Versuchsaufbau sieht wie folgt aus: Der Blog wird um umschaltbare Logmethoden erweitert. Die Modi sind normale Ausgabe mit print(), händisches Schreiben in eine Datei und Schreiben in eine Datei via python-logging. Die Initialisierung des logging-Moduls wird bei den anderen beiden Versuchen auskommentiert um das Messergebnis nicht zu verfälschen. Gemessen werden jeweils 2x10 Verbindungen pro Methode. Messtools der Wahl sind curl und time. Dieser Versuch ist zwar bei weitem nicht genau, aber für unsere Zwecke vollkommen ausreichend.

Die Durschnittswerte sind wie folgt:

print(): 0,0541s

custom write: 0,0568s

python-logging: 0.0549

Die gemessenen Unterschiede sind jetzt nicht unbedingt groß genug, um von einer nennenswerten Verzögerung sprechen zu können.

Bei der darauffolgenden Messorgie wurden bei eingeschaltetem Logging mittels python-logging Durchschnittswerte von 0,035s bzw 0.041s über 1000 Pakete gemessen.

aibo hatte hierbei sichtlich Spaß und mein armer Webserver den vermutlich größten Ansturm seines Lebens.

Fazit: Die anfänglichen Bedenken haben sich zumindest für meinen Use-Case als nichtig herausgestellt. Die Verzögerung durch das Schreiben der Logfiles hat hier keinen relevanten Einfluss auf die Responsivität der Seiten. Bei anderen Dimensionierungen der Situation bzw. der Anforderungen kann das allerdings schon wieder ganz anders aussehen.

Vielen Dank nochmal an aibo und Flipez für die Unterstützung/Hilfe bei diesem schwachsinnigen Versuch.

In diesem Sinne,

Happy Measuring

Nyo


2015-07-29 0:40 blog allgemein python flask logging performance curl time bastelei