Gründe für Logging und wie es damit zu Deadlocks kommen kann
Es gibt viele Gründe eine ausreichende Anzahl von aussagekräftigen Logausgaben in eine Anwendung einzubauen. Einer der häufigsten Gründe ist die Möglichkeit einen Softwarefehler später, also im Nachhinein, durch Analyse der Logdateien finden zu können. In nebenläufigen Anwendungen sind Logausgaben zudem oft die einzige Möglichkeit einen Fehler schon während der Entwicklung zu finden, da z.B. die Verwendung eines Debuggers hier meistens nicht praktikabel ist. Dabei dürfen die Logausgaben die Anwendung nicht negativ beeinflussen. Insbesondere Performance und Stabilität dürfen nicht darunter leiden. Die Logging-Komponente der Anwendung muss also performant und stabil sein. Bei nebenläufigen Anwendungen, die heutzutage eigentlich der Standard sind, müssen sie auch noch threadsicher sein. Der Anwendungscode mit den Logausgaben, also der Teil, der die Logging-Komponente für Logausgaben nutzt, muss in diesem Fall selbst auch threadsicher sein. Und genau das kann zu Deadlocks führen.
In unserem Blogbeitrag „Nachweislich keine Deadlocks“ erklärt Paul Bininda, dass Deadlocks immer dann auftreten können, wenn zwei (oder mehr) Synchronisationsobjekte, kurz „Locks“, in verschiedenen Codepfaden mit unterschiedlicher Reihenfolge angefordert werden. Dies kann der Grund für Deadlocks beim Logging sein, denn einerseits arbeitet die Logging-Komponente mit Locks um threadsicher zu sein, anderseits arbeitet aus demselben Grund auch der Anwendungscode mit Locks.
Ein Beispiel mit Details zum Deadlock durch Logging
Ob es dann zu Deadlocks kommen kann, hängt natürlich von den Implementierungsdetails des beteiligten Codes ab. Deshalb sehen wir uns im Folgenden diese Details an. Um es vorwegzunehmen, das Problem ist real in einer C# Anwendung mit der Apache log4net Bibliothek (Version 2.0.7.0) aufgetreten. Es könnte aber prinzipiell mit jeder Programmiersprache oder Logging-Komponente auftreten. Kritisch wird es, wenn ein Objekt einerseits die Datenkonsistenz durch ein Lock sicherstellt und dabei die Logging-Komponente nutzt, um den aktuellen Zustand konsistent zu loggen, und andererseits gleichzeitig ein drittes Objekt über die Logging-Komponente den Zustand des ersten Objekts logged. Der Deadlock entsteht, wenn dabei in beiden Fällen die Logging-Komponente ihren Zustand per Lock absichert. Das hört sich komplizierter an, als es tatsächlich ist und lässt sich an einem Codebeispiel einfach nachvollziehen. Das Codebeispiel dient nur dazu das Problem zu veranschaulichen und ist deshalb stark vereinfacht. In einer realen Anwendung sind die beteiligten Klassen wahrscheinlich deutlich komplexer. Grundsätzlich müssen wir uns aber immer eine nebenläufige Anwendung mit zwei oder mehr Threads vorstellen.
C# Codebeispiel zum Deadlock
public class SomeClass
{
private static ILogger msLogger = LogManager.GetLogger("SomeClass");
private int mA;
private int mB;
private readonly object mLock = new object();
public override string ToString()
{
lock (mLock)
{
return $"SomeClass: mA: {mA}, mB: {mB}";
}
}
public void SetParameters(int a, int b)
{
lock (mLock)
{
msLogger.Trace("updating mA:{0}, mB:{1} by a:{2}, b:{3}", mA, mB, a, b);
mA = a;
mB = b;
}
}
}
public class OtherClass
{
private static Ilogger msLogger = LogManager.GetLogger("OtherClass");
public void DoWork(SomeClass s)
{
msLogger.Debug("Doing work with s: {0}", s); // log state of s
// ...
}
}
// some client code of SomeClass and OtherClass that uses two or more threads
...
var someClass = new SomeClass();
...
var otherClass = new OtherClass();
...
// the details how the threads access s and o are omitted here
...
// one thread calls
otherClass.DoWork(s);
...
// a 2nd thread concurrently calls
someClass.SetParameters(2, 3);
Abhängig von der Implementierung von ILogger, kann das zum Deadlock führen.
Sehen wir uns dazu den Code im Einzelnen an.
SomeClass
Die Klasse SomeClass hat die zwei privaten Felder mA und mB die zusammen den Zustand des aktuellen Objekts beschreiben. Für SomeClass soll ein semantischer Zusammenhang zwischen mA und mB bestehen. Das bedeutet, dass mA und mB immer zusammen geändert oder gelesen werden müssen, um einen konsistenten Zustand des aktuellen Objekts darzustellen.
Die Klasse SomeClass implementiert ToString() um den Zustand des aktuellen Objekts als String darzustellen. Für das Codebeispiel schützt ToString() selbst den Zustand des Objekts, also die Felder mA und mB, per mLock. In einer realen Anwendung könnte ToString() stattdessen andere (private) Methoden rufen die die Synchronisation durchführen. Das Ergebnis ist für das hier betrachtete Thema dasselbe.
Des Weiteren implementiert SomeClass die Methode SetParameters() die die Felder mA und mB setzt. Dazu muss der Zustand des aktuellen Objekts wieder per mLock konsistent gehalten werden. Diesen Zustand gibt SetParameters() für Analysezwecke per ILogger über die Logging-Komponente aus. Das muss innerhalb des synchronisierten Bereichs passieren, damit ein nebenläufiger ToString() Aufruf einen konsistenten Zustand von mA und mB hat. Das ist ein klassischer Lösungsansatz bei nebenläufigen Anwendungen und insofern nichts Besonderes. Es wäre übrigens auch denkbar, dass es konkurrierende SetParameters() Aufrufe aus mehreren Threads gleichzeitig gibt.
In einer realen Anwendung würde SomeClass noch weitere Methoden enthalten, die für ihre Aufgabe die Felder mA und mB benötigen und ebenfalls per mLock schützen müssen. Für unser Beispiel sind die dargestellten Methoden und Felder ausreichend.
OtherClass
Die Klasse OtherClass dient im Beispiel nur dazu um die ToString() Methode eines Objekts von SomeClass via Logging-Komponente zu rufen. Sofern der Logginglevel Debug gesetzt ist, wird der Aufruf msLogger.Debug(…,s) in DoWork() die ToString() Methode von s aufrufen. Das wird von der Logging-Komponente aufgerufen, wenn sie den String für die Logausgabe formatiert. DoWork() ruft selbst nicht s.ToString() auf.
Nebenläufige Aufrufe und möglicher Deadlock
Zuletzt sehen wir die zwei Aufrufe von otherClass.DoWork(s) und someClass.SetParameters(2,3), die für unser Beispiel von zwei unabhängigen Threads gleichzeitigt stattfinden sollen.
Jetzt kann folgendes passieren:
DoWork ruft msLogger.Debug(). Um ihren Zustand zu schützen, synchronisiert die Logging-Komponente mit einem Lock. Dann ruft die Logging-Komponente s.ToString() für dies Ausgabe als String auf, und s.ToString() synchronisiert via mLock.
Gleichzeitig synchronisiert SetParameters() mit mLock und ruft dann die Trace() Methode der Logging-Komponente. Sofern der Logginglevel Trace gesetzt ist, wird jetzt die Logging-Komponente den String für die Logausgabe formatieren und genauso wie oben beschrieben ihren Zustand per Synchronisation schützen.
Fazit: Der erste Thread synchronisiert in der Reihenfolge Logging-Komponente.Lock → someClass.mLock, und der zweite Thread synchronisiert in der umgekehrten Reihenfolge someClass.mLock → Logging-Komponente.Lock. Wie in „Nachweislich keine Deadlocks“ dargestellt kann das zu Deadlocks führen. Und eins ist sicher, wenn es dieses Risiko gibt, dann wird es auch irgendwann eintreten.
Sequenzdiagramm zum Deadlock
Die umgekehrte Reihenfolge bei der Synchronisation kann man auch an Sequenzdiagrammen gut erkennen.
Die Aufrufe [103] und [105] synchronisieren in umgekehrter Reihenfolge wie [202] und [204].
Die eigentliche Ursache des Deadlocks und Lösungsansätze
Das grundsätzliche Problem ist hier, dass sowohl SomeClass, als auch die Logging-Komponente aus einem synchronisierten Bereich ein anderes Objekt aufrufen, das wiederum synchronisiert.
Es ist immer ungünstig ein anderes Objekt aus einem synchronisierten Bereich heraus aufzurufen, wenn man nicht genau weiß, wie das andere Objekt implementiert ist, denn es könnte immer ein Deadlock Risiko geben. Damit das Risiko eintritt muss es noch die umgekehrte Sequenz (s.o.) geben, aber wenn man die Implementierung des anderen Objekts nicht kennt, ist das oft nicht leicht festzustellen.
Lösungsversuch in SomeClass
SomeClass sollte also in SetParameters() am besten msLogger nicht aus dem synchronisierten Bereich heraus aufrufen. Dazu könnte SetParameters die Felder mA und mB lokal kopieren (synchronisiert) und dann die Werte loggen. Das ist aber umständlich, verschlechtert die Lesbarkeit des Codes deutlich, und hat am Ende auch Performanceauswirkungen. Nicht zuletzt wird die Zustandsänderung dann nicht atomar gelogged, wenn gleichzeitig andere SetParameters() Aufrufe stattfinden.
Public void SetParameters(int a, int b)
{
// not really a good solution
int la, lb;
lock (mLock)
{
la = mA;
lb = mB;
}
msLogger.Trace("updating mA: {0}, mB: {1} by a: {2}, b: {3}", la, lb, a, b);
lock (mLock)
{
mA = a;
mB = b;
}
}
Lösung in der Logging-Komponente
Bei Licht betrachtet ist das eigentliche Problem die Logging-Komponente, denn dass diese aus einem synchronisierten Bereich heraus aufgerufen wird, ist ein Standardfall mit dem die Logging-Komponente umgehen können muss. Das bedeutet die Logging-Komponente darf die ToString() Aufrufe zur Formatierung der Logausgabe nicht aus einem synchronisierten Bereich heraus durchführen. Dazu sollte es auch keine Notwendigkeit geben, denn eine Synchronisation in der Logging-Komponente dient normalerweise dazu gleichzeitige Logaufrufe so zu serialisieren, damit es im Ausgabestream keine Vermischung der Ausgaben gibt. Die eigentliche Formatierung als String kann vorher stattfinden und muss nicht synchronisiert werden.
Wenn man Zugriff auf den Quelltext der Logging-Komponente hat, zum Beispiel wenn sie Teil eines Open Source Projekts ist, dann kann man das Problem wahrscheinlich dort lösen. Ein Open Source Projekt wird dann von diesem Beitrag profitieren.
Fazit
Als das in diesem Blog Artikel beschriebene Problem in einer realen Anwendung aufgetreten ist, konnte das Problem im Quelltext der Anwendung gelöst werden. Dass die Logging-Komponente am Deadlock beteiligt war, war im Debugger leicht zu erkennen. Leider hatten wir zu diesem Zeitpunkt nicht die Ressourcen, um das Problem im Quelltext von log4net weiter einzugrenzen und zu analysieren. Vielleicht weckt dieser Artikel Ihre Neugier und Sie bekommen Lust das Problem dort zu beheben.
In diesem Artikel wurde beschrieben, wie es zu unerwarteten Deadlocks kommen kann, und wo man für eine Lösung ansetzen kann. Es wurde auch gezeigt, dass der Aufruf eines anderen Objekts aus einem synchronisierten Bereich immer ein Deadlock Risiko birgt. Deshalb ist es besser, wenn man Deadlocks dadurch vermeidet, dass man in nebenläufigen Anwendungen weitestgehend ohne Locks auskommt und so das Deadlock-Risiko praktisch eliminiert. Wie das geht, ist dann aber ein anderer Artikel.