Wie mich die Suche nach Transaktionszeitüberschreitungen Geld gekostet hat

Bei unserem Projekt liegt der Schwerpunkt darauf, die Anwendung stabil und kontrollierbar zu machen. Anstatt also coole neue Funktionen zu entwickeln, verbringen wir unsere Zeit damit, sicherzustellen, dass die Anwendung in der Produktionsumgebung stabil läuft. Nach den ersten paar Problemen tauchte das so genannte 'Transaktions-Timeout'-Problem auf. Ab und zu warf die Anwendung eine Exception wegen eines Transaktions-Timeouts aus. Das war sehr seltsam, da der Timeout auf 30 Sekunden eingestellt war und die komplette Verarbeitung der gesamten Anwendung in weniger als 2 Sekunden (verteilt auf mehr als 1 Transaktion) durchgeführt wurde.

Als erstes haben wir versucht, eine produktionsähnliche Umgebung einzurichten, um das Problem zu reproduzieren. Wir haben ein paar Stunden damit verbracht, unsere Entwicklungsumgebung so produktionsnah wie möglich zu gestalten. Mit vielen Stichproben an den Außengrenzen des Systems und einem Live-Feed von Daten, die zu verarbeiten waren, wurde unser Test am Freitagnachmittag gestartet. Als wir am Montagmorgen im Büro ankamen, waren wir sehr überrascht, dass es 0 Zeitüberschreitungen gab. Nun zu Plan B. Die ursprüngliche Anwendung besteht aus 4 Teilen. Der Plan war also, unsere Umgebung so zu verändern, dass nur ein kleiner Teil der ursprünglichen Anwendung ausgeführt wird. Wir haben auch die Transaktionszeitüberschreitung auf 1 Sekunde geändert, um die Wahrscheinlichkeit von Zeitüberschreitungen zu erhöhen. Auf diese Weise können wir vorhersagen, in welchem Teil der Anwendung die Suche fortgesetzt werden muss.

1 != 1

Der Titel dieses Absatzes mag etwas seltsam klingen, aber halten Sie sich fest, eine Erklärung folgt bald. Nach unserem Testlauf gab es einige Transaktions-Timeouts. Wir stellten auch fest, dass dieser Teil der Anwendung die normale Verarbeitung in etwa 13 Millisekunden durchführte. Schnell genug, um die Zeitüberschreitung zu umgehen, sollte man meinen. Aber dann entdeckten wir, dass der Grund für diese Zeitüberschreitung nicht derselbe war wie die Zeitüberschreitung, die wir in unserer Live-Umgebung erlebten. Der Grund für die Zeitüberschreitung in diesem Setup lag in einer etwas anderen Bedeutung der Zeitüberschreitung, als wir erwartet hatten. Wir hatten erwartet, dass die Zeitüberschreitung überwacht wird, wenn die Transaktion beginnt und nach 1 Sekunde eine Ausnahme auslöst. Aber..... Werfen wir einen Blick auf den Code in der Klasse org.hibernate.jdbc.AbstractBatcher sind zwei Methoden beteiligt [sourcecode language="java"] public void setTransactionTimeout(int seconds) { isTransactionTimeoutSet = true; transactionTimeout = System.currentTimeMillis() / 1000 + seconds; } [/sourcecode] und [sourcecode language="java"] private void setTimeout(PreparedStatement result) throws SQLException { if ( isTransactionTimeoutSet ) { int timeout = (int) ( transactionTimeout - ( System.currentTimeMillis() / 1000 ) ); if (timeout<=0) { throw new TransactionException("transaction timeout expired"); } else { result.setQueryTimeout(timeout); [/sourcecode] } } } Wenn Sie den Transaktions-Timeout auf 1 Sekunde setzen, löst Hibernate die Timeout-Exception genau zum Sekundenwechsel aus. Wenn Sie Ihre Transaktion um 13:45:21.990 starten, beträgt der Timeout genau 10 Millisekunden! Kein Wunder, dass diese Zeitüberschreitungen auftraten. Wenn Sie also wollen, dass die untere Grenze der Transaktionszeitüberschreitung bei 1 Sekunde liegt, müssen Sie die Hibernate-Transaktionszeitüberschreitung auf 2 Sekunden einstellen! Und ja, nach der Einstellung auf 2 Sekunden gibt es keine Zeitüberschreitungen mehr!

Dumme Idee!

Während der Tests bin ich über einige Threaddumps gestolpert (die aus einem anderen Grund erstellt wurden). Was mir dabei auffiel, waren die vielen Threads, die auf eine Sperre für apache log4j-bezogene Klassen warteten. Wir führen in unserer Anwendung umfangreiche Protokollierungen durch, so dass mir das nicht völlig fremd war. Aber irgendwo in meinen grauen Zellen wurde ein Zusammenhang zwischen diesem Phänomen und dem Transaktions-Timeout hergestellt, den wir untersuchten. Also teilte ich meine Gedanken dem Team mit. Ich sagte ihnen, dass ich den Verdacht hatte, dass die Protokollierung in der Anwendung so lange dauern könnte, dass die Transaktion nicht innerhalb der 30 Sekunden abgeschlossen wurde. Und dann wurde ich ausgelacht! Wie um alles in der Welt könnte etwas so Schnelles wie das Schreiben einer Zeile in eine Protokolldatei so lange dauern. Diese dumme Idee löste weitere dumme Ideen aus (die allerdings nicht so dumm waren wie meine), und so war die Teamwette geboren!

Team-Wette

Die Teamwette ist eine Wette, die innerhalb des Teams entstanden ist. Alle Ideen zu einem Problem, das innerhalb des Sprints untersucht wird, werden auf der Pinnwand festgehalten. Jeder kann seine eigene Idee einbringen oder die Idee eines anderen Teammitglieds unterstützen. Das einzig Seltsame ist, dass der Gewinner (und seine Unterstützer) für den Kuchen bezahlen müssen. Ewiger Ruhm ist natürlich der Preis, den Sie gewinnen. Ein paar Tage lang stand meine dumme Idee auf dem Whiteboard mit der alleinigen Unterstützung des Testers im Team. Weil es die dümmste Idee auf dem Board war, wurden die anderen Ideen zuerst untersucht. Aber nach ein paar Tagen war nur noch diese dumme Idee übrig. Mit den Tagen, die vergingen, wurde mein Gefühl für diese dumme Idee immer stärker. In meiner Freizeit ging ich den Code durch und machte das seltsame Verhalten an der Log-Rotate-Funktion fest. Jedes Mal, wenn eine neue Logdatei erstellt wurde, musste die älteste gelöscht werden, um das Verzeichnis sauber zu halten. Aber ein paar Tests mit einer großen Anzahl von Dateien zeigten, dass dies auf meinem lokalen System in weniger als 30 Millisekunden erledigt war.

Ich bin ein Sturkopf

Dickköpfig wie ich bin, war ich immer noch überzeugt, dass dies das Problem war. Da zu diesem Zeitpunkt jeder aus dem Team bereit war, mir das Gegenteil zu beweisen, beschlossen wir, das Logfile-Verzeichnis in der Produktionsumgebung zu leeren (denn das war der einzige Ort, an dem die Timeouts auftraten). Vor dieser Aktion hatten wir etwa 10 bis 15 Timeouts pro Stunde. Und ja, Sie haben richtig geraten, nach dem Leeren des Protokollverzeichnisses gab es mehrere Wochen lang keine Zeitüberschreitungen mehr. Das hörte sich langsam wie eine Ente an, aber um sicher zu sein, dass es eine Ente war, mussten wir einen umgekehrten Test durchführen. Aber hey! Rühren Sie ein gut funktionierendes System nicht an (denn das ist es, was wir durch das Entfernen der großen Menge an Dateien geschaffen haben), also durften wir in unserer Live-Umgebung nicht mehr experimentieren. Und da bei den Transaktionszeitüberschreitungen alles reibungslos funktionierte, konzentrierten wir uns auf das nächste wichtige Problem. Um bei dem Problem der Transaktionszeitüberschreitung ein wenig voranzukommen, haben wir die Tester, die die Akzeptanztests durchführen, gebeten, diesen Rückwärtstest für uns durchzuführen. Und nach einem Tag bekamen wir die endgültige Antwort: Transaktions-Timeouts wurden durch die große Menge an Protokolldateien im Verzeichnis in Verbindung mit einer Protokollrotation und Bereinigung der ältesten Datei verursacht. Das Ergebnis dieser Suche war, dass ich und mein Unterstützer zur nächstgelegenen Bäckerei gingen, um Kuchen für die ganze Abteilung zu kaufen. Und deshalb hatte mich die Suche Geld gekostet und mir im Gegenzug ewigen Ruhm beschert. Und das bringt mich auch dazu, mich zu fragen, wie frei Open-Source-Software eigentlich ist.....