Performance Logging

Applikations Performance von PHP im Graylog auswerten

Heute widme ich mich einem etwas praktischerem Thema und muss euch gestehen, dass ich mich hier schon wieder mit fremden Federn schmücke. Ich möchte euch hier die Lösung unserer SysOps Engineers von dem Problem unseres Performance Loggings aus dem PHP bis hin zum Graylog erklären.

Einleitend möchte ich euch ein wenig über unseren Tech-Stack erzählen. Früher hätte man das Setup als klassisches LAMP beschrieben, also ein Linux Server mit Apache, den wir übrigens im pre-fork Mode betreiben, der PHP Scripte ausführt, welche die Daten aus einer Mysql Datenbank lesen. Das ganze klingt jetzt einfacher als es in Wirklichkeit ist, da natürlich noch zahlreiche weitere Services notwendig sind, um einen reibungslosen Betrieb von unseren Onlineshops zu gewährleisten. Einer dieser Services ist der Graylog Server, den wir zum Sammeln unserer Logs verwenden und hier eine zentrale Instanz beziehungsweise einen Relay Server Pro Cluster betreiben. Die Logs selbst werden auf jedem Server direkt ins Syslog geschrieben und von dort an den Logging Server weitergeleitet, somit ist dieser Prozess asynchron und blockiert nicht die Ausführung der Anwendung.

Unsere Problemstellung ist nun, dass wir “lahme” Seiten ausfindig machen wollen, langsame Seiten können zweierlei Ursachen haben, entweder braucht die Datenbankabfrage zu lange oder die Rechenzeit einer Komponente auf der Seite ist zu lange. In der Anwendung also zum Zeitpunkt der Ausführung haben wir die Daten schon als Variable im PHP Kontext zur Verfügung, wie bekommen wir diese nun in den Graylog?

Code 1: PHP set Performance Header

Als erster Schritt ist es notwendig, die Daten in den PHP  Header zu schreiben, wie das im Code Block 1 ersichtlich ist. Einziger Nachteil hierbei ist, dass nur die Performance bis zum Senden des Headers gemessen werden kann. Da in unserem Fall aber 99% der Rechenzeit vor dem Senden des Headers passiert, können wir mit dieser Einschränkung gut leben. Die 2 Parameter, die wir dem Header nun mitgeben, sind x-qt, also die Query Time und x-rt für die generelle Rechenzeit (Response Time). Die globale Variable TIMESTART wird beim bootstrapping der Applikation mit der aktuellen Zeit in Millisekunden initialisiert und der statische QueryTime Parameter in unserem Datenobjekt wird bei jedem SELECT oder COUNT auf die Datenbank erhöht. Seid euch hier aber bitte im Klaren, dass diese Daten, sofern sie nicht durch einen weiteren Layer im System, wie zum Beispiel ein HA-Proxy sein kann, herausgefiltert werden, direkt an den Browser weitergeleitet werden und somit niemals sensible Daten enthalten dürfen.

Code 2: Log Format String in der Apache Config

Der zweite Schritt beinhaltet das Anpassen des Apache Logging Formates, wie in Code Block 2 ersichtlich ist. Dabei ist die Lösung so einfach wie genial, denn es kann hier direkt auf den Header zugegriffen werden. Das Schema sieht folgendermaßen aus: %{HEADER_PARAM}o das kleine o macht in diesem Fall den Unterschied aus und führt dazu, dass der Header Parameter ausgelesen wird. Was apache log noch so alles bietet, kann direkt in der Dokumentation von Apache nachgelesen werden [1]. Nun haben wir die Log Message um die Performance Parameter erweitert, also fehlt nur noch das Auslesen im Graylog. Das Geniale in Graylog sind die Rules zum Extrahieren spezieller Felder aus den Log-Messages.

Code 3: Graylog split Apache Header Message

In Code Block 3 ist unser vollständiger Extraktor für die Apache Log Felder ersichtlich. Dieser funktioniert über die in Graylog eingebaute regex Methode und liefert uns ein Array von Werten, welche in weiterer Folge den Custom Feldern zugewiesen werden. Neben den Standard Feldern sind auch die zwei neuen Performance Einträge bereits definiert. Die Regular Expression wurde eigentlich nur um den Ausdruck „(\\d+)\\:(\\d+)\“ erweitert und soll einen Text im Format “121:11” am Ende des Log-Eintrags extrahieren. Müssen die Daten in weiterer Folge analytisch betrachtet werden ist es wichtig, dass eine Konvertierung über die to_long() Methode passiert, ansonsten können keine Rechenaufgaben auf Basis dieser Daten ausgeführt werden.
Abbildung 1: Durchschnittliche Query Zeit

Da es sich ja in dem Beitrag um das Auswerten von Performance Daten im Graylog handelt, möchte ich euch auch hier die Möglichkeiten nicht gänzlich unterschlagen. Auf der einen Seite haben wir, wie in Abbildung 1 ersichtlich ist, den Durchschnitt der Datenbank Ladezeiten pro Cluster visualisiert, um Veränderungen bei der Datenbank rasch zu erkennen. Auf der anderen Seite haben wir uns einen Filter eingerichtet, welcher Seitenaufrufe mit einer Response Time größer 500 Millisekunden liefert. Auf Basis dieser Daten konnten wir weitere Optimierungen durchführen und vereinzelte Ausreißer identifizieren, die ansonsten bei der Masse an Anfragen einfach untergegangen wären.

Stay Nice!

[1] https://httpd.apache.org/docs/2.4/mod/mod_log_config.html