Ich habe neulich eine Serverapplikation geschrieben, die per remote-syslog Applikationslogs von vielen verteilten Clients einsammeln sollte und diese dann als gewöhnliche Logdateien zentralisiert auf dem Server ablegen sollte. Aufgrund der Anzahl an Clients und der Loggingstufe muss die Anwendung dabei mit vielen hundert bis tausend ankommenden Meldungen pro Sekunde umgehen können. Außerdem sollten die Logdateien nach einem freien Format aufgebaut werden können.
Um das Anwedungsökosystem konsistent zu halten und weil meine Kollegen mit der Sprache vertraut sind, habe ich mich entschieden, diese Funktion als Java-Microservice zu implementieren.
Parallel Empfangen & Verarbeiten
Schon zu Beginn der Designphase war mir klar, dass aufgrund der hohen Spitzenlast die Verarbeitung der empfangenen Meldungen parallelisiert und getrennt von dem Empfangen der UDP-Telegramme passieren musste. Folglich werden die UDP-Telegramme nun von einem Thread empfangen und an einen Threadpool von Verarbeitern weitergereicht. Um das Allozieren und Garbage-Collecten der großen byte-Array-Puffer der Java UDP-Pakete zu optimieren, werden die einmal instanziierten Pakete im Round-Robin-Verfahren wiederverwendet, sobald der empfangene Inhalt verarbeitet wurde. Der Paket-Pool erzeugt und vernichtet dabei automatisch Pakete nach Bedarf und aktueller Last.
Parsen von Meldungen
Eigentlich ist Linux-rsyslog weitgehend standardisiert: Pro Logmeldung wird ein UDP-Telegramm mit festem Format versendet. Inhalt sind: Meldungstext, Anwendungsname und PID, Priorität als Produkt aus Severity und Facility, Zeitstempel und ein bisschen Meta-Info wie IP des Client-Hosts, Empfangszeit etc. Leider wich die Implementierung in der Distribution, die meine Clients verwendet haben, etwas davon ab. Busybox muss offenbar eigene Wege gehen. Also gibt es nun mehrere Parser, die ein gemeinsames Interface implementieren, das von den Verarbeiter-Threads aufgerufen wird, um die UDP-Payloads erstmal in meine eigene Syslog-Meldung-Klasse zu parsen.
Formatieren von Meldungen
Um die Anwendungslogs mit denen von anderen Applikationen bei unterschiedlichen Kunden konsistent zu halten, sollten die geparsten Meldungen nun nach einem frei konfigurierbaren Format in Strings umgewandelt werden. Diese werden dann jeweils zeilenweise an die Logdateien angehangen, deren Dateiname mittels der gleichen Formatierung gebildet werden sollte. Nun hätte ich eine Standard-Templating-Engine dafür nehmen können, aber für einzeilige Texte, bei denen nur ein paar vordefinierte Platzhalter zu ersetzen waren, fand ich das etwas zu schwergewichtig. Immerhin war ich mit ein paar wenigen Zeilen String.replace() auch schon fertig. (Warum das nicht funktioniert hat später) Nun noch ein intelligentes Datei-Appending und Flushing der I/O-Streams dahinter und fertig war die Business-Logik.
Konfiguration
Die Anwendung soll als einfacher Hintergrundtask permanent laufen. Keine Nutzerinteraktion erforderlich und außerdem sind die User Sysadmins, DevOps oder sogar manchmal Entwickler. Also habe ich die Anwendung in ein executable jar verpackt und lasse sie durch Kommandozeilenparameter konfigurieren. Da es hier allerdings recht viele Optionen gibt, habe ich auch das Verpacken der Konfig in einer Datei erlaubt. Dabei habe ich mich für eine simple Properties-Datei entscheiden, da die Konfiguration nur Key-Value-Paare umfasst und Java dafür eine fertige Unterstützung mitbringt. Eine kleine Auswahl der Konfigurationsoptionen: Zeilenende-Zeichen der Logmeldungen, Format-String der Meldungen und der Zieldateinamen, Zeitzone und Locale, Bind-IP-Adresse und -Port, Größe von diversen Puffern und Caches, beliebiges Regex/Replace auf den fertigen Meldungstext um noch etwas nachzuverarbeiten. Das Nachverarbeiten habe ich eingeführt, weil ich die Quell-IP-Adressen der Clients durch meine eigenen Namen für die Clients ersetzen wollte (die Hostnamensauflösung hat nämlich keine akzeptablen Namen hervorgebracht).
Erster Integrationstest
Nachdem die Anwendung die Unit-Tests bestanden hatte ging es für mich an die Integrationstests. Bei einem ersten Volldurchlauf der Funktion mit nur einem Client auf meinem Schreibtisch lief alles wunderbar: für jeden Aufruf von "logger Hello World" auf dem Client erschien eine neue Zeile in der richtigen Logdatei auf dem Server. Auch wenn ich mit "watch logger Hello World" daherging, pflegte die Logdatei in der gleichen Frequenz zu wachsen, wie ich watch laufen ließ.
Erste Probleme in Production
Nachdem die Anwendung auch die statische Code-Analyse, Linting, Testing und Building durchlaufen hatte, war es Zeit, Version 1.0 in der Realität zu testen. Leider musste ich feststellen, dass sobald mehrere Clients über meinen Server geloggt haben und diese auch noch in mehreren Subnetzen verteilt waren, meine Logdateien nicht mehr so flott gepflegt wurden. Dafür aber stieg der RAM-Verbrauch des Servers unaufhörlich. Nach kurzer Analyse mit visualvm zeigte sich der Grund: der RAM stieg, weil das Verarbeiten der Meldungen zu lange dauerte. In der Zeit für das Parsen einer Meldung kamen mehrere neue an. Dadurch staute sich die Verarbeitungs-Warteschlange. Der Grund dafür war auch mittels Thread-Sampling schnell gefunden: Die Hostnamensauflösung der Clients dauerte zu lange. Bei dem Parsen jeder Meldung habe ich nämlich ein InetAddress.getHostname() gemacht. Leider machte diese Methode in meinem Fall jedes Mal einen Lookup gegen das Netzwerk (der aufgrund der Firewall in einen Timeout lief). Da ich auf das automatische Quasi-Mini-Reverse-DNS nicht verzichten wollte (immerhin beschleunigt ein lesbarer Name die Inbetriebnahme manchmal deutlich), habe ich selbst einen Cache für die Hostnamen gebaut. Version 1.1 lief dann sehr zufriedenstellend.
String.replace()-Performance
Leider lief das nicht allzu lange. Am nächsten Morgen war die Anwendung nämlich an einer OutOfMemoryException verendet. Offenbar war mein Profiling nicht ausdauernd genug. Bei einer Lastspitze in der Nacht hat meine Anwendung nämlich nicht mehr mithalten können. Ein erneutes (ausdauerndes) Profiling ergab, dass im RAM-Verbrauch deutliche Ausschläge vorlagen, die nicht auf seltenes Garbage-Collection zurückzuführen waren. Ein Memory-Sampling lies mich außerdem stutzig werden, dass über 90% des Heap an int[] ging. Ein Backtracking der Referenzen hat als Ursache ergeben: die Java Regex-Engine hat ständig neuen Patterns kompiliert. Das verwunderte mich stark, denn die Regexe, die ich in meiner Anwendung erlaubt habe, wurden alle zum Start der Anwendung vorkompiliert, sodass hier keine solchen Aufrufe mehr stattfinden hätten dürfen. Was ich nicht gewusst habe: String.replace() erzeugt intern einen Regex um die Ersetzung durchzuführen (zumindest in meiner JVM). Da ich ja, wie oben beschrieben, einfaches String.replace auf alle Platzhalter in meinem Ausgabe-Format-String gemacht habe, hat das natürlich für jede der hunderten Logmeldungen pro Sekunde mehrfach ein Pattern.compile() ausgelöst. Ich gebe zu, dass ich nicht damit gerechnet hatte, dass eine so einfache Funktion einen so schwergewichtigen Aufruf auslöst.
High-Performance-String-Templating
Um diesen Aufruf also nicht mehr tun zu müssen, habe ich das Problem zerlegt: Bei Anwendungsstart wird der Formatstring mittels Regex analysiert und die Platzhalter und die statischen Texte dazwischen werden extrahiert. Diese werden dann durch Platzhalter-Enums ersetzt und in meinem neuen CompiledFormatString CFS gespeichert. (Also genauergenommen sind da noch Zeit-Formatter, Locale-Formatter und einiges mehr drin, aber das abstrahiere ich hier der Einfachheit halber mal.) Wenn nun eine Meldung kommt mache ich einen StringBuilder auf und iteriere über die einzelnen Parts meines CFS. Statische Texte werden dabei direkt an den Builder angehangen, während bei Platzhaltern direkt der entsprechende Wert angehangen wird. Der Trick, der das Ganze dann schnell gemacht hat war, dass mir aufgefallen war, dass in dem CFS zwangsweise Platzhalter und Texte sich streng abwechseln mussten. Beispiel FS="Hallo %target!" ergibt CFS=[Text "Hallo ", Platzhalter target, Text "!", Platzhalter null]. Damit konnte ich diese auf zwei Arrays Platzhalter[] und Text[] aufteilen und mit einem gemeinsamen Index über beide iterieren. Der StringBuilder hat dann seine übliche Magie getan und die korrekte Logmeldung zusammengebaut, ohne dabei auf Regex zurückgreifen zu müssen. Version 1.2 läuft nun in Production stabil (auch über längere Zeit) und verbraucht für mehrere tausend Meldungen pro Sekunde nicht mal 70MB RAM und CPU nur im nicht-messbar-kleinen Prozentbereich. Zum Vergleich: im dem Server steckt nur ein 8-Kerner mit 3GHz.
Resumée
Um Logs von vielen verteilten Systemen einzusammeln, wenn man ein Logmanagement (wie bspw. Graylog) in der Architektur nicht einführen kann, bietet sich das Linux-Standardwerkzeug rsyslogd an. Die Apps auf den Clients müssen diese Schnittstelle zwar direkt zum Loggen ansprechen, aber dafür kümmert sich der Systemdienst dann um das puffern und senden der Meldungen. Leider bietet das System keinen Schutz gegen Übertragungsfehler oder Netzwerkausfälle, aber dafür ist die Performance (Meldungen/Zeit) extrem gut. Mein Syslog-Server verbraucht dafür kaum Ressourcen und kann sehr individuell auf den Kontext eingestellt werden. Diesen Lösungsweg empfehle ich für Anwendungsfälle, bei denen sehr viele Thin-Clients (Größenordnung 100+) existieren, die selbst nicht die Kapazität haben (oder die man nicht alle einzeln administrieren kann), um ein Logmanagementsystem zu beherbergen. Deutlich stabileres Logging erreicht man hingegen mit einem Logmanagementsystem, das Netzwerkausfälle abfangen kann.