DB-Lock-Probleme mit Transactional REQUIRES_NEW — Weitere Fallstricke beim Spring/Java-Transaktionshandling

Falls du es noch nicht gelesen hast, empfiehlt es sich, zuerst Teil 1 dieser Beitragsreihe zu lesen.

Ab jetzt gehen wir davon aus, dass wir uns grob daran erinnern, worum es in Teil 1 ging. Zur Auffrischung hier noch einmal einer der wichtigsten Punkte:

Was ist Propagation.REQUIRES_NEW? Man könnte meinen, dass es der Datenbank „magisch“ mitteilt, eine verschachtelte Transaktion zu erstellen. Dieses mentale Modell ist jedoch falsch – viele Datenbanken unterstützen gar keine verschachtelten Transaktionen, daher muss etwas anderes passieren. Was tatsächlich passiert, ist, dass Spring eine neue Verbindung zur Datenbank öffnet.

In Teil 1 haben wir bereits gelernt, dass ein Nebeneffekt davon ist, dass Kontrollflüsse, die zunächst eine Transaktion benötigen und später auch propagation=REQUIRES_NEW verwenden, 2 Datenbankverbindungen benötigen. Und wie wir gesehen haben, kann dies sogar zu Deadlock-Situationen führen, wenn alle Verbindungen aus dem Pool von Threads belegt sind, die ihrerseits alle auf eine weitere Verbindung warten. Das kann passieren, wenn sie alle eine anfängliche Verarbeitung abgeschlossen haben und nun alle an der REQUIRES_NEW-Grenze auf ihre zweite Verbindung warten, die sie „nie” erhalten werden. In der Praxis kann man hoffen, dass der Connection-Pool mit einem Timeout konfiguriert ist, der die Situation irgendwann auflöst.

Wir haben auch erklärt, dass es ein weiteres Problem gibt, bei dem die Ausführung hängen bleibt. Dieses Szenario (im ersten Beitrag als Szenario 2 bezeichnet) erfordert nicht einmal mehrere Threads. Genau das werden wir in diesem Beitrag genauer untersuchen.

Eine kleine Geschichte

Diesmal beginnen wir mit einer kleinen Geschichte, um zu erklären, wie wir in einer realen Situation zu Code gelangen können, der auf dieses Problem stößt.

Tag 1: PO: Wir möchten ein Protokoll/Log aller vom Benutzer ausgelösten Aktionen in unserer Datenbank haben. DEV: Einfach genug – ich erstelle eine neue Tabelle und einen Service, der das vereinfacht. Er nimmt die Benutzer-ID und einen Text, der beschreibt, was passiert ist.

Tag 2: PO: Die Funktion funktioniert gut, aber mir ist aufgefallen, dass wir keinen Protokolleintrag in der DB sehen, wenn der Benutzer versucht, eine Aufgabe auszuführen und dabei ein Server-Fehler auftritt. DEV: Ah ja, das liegt an der Transaktionalität und den Rollbacks. Da unser Protokollcode an der Haupttransaktion teilnimmt, wird er auch zurückgerollt, wenn etwas – eine Ausnahme, die später beim tatsächlichen Ausführen der Aktion auftritt – passiert. Aber das lässt sich leicht beheben: Wir verwenden einfach REQUIRES_NEW als Propagationsstufe, dann ist der Protokollcode vom anderen Rollback nicht betroffen.

Tag 3: PO: Die Änderungen funktionieren gut. Heute haben wir einen neuen Authentifizierungsproxy bekommen. Wenn dieser einen bestimmten HTTP-Header sendet, soll unser System automatisch einen neuen Benutzer anlegen. Das könnte bei jeder Anfrage an unser System passieren. DEV: Kein Problem, wir verwenden einfach einen Filter, der bei jeder Anfrage aufgerufen wird – das wird immer™ funktionieren.

Und da haben wir es: Jetzt haben wir (je nachdem, wie das Transaktionshandling umgesetzt ist) sehr wahrscheinlich eine Situation, in der wir einen Deadlock auf Datenbankebene bekommen werden.

Zum Code!

Das Beispiel-Repository befindet sich hier: https://github.com/NoUsername/transactions-handlinge-issue-2

Hinweis: Der Code spiegelt nicht ganz das wider, was die Geschichte erzählt. Der Einfachheit halber verwenden wir einen einfachen Service und keinen Request-Filter.

Der wichtige Teil, den wir uns ansehen möchten, ist dieser Ausschnitt aus dem UserService:

@Transactional  
fun signup(name: String) {  
    // shortened  
    val user = userRepository.save(  
        User(  
            name = name,  
            signupDateTime = LocalDateTime.now()  
        )  
    )  
   // NOTE: this uses @Transactional(propagation = REQUIRES_NEW)  
   userLogService.logUserAction(user.id!!, "User signed up")  
   // shortened  
}

Die Funktion logUserAction versucht, ein Protokoll der Aktion zu schreiben, die mit diesem Benutzer zusammenhängt. Das wird jedoch nicht funktionieren. Die Ausführung wird einfach bei der Datenbank hängen bleiben (und nach einigen Sekunden fehlschlagen).

Was ist das Problem?

Das Problem besteht darin, dass wir 2 Datenbankverbindungen verwenden und dabei mit zusammenhängenden Daten arbeiten.

Gehen wir das Schritt für Schritt durch: Wir haben unsere „äußere” Transaktion (O), die durch die signup-Methode geöffnet wird, und wir haben unsere „innere” Transaktion (I), die durch logUserAction geöffnet wird.

(O) schreibt einen neuen Benutzer mit ID=1 in die USER-Tabelle – noch kein Commit (I) versucht, einen Eintrag in die USER_LOG-Tabelle zu schreiben, der auf einen USER-Eintrag mit ID=1 verweist.

Da die Datenbank klug genug ist zu erkennen, dass (I) abschließen könnte, wenn nur (O) committen würde, lässt sie (I) auf (O) warten. Was die Datenbank nicht wissen kann, ist, dass unsere Anwendung genau das Gegenteil tut. Unsere Anwendung wartet darauf, dass die Transaktion (I) den Commit abschließt, bevor sie (O) weiterführt – also wartet (O) auf (I).

Das klingt wieder vertraut, denn das ist genau das Deadlock-Muster: Beide Seiten warten auf Ressourcen in genau umgekehrter Reihenfolge.

Einfach gesagt: Stellen wir uns vor, wir öffnen 2 SQL-Clients (ohne Auto-Commit) und geben diesen Befehl im ersten ein:

INSERT INTO USER (id, name) VALUES (1, 'foo');  
-- no commit yet

Und im zweiten Client führen wir aus:

INSERT INTO USER_LOG  
  (id, user_id, message)  
 VALUES  
  (123, 1, 'message');  
COMMIT;

Wir würden im zweiten Client sehen, dass der Commit noch nicht durchgeführt wird, weil wir versuchen, über einen Fremdschlüssel auf nicht committete Daten zu verweisen.

Genau das passiert hinter den Kulissen in unserer Anwendung.

Kein Blogbeitrag von mir wäre vollständig ohne eine schlechte Zeichnung, also bitte sehr:

Typisches zirkuläres Warte-Deadlock-Muster

„Aber ich würde diesen Code nie schreiben”

Natürlich würden wir diesen Code nie schreiben. Aber wie wir in der Geschichte gesehen haben (und wie es im echten Leben meist abläuft), ist der Code in der Produktionsanwendung viel komplexer. Dieser bestimmte Kontrollfluss, der den Fehler auslöst, tritt typischerweise nur unter sehr seltenen Bedingungen auf, die normalerweise nicht durch Tests abgedeckt werden.

Wie in unserer Geschichte: Der „Benutzer erstellen”-Code wäre nicht direkt sichtbar. Stattdessen wäre er in einem Request-Filter oder sogar in einem anderen Modul versteckt.

Realitätscheck

Zugegeben, viele (die meisten/alle – ich kann jedoch nur für MariaDB und MsSql in neueren Versionen sprechen, die das tun) Datenbanksysteme lassen diese Verbindungen nicht wirklich in einen echten Deadlock geraten. Sie haben ein eingebautes Timeout, das dann einen Fehler an die Aufrufer zurückgibt. Aber das bedeutet trotzdem:

• Unsere Anwendung (der Request-Thread und die DB-Verbindungen) wird typischerweise mehrere Sekunden lang blockiert.
• Die Aktion, die wir versucht haben (DB-Schreiboperationen), schlägt fehl.

Wie finden wir dieses Problem in unserem Code?

Wie immer bei Software-Problemen ist ein guter erster Schritt, wenn wir das Problem reproduzieren können 😁

Lösen wir also eine Anfrage aus, die das Problem verursacht (POST an /signup), und erstellen dann einen Thread-Dump, um zu sehen, wo unsere Anwendung tatsächlich hängt. Das zeigt uns in etwa Folgendes:

Vereinfachter & kommentierter Stacktrace

Das zeigt uns, dass bei (1) der Thread gerade darauf wartet, eine Antwort von der Datenbank zu erhalten. Und bei (2) sehen wir, dass er gerade dabei ist, den Benutzerprotokolleintrag in die DB zu schreiben. Wenn wir ein paar Sekunden später nachschauen würden, würde der Stacktrace immer noch gleich aussehen (kein Fortschritt).

Wenn das Anwendungslogging aktiviert ist, bestätigt es diesen Zustand.

Da wir auf die Datenbank selbst warten, ist das der Ort, an den wir uns als Nächstes wenden sollten. Denn wie soll unsere Anwendung wissen, warum die Datenbank nicht antwortet?

Es gibt einige nützliche Befehle, die uns helfen können, die Ursache herauszufinden, wie zum Beispiel:

SHOW FULL PROCESSLIST;  
SHOW ENGINE INNODB STATUS;

Wenn wir jedoch eine bereits aufbereitete Ansicht darüber sehen wollen, welche Abfragen gerade blockiert werden und wodurch, bietet dieser Artikel folgende praktische Abfrage:

SELECT r.trx_id              waiting_trx_id,
       r.trx_mysql_thread_id waiting_thread,
       r.trx_query           waiting_query,
       b.trx_id              blocking_trx_id,
       b.trx_mysql_thread_id blocking_thread,
       b.trx_query           blocking_query
FROM information_schema.innodb_lock_waits w
         INNER JOIN information_schema.innodb_trx b
             ON b.trx_id = w.blocking_trx_id
         INNER JOIN information_schema.innodb_trx r
             ON r.trx_id = w.requesting_trx_id;

In unserem Fall würde das ein Ergebnis ähnlich dem Folgenden zeigen:

Ergebnis der Blockierungsanalyse-Abfrage

Wenn wir ungeduldig sind und die Test-Abfrage mehrmals parallel ausgeführt haben, würden wir sogar mehrere solche Zeilen sehen.

Man beachte, dass sich die Werte waiting_thread und blocking_thread nicht überschneiden. Jedes INSERT in die user_log-Tabelle wird durch das entsprechende INSERT in die user-Tabelle blockiert.

Leider zeigt blocking_query nicht die eigentliche Abfrage, die zuvor in diesem DB-Thread bzw. dieser Transaktion ausgeführt wurde. An sie kämen wir heran, wenn wir das performance_schema aktiviert hätten und damit Zugang zu historischen Abfragedaten hätten. Das geht jedoch über den Rahmen dieses Artikels hinaus.

Wie beheben wir das?

Wie in Teil 1 der Serie empfiehlt es sich auch hier, die Verwendung von REQUIRES_NEW zu hinterfragen.

Was können wir stattdessen tun, wenn wir auf die Transaktionsunabhängigkeit verzichten wollen? Den Datenbankzugriff serialisieren. Damit meinen wir nicht das Speichern von Daten im Binär- oder Textformat, sondern das Eliminieren von Nebenläufigkeit.

„Nebenläufigkeit? Aber wir reden doch nur von einzelnen Threads?” > Eine kurze Internetsuche nach „Concurrency vs. Parallelism” wird das klären. Da REQUIRES_NEW eine neue DB-Verbindung öffnet, nutzen wir diese 2 Ressourcen stets nebenläufig.

Das Serialisieren des Datenbankzugriffs bedeutet also, zunächst eine Transaktion vollständig abzuschließen, bevor die nächste gestartet wird.

Eine einfache Möglichkeit dazu ist beispielsweise der Einsatz von Springs TransactionSynchronizationManager:

// Propagation.MANDATORY makes sure a transaction is ongoing
//   so we have something to "sync to"
@Transactional(propagation = Propagation.MANDATORY)
fun logUserActionFixed(userId: Long, action: String) {
  LOG.info("logUserActionFixed start for userId {} and action {}",
             userId, action)
  TransactionSynchronizationManager
    .registerSynchronization(object : TransactionSynchronization {
      override fun afterCompletion(status: Int) {
        // NOTE: we could even check if the initial transaction
        // failed or succeeded via the status parameter
        LOG.info("starting actual logging to repository")
        userLogRepository.save(
          UserLog(
            userId = userId,
            dateTime = LocalDateTime.now(),
            log = action
          )
        )
        LOG.info("actual logging to repository done")
    }
  })
  LOG.info("logUserActionFixed done (no actual logging yet)")
}

Das führt dazu, dass die eigentliche Ausführung in unseren Logs ungefähr so aussieht:

Eine weitere Möglichkeit wäre ein radikalerer Ansatz: der Einsatz einer Form von Messaging (wie JMS), um die Aktion aufzuschieben. Auch in diesem Fall sollten wir darauf achten, dass die JMS-Nachricht erst am Ende der Transaktion gesendet wird – andernfalls könnten wir immer noch auf Race Conditions stoßen.

Zusammenfassung

Nach dem „Pool Locking” im ersten Artikel haben wir nun auch das zweite potenzielle Deadlock-Szenario „Database Locking” in Aktion gesehen. Beide Probleme sind Folgen dessen, was

@Transactional(propagation = Propagation.REQUIRES_NEW)

unter der Haube macht. Sollten wir Propagation.REQUIRES_NEW niemals verwenden? Sag niemals nie. Es mag Fälle geben, in denen dies die sauberste und schnellste Lösung ist UND wir sicher sein können, dass es kein Problem darstellt (weil wir das auf irgendeine Weise sichergestellt haben). Probleme können später trotzdem auftreten, wenn ein Teil des Codes geändert wird und plötzlich ein Fall entstehen kann, in dem wir auf diese Probleme stoßen.

Was sollte unser Fazit sein? Jedes Mal, wenn wir Propagation.REQUIRES_NEW in einer Codebasis sehen, sollten wir zumindest in einen Alarmzustand wechseln – Gefahrenmodus, Spidey-Sinn auf Hochtouren – und doppelt prüfen, was vor sich geht. Vielleicht sollten wir uns diese Fragen stellen:

• Wurden diese potenziellen Probleme beim Schreiben dieses Codes berücksichtigt?
• Wie ist der DB-Pool konfiguriert?
• Ist die Nebenläufigkeit beim Aufruf dieses Codes begrenzt?
• Auf welche Daten (Tabellen) wird innerhalb dieses Codes zugegriffen und auf welche außerhalb (davor)? Typischerweise interessieren uns hier nur Schreibzugriffe.

Es gibt also eine ganze Liste von Dingen zu prüfen, bevor man vernünftigerweise sagen kann, dass dieses kleine REQUIRES_NEW uns nicht wieder einholen wird.

Und schließlich: Woher kommt dieses Wissen wie von Zauberhand? Nun, natürlich ist in der Praxis etwas schiefgelaufen. Tipp: Der interne, blockierende DB-Zugriff könnte sogar in einer gespeicherten Prozedur versteckt sein – für zusätzliche „Leichtigkeit” beim Debuggen 😋