Best Practices: Logging in .NET – Wie Sie das Beste aus Ihren Logs herausholen

Logdateien zu schreiben erscheint auf den ersten Blick trivial. Auf den zweiten Blick auch noch. Und irgendwann sitzt man dann doch da, und debugged seinen eigenen Logging-Code, während man in den dazugehörenden Logdateien die erwarteten und erhofften Informationen zum Fehler einfach nicht findet. Damit Ihnen das nicht passiert, habe ich hier ein paar Ideen, Stolperfallen, Anregungen und Best Practices zum Thema Logging in .NET zusammengeschrieben.

In diesem Artikel:

sg
Sebastian Gingter ist Consultant und „Erklärbär“ bei Thinktecture. Seine Spezialgebiete sind Backend-Systeme mit .NET Core und IdentityServer.

Einleitung

Logging in .NET hat sich seit .NET Core und in .NET 5 bzw. 6 ein gutes Stück von dem weiterentwickelt, wie wir es eventuell noch aus dem .NET Framework in den Versionen 1-4 kannten.

Unsere Logger-Klasse kommt nun üblicherweise aus der Dependency-Injection, und vor allem müssen wir nicht die Abhängigkeit auf ein bestimmtes Logging-Library durch unser gesamtes Projekt ziehen, denn Microsoft bietet eine eigene Abstraktion für einen ILogger an.

Das Minimal-Beispiel, mit den neuen Minmal APIs in .NET 6, sieht damit so aus:

				
					// Program.cs
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

var services = new ServiceCollection()
    .AddLogging(o => o
        .SetMinimumLevel(LogLevel.Information)
        .AddDebug()
        .AddConsole()
    )
    .AddSingleton<MyClass>()
    .BuildServiceProvider();

var c = services.GetRequiredService<MyClass>();
c.DoSomething();

// Additional classes
public class MyClass
{
    private readonly ILogger _logger;

    public MyClass(ILogger<MyClass> logger)
    {
        _logger = logger;
    }

    public void DoSomething()
    {
        _logger.LogInformation("Doing something at {Time}", DateTimeOffset.UtcNow);
    }
}
				
			

Alle Logging-Bibliotheken können sich inzwischen hinter dieser einheitlichen ILogger Fassade heimisch machen, und damit ganz einfach einem zentralen Punkt über das DI-System ausgetauscht werden.

Verschiedene Bibliotheken

Wo wir gerade von Logging-Bibliotheken sprechen: Wurde früher noch oft auf NLog oder Log4NET gesetzt, so hat sich seit der Einführung von .NET Core und damit auch in .NET 5 und dem kürzlich veröffentlichten .NET 6 Serilog als der de-facto-Standard für eine Logging-Bibliothek etabliert.

Nichts desto trotz gibt es eine Vielzahl von alternativen Logging-Bibliotheken. Manche davon sehr spezifisch für bestimmte zentrale Log-Sammel-Systeme, andere mit flexibel austauschbaren Zielen, die so ziemlich jedes Logging-System bedienen können. Diese möchte ich hier auch nicht unerwähnt lassen. Die Auflistung ist alphabetisch sortiert und nicht wertend, und ganz sicher auch nicht vollständig.

Hinweis: Diese alternativen Log-Bibliotheken nutzen zum Teil andere LogLevel-Namen als Microsoft.Extensions.Logging. Zum Beispiel heißt der Microsoft-Level Trace bei Serilog Verbose und der Microsoft-Level Critical heißt bei Serilog Fatal. Im Code werden grundsätzlich die Microsoft-Level mit dem ILogger verwendet, in der Konfiguration des konkreten Log-Systems müssen aber in aller Regel die Bibliotheksspezifischen Namen verwendet werden.

Dies fällt insbesondere dann auf, wenn man Serilog in seiner AppSettings.json auf "minimumLevel": "Trace" konfiguriert – und dann nichts im Log findet, weil Serilog mit Trace nichts anfangen kann und daher gar nichts loggt.

Stolperfallen

Zuerst möchte ich auf ein paar Stolperfallen eingehen, denen ich im täglichen Einsatz schon begegnet bin.

1. Strings statt Parameter / String interpolation

Logeinträge sind heutzutage strukturiert. Das heißt, sie können neben einem reinen Log-Text auch Kontext-Informationen beinhalten, sowie einsetzbare Platzhalter. Je nach dem eingesetzten Logging-System, welches die Einträge dann empfängt, sind diese Platzhalter dann auch nach ihren spezifischen Werten durchsuchbar. Das geht allerdings nicht, wenn man nur normale Strings in das Log schreibt:

				
					Log.Write("Doing something at " + DateTimeOffset.UtcNow.ToString() + " and ...");
				
			

Oder genauso unschön, nur etwas moderner, mit String Interpolation:

				
					Log.Write($"Doing something at {DateTimeOffset.UtcNow} and ...");
				
			

Davon abgesehen, das wir hier die strukturierten Kontext-Informationen verlieren, wird bei dieser Methode jedes mal ein neues String-Objekt allokiert, was Speicher verbraucht und die Garbage-Collection unnötig beschäftigt.

Besser ist hier das schon eingangs gezeigte Beispiel mit dem Platzhalter und dem Wert als Parameter:

				
					_logger.LogInformation("Doing something at {Time} and ...", DateTimeOffset.UtcNow);
				
			

Hier kann nun in allen Logs durchsucht und auch gefiltert werden. Zum Beispiel interessieren mich alle Log-Einträge, bei denen der Platzhalter Time einen Wert zwischen 12:00 und 12:05 hat, und kann die Menge der Einträge entsprechend eingrenzen. Es bietet sich hier dementsprechend auch an, für einen bestimmten Wert auch immer denselben Platzhalter zu verwenden, damit der Wert bei einer Suche dann auch in anderen Logeinträgen gefunden wird.

Aber aufgepasst: Die Log-Methoden nehmen als ersten Parameter den string messageTemplate an, also unseren String mit Platzhaltern, und danach ein params object[] mit den Werten. Das hat den Nachteil, das bei jedem Aufruf der Methode alle Werte-Typen (value types) in ein Objekt geboxed werden, und damit für jeden Wert jedes mal ein neues Objekt allokieren das den Wert kapselt. Das ist insbesondere ungeschickt, wenn der Log-Aufruf aufgrund seines Levels hinterher gar nicht zu einem Logeintrag führt.

2. Loggen, wenn nicht notwendig

Wenn unser Logger so konfiguriert ist, das er nur Warnungen, Fehler und Kritische Meldungen schreibt, dann ist es unnötig, ihn für Informationen, Debug-Infos oder gar Trace-Einträge aufzurufen.

Wir können daher den Log-Aufruf verhindern, wenn das gewünschte Log-Level nicht benötigt wird:

				
					if (_logger.IsEnabled(LogLevel.Information))
{
    _logger.LogInformation("Doing something at {Time} and ...", DateTimeOffset.UtcNow);
}
				
			

Dieser Check spart (auf meiner Maschine) bei jedem einzelnen Aufruf ca. 35 Nanosekunden ein. Das erscheint auf den ersten Blick nicht viel, aber wenn man bedenkt das ein Webservice immer 24/7 läuft, darin hunderte bis tausende Klassen (nicht nur die eigenen, sondern auch die aus verwendeten Nuget-Paketen) sind, mit jeweils zig Methoden die alle irgendwie Debug- und Infoaufrufe haben, und der Dienst dann irgendwann unter Last steht, dann können das sehr schnell schon etliche Milliarden Log-Aufrufe werden, die jeweils 35 Nanosekunden einsparen. Das summiert sich dann über die Tage und Wochen hinweg schon zu einer stattlichen CPU-Zeit. Und wenn man diese z.B. in der Cloud noch bezahlen muss, kann man dadurch in der Tat einiges an Geld sparen.

Aber ja, dieser Check ist unbequem und wird daher in aller Regel nicht gemacht. Ich zeige später noch einen Weg, der diesen Check automatisch mit bringt, so das wir uns diesen if-Block sogar sparen können.

3. Falsche Parameteranzahl

Nehmen wir an, wir setzen einen weiteren Platzhalter unseren Logeintrag ein, vergessen aber, den Wert auch zu befüllen:

				
					public void DoSomethingWrong()
{
    _logger.LogInformation("Doing something at {Time} and {Date}", DateTimeOffset.UtcNow);
}
				
			

Das lässt sich (leider) wunderbar kompilieren, führt dann aber zur Laufzeit zu einem sehr unschönen Fehler:

				
					Unhandled exception.
System.AggregateException: An error occurred while writing to logger(s). (Index (zero based) must be greater than or equal to zero and less than the size of the argument list.)
---> System.FormatException: Index (zero based) must be greater than or equal to zero and less than the size of the argument list.
				
			

Manche Source Code Analyzer und/oder IDE-Tools (ReSharper, Rider) können diese Fehler aufspüren und uns davor warnen, aber solange wir die „normalen“ Logging-Methoden verwenden haben wir darüber hinaus keine Hilfestellungen.

Kurzum: Wer nicht möchte, dass sich seine Anwendung irgendwann zur Laufzeit wegen einer solchen Exception komplett auf die Nase legt, vielleicht sogar erst nach Jahren, wenn irgendein obskurer Code-Pfad durch eine seltsame Konstellation von Datenbankeinträgen doch irgendwann das erste mal durchlaufen wird (und damit dann der kopierte und nicht korrekt mit allen Parametern angepasste Logaufruf das erste mal aufgerufen wurde) der sollte auf so etwas peinlichst genau achten. Oder weiter lesen, denn auch hierfür kommt noch eine Lösung.

Achja, und fragt bitte nicht, warum mir jetzt ganz spontan ein so seltsames Beispiel eingefallen ist, was ja eh nie und „erst recht nicht wenn die Anwendung schon 4 Jahre lang läuft und täglich benutzt wird“ auftritt 🙈.

4. Logs nicht fertig schreiben

Wenn irgend möglich sollte man sicherstellen, dass es alle Einträge auch in das Logging-System schaffen, das heißt konkret bei zentralisierten Systemen noch übers Netzwerk weggeschickt oder zumindest in eine lokale Datei geschrieben wird. Denn es hilft das allerbeste Logging nichts, wenn der Service noch vor dem Wegschreiben des File-Streams stirbt und man den Fehler mit der passenden Exception, die einem zur Lösung helfen könnte, nie zu Gesicht bekommt.

Hier wieder am Beispiel von Serilog:

				
					public async Task<int> Main(string[] args)
{
    try
    {
        // ... Setup des Hosts etc....
        await app.RunAsync();
        return 0;
    }
    catch (Exception ex)
    {
        Log.Logger.LogFatal(ex, "An error caused the servic to crash");
        return 1;
    }
    finally
    {
        // Sicherstellen, das das Log auch wirklich geschrieben wird!
        Log.Logger.CloseAndFlush();
    }
}
				
			

Das hilft natürlich nicht, wenn der Prozess einfach terminiert und nicht mehr in den catch / finally-Handler läuft, aber wenn das passiert haben wir in der Regel ein anderes externes Problem, das sich ggf. mit dem EventLog / Systemlog herausfinden lässt.

5. Auslassen der EventId

Die Logging-Methoden aus Microsoft.Extensions.Logging nehmen alle einen EventId-Parameter an. Dies ist einfach eine positive Zahl (ushort) zwischen 1 und 65536, die den Logeintrag eindeutig identifiziert. Leider ermöglichen es die meisten der Logging-Methoden seit .NET Core 2.0 aber, diese EventId auszulassen. In kaum einen Beispiel findet sich die Verwendung.

Eine (mehr oder weniger) eindeutige EventId zu vergeben hat allerdings Vorteile. Sie erlaubt es zum einen, Logeinträge nach ihrer Art zu gruppieren. Beispielsweise können alle Logeinträge die damit zu tun haben, eine bestimmte Entity zu speichern eine Id bekommen, und alle Einträge die damit zu tun haben eine bestimmte Entity zu löschen eine andere Id bekommen. Somit wird es einfacher, die entsprechenden Einträge aus dem Log herauszufiltern. Alternativ kann man auch Nummernkreise hernehmen und wirklich jedem Event eine eineindeutige Id in einem bestimmten Bereich zuweisen. Der Bereich deutet dann auf die Quelle der Logmeldung oder deren Bedeutung hin.

Ein weiterer riesiger Vorteil ist, dass man eine einmal zugeordnete EventId nicht zwangsläufig ändern muss, wenn man bei einem Update der Anwendung den Text des Logeintrags verändert. Grundsätzlich ist es einfacher, in Logging-Systemen nach EventId = 4711 zu suchen als nach Text = "Did something with dataset {XZ} on {whatever}". Somit lassen sich auch historische Einträge in einem System vergleichen und auffinden, wenn bei früheren Updates irgendwann einmal der Text der Nachricht geändert wurde.

Denn wer hat nicht schonmal ein Log nach einer Nachricht durchsucht und sich gewundert, dass bestimmte Einträge fehlten – und dann festgestellt das in den Logeinträgen z.B. Orignal statt Original stand – und man sie deshalb nicht gefunden hat?

6. Impliziter Parameter Kategorie

Zu guter letzt wird auch die Kategorie oftmals nicht effizient genutzt. Das in .NET Core eingeführte Logging-System stellt eine Logger Factory zur Verfügung, damit wir in unsere Klassen einen ILogger<TCategoryName> hineingeben lassen können. Als Typ wird in aller Regel die Klasse angegeben, in die der Logger verwendet wird. Der Kategoriename ist dann der vollständige Klassenname inklusive Namespace. Wir erhalten also einen Logger, dessen Parameter category in jeder Lognachricht den Namen der Klasse trägt, die den Logeintrag schreibt.

Wozu ist das nun gut?

Zum Einen können wir in der Konfiguration des Logging-Systems den kleinsten zu schreibenden LogLevel (MinimumLevel) pro Kategorie überschreiben. Beziehungsweise konkreter: pro Anfang eines Kategorienamens.

Die Logger-Konfiguration der Projektvorlage für ASP.NET Core Anwendungen generiert zum Beispiel folgende Konfiguration:

				
					{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}
				
			

Hier wird als Standard der Level Information geloggt, aber die Konfiguration für alle Einträge, deren Katgeorie mit Microsoft beginnt ist spezifischer, und diese Einträge werden erst ab Warning geloggt. Dann greift die Ausnahme für die Einträge der Kategorie Microsoft.Hosting.Lifetime, die wieder auf Information zurückgestellt werden.

Hiermit kann sehr fein granular eingestellt werden, von welchen Bereichen des eigenen Codes man welche Logeinträge sehen möchte. Insbesondere beim Debuggen kann man hiermit deutlich effizienter steuern was man braucht, ohne zum einen wichtige Einträge zu verpassen, aber vor allem auch ohne von massenhaft von für das aktuelle Problem uninteressanten Logeinträgen überflutet zu werden.

Best Practices

Nachdem wir uns nun die häufigsten Probleme mit Logging angeschaut haben, wollen wir nun prüfen, was – und wie – wir das besser machen können.

Option 1: Performance verbessern durch vorformatierte Log-Einträge

Wenn wir strukturiertes Logging verwenden, so muss das Log-System die vorgegebene Log-Nachricht erst parsen, die Platzhalter herausfinden, und dann die Werte zu den Platzhaltern im strukturierten Log ablegen. Haben wir dazu noch eine Ausgabe in einem unstrukturierten Format wie z.B. der normale Text auf der Konsole, so muss er auch noch den Platzhalter ersetzen und den resultierenden String bauen.

Das Logging-System ist in der Lage, das Ergebnis des geparsten Logeintrages zu cachen. Nur: wenn wir immer alles cachen, ist irgendwann der Speicher voll. Das Logging-System von .NET begrenzt den Cache daher auf 1024 Einträge. Wenn wir mehr Lognachrichten haben und diese oft durcheinander verwendet werden, so dass alte Einträge im Cache öfter verworfen werden, so kann auch dies zu einem Performance-Problem werden.

Mit dem Hilfsmittel LoggerMessage.Define können wir eine Log-Nachricht vorformatieren. Wir erhalten eine Action zurück, die wir mit einem Logger, unseren Parameter und einer optionalen Exception aufrufen können, und diese beinhaltet unser vorformatiertes Message-Template:

				
					private static readonly Action<ILogger, DateTimeOffset, Exception?> _logSomething =
    LoggerMessage.Define<DateTimeOffset>(
        logLevel: LogLevel.Information,
        eventId: 1,
        formatString: "Doing something at {Time}");

public void DoSomething()
{
    _logSomething(_logger, DateTimeOffset.UtcNow, null);
}
				
			

Die Vorteile sind:

  • Die Log-Nachricht wird nur einmalig geparsed, wenn wir LoggerMessage.Define aufrufen. Danach haben wir die vorformatierte Nachricht und können diese beliebig oft aufrufen, ohne das ein verwerfen eines Caches ein erneutes Parsen erzwingen würde.
  • Die Action hat einen automatischen Check auf _logger.IsEnabled() eingebaut. So wird der eigentliche Logaufruf nicht passieren, wenn der verwendete LogLevel nicht konfiguriert ist.
  • Die Action lässt sich nur mit der richtigen Anzahl an typisierten Parametern aufrufen. Das hilft uns allerdings nicht, wenn wir uns bei den Platzhaltern im String vertun.

Die Nachteile liegen leider auch klar auf der Hand: Es ist viel Code, er ist aufwändig zu schreiben und leider auch sehr unhandlich zu verwenden. Auch wenn das nahezu alle unsere Probleme löst, so ist diese Lösung so unschön, das man sie lieber nicht einsetzen möchte. Und das ehrlich gesagt zurecht.

Option 2: Source Generators nutzen

Glücklicherweise bringt uns .NET 6 die neue Möglichkeit, diese aufwändigen Optimierungen rund ums Logging zu automatisieren, und uns auf das wichtige zu Konzentrieren: Das eigentliche Loggen. Das Schreiben des ganzen Codes für die Action und das Vorformatieren etc. übernimmt dann der Source Generator für uns.

Wer Source Generatoren noch nicht kennt: Sehr vereinfacht und sehr kurz gesagt ist das eine Art Plugin für den Compiler. Hiermit kann eigener oder auch über NuGet-Pakete importierter Code im Compiler, direkt während des Kompilierens ausgeführt werden, der z.B. neuen Code generiert. Mein Kollege Pawel hat hier einen (englischen) Artikel geschrieben, in dem Source Generatoren im Detail erklärt werden.

Aber keine Angst: Wir müssen hier nichts selber schreiben, denn glücklicherweise bringt .NET 6 einen fertigen Source Generator für das Logging mit, und zwar in Form des [LoggerMessage()]-Attributs. Der Source-Generator implementiert für uns sowohl das Vorformatieren der Nachricht, als auch den Aufruf mit der Prüfung, ob der Loglevel aktiv ist oder nicht.

Unsere Log-Methode sieht mit dem Source Generator dann folgendermaßen aus:

				
					[LoggerMessage(0, LogLevel.Information, "Doing something at {Time}")]
partial void LogSomething(DateTimeOffset time);

public void DoSomething()
{
    LogSomething(DateTimeOffset.UtcNow);
}
				
			

Um den Source Generator nutzen können müssen wir jedoch eine Sache beachten: Der Generator muss den Code der Methode, den er generieren soll, ja auch irgendwo hin schreiben. Das macht er während des Kompilierens in einer temporären Datei, die den Implementations-Code unserer als partial markierten Signatur der Log-Methode ergänzt. Und das funktioniert (leider) nur, wenn auch unsere Klasse als partial markiert ist.

Und ja, anstelle eines einfachen

				
					public void DoSomething()
{
    _logger.LogInformation("Doing something at {Time}", DateTimeOffset.UtcNow);
}
				
			

haben wir noch zwei Zeilen mehr zu schreiben, nämlich die partielle Methodensignatur mit unseren Parametern und das LoggerMessage Attribut mit den weiteren Angaben zur Log-Nachricht.

Allerdings löst uns das wirklich alle Probleme, die wir oben angesprochen hatten. Da der [LoggerMessage] Source Generator auch noch einen Analyzer beherbergt, sagt uns nun sogar der Compiler, wenn ein Platzhalter in unserer Log-Nachricht nicht durch einen Parameter der Log-Methode befüllt wird.

Zusatzinfos zu Source Generatoren

Bei der Verwendung von LoggerMessage.Define mussten wir den ILogger bei jedem Aufruf übergeben. Der Source Generator findet ihn automatisch, indem er nach einem Feld oder Property vom Typ ILogger auf unserer Klasse sucht und diesen in der generierten Methode verwendet. Wenn wir keinen haben (z.B. auf statischen Klassen), können wir den Logger auch in der Definition unserer Log-Methode an-, und dann beim Aufruf übergeben:

				
					[LoggerMessage(0, LogLevel.Information, "Doing something at {Time}")]
static partial void LogSomething(ILogger logger, DateTimeOffset time);

public static void DoSomething(ILogger logger)
{
    LogInformation(logger, "Doing something at {Time}", DateTimeOffset.UtcNow);
}
				
			

Log-Level und Kontext-Informationen richtig nutzen

Dies ist kein technisches Thema, aber wichtig.

Wir loggen, damit uns das Log zur Entwicklungszeit und im Betrieb einen Mehrwert liefert. Der Mehrwert den wir uns erwarten ist, Fehlerfälle und deren Entstehungsgeschichte besser zu verstehen und nachvollziehen zu können. Eben damit wir Fehler schneller finden und besser beheben können.

Dazu ist es wichtig, die Log-Level auch sinnvoll und vor allem konsistent einzusetzen. Hierzu gibt es leider keine allgemeingültigen Best Practices, aber mit den folgenden Daumenregeln habe ich in den letzten Jahren sehr gute Erfahrungen gemacht:

  1. Trace (bei Serilog: Verbose)
    Traces sind furchtbar. Das Log wird sehr, sehr viel größer wenn man sie anmacht und man ertrinkt förmlich in Informationen. Wenn man sie wirklich braucht, hat man ein gewaltiges Problem (z.B. Nebenläufigkeit in Multithreading). Normalerweise schreibe ich keine Trace-Log-Meldungen. Nur, wenn an einer Stelle wirklich eine extrem hart zu knackende Nuss vorliegt, markiere ich mit Trace-Logs z.B. jeden Einstieg in betroffene Methoden (mit allen Parametern und deren Werten) und den Ausstieg (wieder mit allen Eingaben und dem Rückgabewert). Als zusätzliche Kontext-Information logge ich dann auch gerne die Thread-Id mit (z.B. mit dem Thread-Enricher von Serilog), um den Ablauf besser herausfinden zu können. Die allermeisten Trace-Statements landen bei mir zusätzlich hinter einer #if DEBUG Compiler-Direktive, damit sie nicht im Release-Build enthalten sind.
    Grundsätzlich gilt nämlich vor allem: Die Parameter-Werte gehören nicht in ein Produktionslog.
  2. Debug
    Heißt so, wie es einzusetzen ist: Während des Debuggens. Wann rufe ich etwas auf? Mit welchen Werten? Was bekam ich zurück?
    Achtung: Dabei aber bitte auch wieder unbedingt darauf achten, das keine Daten im Log landen die aus Datenschutz-Sicht problematisch sein könnten. Diese eher mit Trace und nur im Debug-Build loggen.
  3. Info
    Auf diesem Level logge ich persönlich gerne alles, was an den Systemgrenzen passiert, und wenn Aktionen gestartet werden. Alles, was ein Benutzer auslöst, erhält eine Logzeile (wer hat was wann angestossen?), genauso bekommen regelmäßig laufende Prozesse einen Startmarker.
  4. Warning
    Alles was später zu einem Problem werden könnte, sollte als Warning geloggt werden: Der Datenbankaufruf, der länger als erwartet gedauert hat: Wenn sich das hochschaukelt kann ein System zusammenbrechen weil es nur noch auf die Datenbank wartet. Ein In-Memory-Cache, der voll läuft und alte Einträge verwirft: Wenn das häufig und/oder zu Stoßzeiten passiert, kann die Performance durch zu viele Cache-Misses massiv einbrechen.
  5. Error
    Sagt das aus, was es ist: Ein Fehler. Ein Datenbank-Zugriff, der nicht funktioniert hat. Ein Netzwerk-Aufruf einer anderen API, die einen Fehler zurückmeldet. Wenn jemand etwas löschen möchte, das schon nicht mehr da ist oder etwas anlegen möchte, das es schon gibt. Oder wenn ein User eine API aufruft, auf die er nicht berechtigt ist und die dafür vorgesehene Client-Anwendung das eigentlich verhindern sollte. Das deutet z.B. entweder auf einen Bug in der Client-Anwendung hin oder auf jemanden, der versucht an unserer API zu manipulieren.
  6. Critical (bei Serilog: Fatal)
    Aus meiner Sicht gibt es nur einen Platz für eine Fatal-Log-Meldung: In der Program.cs im globalen Exception-Handler (bzw. im globalen Exception-Handler, der jeden selber erstellten Thread überwacht). Critical sollte ausschließlich einen Programmabsturz begleiten. Wenn ein Service den Port auf dem er arbeiten sollte nicht bekommt und daher nicht starten kann. Wenn ein Dienst beim Start seine Datenbank nicht oder in einem ungültigen Zustand vorfindet (z.B. nicht passendes Datenbankschema) und damit den Start abbricht bzw. abbrechen muss.

Wie eingangs erwähnt: Das ist keine Industriestandard-Vorgehensweise. Das ist meine persönliche Meinung, die ich mir über viele Jahre Erfahrung an verschiedensten Softwaresystemen gebildet habe. Andere Anforderungen machen sicher andere Einordnungen notwendig. Falls man sich bisher allerdings noch wenig Gedanken zu dem Thema gemacht hat (Verständlich: Logging ist ja auch eher ein notwendiges Übel als unser erhofftes und erwünschtes Lebensziel als Entwickler), dann ist das oben geschriebene vermutlich eine solide Grundlage mit der man nicht furchtbar viel falsch machen kann.

Wann und was

Und wann sollte nun was geloggt werden?

Zur Entwicklungs- und Debugzeit? Für mich ganz klar: So viel wie möglich. Außer, man wird von einer nicht-filterbaren Flut an unnützen Informationen überfahren (z.B. in Text-basierten Logdateien). Dann gilt: So wenig wie gerade notwendig ist damit die Menge noch irgendwie übersichtlich bleibt.

Ich persönlich habe zur Entwicklungszeit gerne die kostenlose Individual / Entwickler-Version von Seq (gesprochen Seek) in einem eigenen Docker-Container pro Kunden laufen, und logge dort alles (also wirklich alles: Trace) hinein. Wenn ich dann in die Logs gucken muss, kann ich dort problemlos und schnell nach den wichtigen Infos filtern, Zeitlich eingrenzen, suchen etc. – und zwar über alle Dienste / Anwendungen hinweg.

Zur Laufzeit? Das kommt ganz auf die Umstände und die Menge an Logs an. Habe ich ein zentralisiertes Logging-System mit viel Speicher, so kann ich problemlos zur Laufzeit immer Debug-Logs schreiben lassen, und diese dann z.B. nach 24h (oder am Ende des nächsten Werktags) verwerfen, und nur Info und wichtigere Meldungen länger beibehalten. Hier gilt es eine sinnvolle Balance zwischen der Vorhaltezeit, dem benötigtem Platz und ggf. gewünschten Statistiken (z.B. Warnings / Zeit) zu finden. Wobei das Ausleiten von Statistiken aus den Logs dann schon in das Thema Monitoring übergeht.

Wenn ich (noch) kein zentrales Logging-System habe und Dateien schreibe, aber z.B. Serilog mit einem dynamischen LogLevelSwitch einsetze, dann reicht es aus, wenn ein Programm erstmal nur Warnings logged. Wenn diese dann auftreten, kann der Loglevel zur Laufzeit automatisch für eine bestimmte Zeit auf Info oder gar Debug hoch gesetzt werden, und wenn die problematische Situation dann danach wieder auftritt, habe ich mehr Informationen zum Nachvollziehen.

Performance

Nun habe ich schon mehrfach behauptet, das es besser bzw. schneller wäre, auch wirklich mit Source Generatoren zu loggen. Aber behaupten kann ich natürlich viel wenn der Tag lang ist. Viel spannender ist doch die Frage, ob ich das auch beweisen kann.

Also habe ich einen kleinen Benchmark gebaut und die verschiedenen Methoden gegeneinander antreten lassen. Jede dieser Methoden erzeugt die gleiche Log-Nachricht mit den gleichen Parametern, einmal auf LogLevel.Trace und einmal auf LogLevel.Critical. Der Logger schreibt auf ein aktives Dummy-Target das nur einen Counter erhöht, und ist auf LogLevel.Information konfiguriert. Das heißt die Trace-Aufrufe werden nicht geschrieben und die Critical-Aufrufe werden alle ausgeführt.

Die Methoden sind:

  • InterpolatedLog[Trace/Critical]
    Verwenden von string interpolation.
  • CommonLog[Trace/Critical]
    Der gewöhnliche _logger.LogXXX("Message", params); Aufruf.
  • ActionLog[Trace/Critical]
    Loggen mit einer durch LoggerMessage.Define() vorformatierten Action.
  • SourceGenLog[Trace/Critical]
    Aufrufen der Log-Methode, die durch den Source Generator implementiert wird.

Dazu gibt es jede Methode (ausgenommen des Source Generators) noch einmal in einer Checked...-Variante, die den if-Block mit der Logger.IsEnabled() Prüfung für den jeweiligen Level beinhaltet.

Die Ergebnisse

Benchmark.NET liefert uns nach dem Lauf der verschiedenen Methoden folgendes Ergebnis:

Method
Mean
Mean
Error
StdDev
Gen 0
Allocated
InterpolatedLogCritical
586.689 ns
11.4315 ns
16.7562 ns
0.0887
1,120 B
CheckedInterpolatedLogTrace
5.234 ns
0.1181 ns
0.1213 ns
CheckedInterpolatedLogCritical
610.778 ns
12.0039 ns
11.2284 ns
0.0887
1,120 B
CommonLoggingTrace
79.181 ns
1.3277 ns
1.2419 ns
0.0082
104 B
CommonLoggingCritical
86.153 ns
1.7055 ns
1.8249 ns
0.0082
104 B
CheckedCommonLoggingTrace
4.804 ns
0.1037 ns
0.1153 ns
CheckedCommonLoggingCritical
92.950 ns
1.8736 ns
2.0825 ns
0.0082
104 B
ActionLoggingTrace
6.018 ns
0.1430 ns
0.1757 ns
ActionLoggingCritical
39.357 ns
0.6841 ns
0.6399 ns
CheckedActionLoggingTrace
4.485 ns
0.1106 ns
0.1656 ns
CheckedActionLoggingCritical
45.367 ns
0.8984 ns
1.1033 ns
SourceGenLogTrace
5.319 ns
0.1289 ns
0.1676 ns
SourceGenLogCritical
38.375 ns
0.7734 ns
0.8906 ns

Auswertung

Vorneweg: Die schnellste Variante ist natürlich die, in der wir nichts loggen und das mit dem Logger.IsEnabled()-Check vorher abfangen. Wie man sieht ist diese if-Abfrage auf meinem Rechner immer um die 5 Nanosekunden „teuer“.

Ansonsten sieht man deutlich: Die interpolierten Strings sind nicht nur die bei weitem langsamste Variante, sondern bringen auch ordentlich Allokationen mit. Hier gilt also: Finger weg!

Das übliche, „normale“ Logging bringt auch Allokationen mit sich. Es ist zwar etwas schneller, aber mit knapp unter 100ns nach wie vor relativ langsam.

Die Varianten mit der vorformatierten Action und dem Source Generator sind von der Geschwindigkeit her gleichauf bei ca. 40ns, und benötigen keinerlei zusätzliche Allokationen, was unsere Garbage Collection auf Dauer stark entlastet. Wie ich schon erwähnt hatte, hat die Action-Methode auch bereits die IsEnabled-Prüfung eingebaut, so dass die Checked-Variante die 5ns der zusätzlichen if-Abfrage nochmal oben drauf packt, falls wir loggen.

Fazit

Das „normale“ Logging mit den direkten logger.LogXXX()-Aufrufen ist zwar zweifellos die verbreitetste, aber nicht unbedingt die optimale Variante. Was die Performance angeht gibt es keinen Unterschied zwischen vorformatierten Actions und dem Source Generator-Ansatz. Das sollte einleuchtend sein, denn der Source Generator macht nichts anderes, als den gleichen Code zu generieren, den wir bei den Actions direkt geschrieben haben. Allerdings müssen wir diesen komplizierten Action-Code nicht selber schreiben, was ein großer Vorteil ist. Natürlich nur unter der Prämisse, das wir damit leben können, unsere Klassen in denen wir loggen dafür als partial zu markieren.

Auch wenn es für jeden Log-Eintrag zwei Zeilen mehr sind: Die Verwendung des [LoggerMessage] Source Generators ist ungefähr doppelt so schnell bzw. halb so teuer wie der gewohnte direkte Logger-Aufruf, spart bei jedem Aufruf ein paar Bytes an Memory ein, bringt zusätzlich den Logger.IsEnabled()-Check mit sich und sorgt mit dem eingebauten Analyzer schon zur Kompilierungszeit dafür, dass die Parameter genau zu den Platzhaltern im Template der Nachrichten passen. Es ist daher die ideale Lösung für Anwendungen, in denen viel und dauernd geloggt wird.

Achja, und bitte nicht Vergessen: Die EventId ist gut, frisst kein Brot und hilft im Problemfall wirklich bei der Suche nach bestimmten Einträgen im Log-System, ohne den genauen Text für eine Volltextsuche kennen zu müssen. 😉

Kostenloser
Newsletter

Aktuelle Artikel, Screencasts, Webinare und Interviews unserer Experten für Sie

Verpassen Sie keine Inhalte zu Angular, .NET Core, Blazor, Azure und Kubernetes und melden Sie sich zu unserem kostenlosen monatlichen Dev-Newsletter an.

Newsletter Anmeldung
Diese Artikel könnten Sie interessieren
Database Access with Sessions
.NET
KP-round

Data Access in .NET Native AOT with Sessions

.NET 8 brings Native AOT to ASP.NET Core, but many frameworks and libraries rely on unbound reflection internally and thus cannot support this scenario yet. This is true for ORMs, too: EF Core and Dapper will only bring full support for Native AOT in later releases. In this post, we will implement a database access layer with Sessions using the Humble Object pattern to get a similar developer experience. We will use Npgsql as a plain ADO.NET provider targeting PostgreSQL.
15.11.2023
Old computer with native code
.NET
KP-round

Native AOT with ASP.NET Core – Overview

Originally introduced in .NET 7, Native AOT can be used with ASP.NET Core in the upcoming .NET 8 release. In this post, we look at the benefits and drawbacks from a general perspective and perform measurements to quantify the improvements on different platforms.
02.11.2023
.NET
KP-round

Optimize ASP.NET Core memory with DATAS

.NET 8 introduces a new Garbage Collector feature called DATAS for Server GC mode - let's make some benchmarks and check how it fits into the big picture.
09.10.2023
.NET CORE
pg

Incremental Roslyn Source Generators: High-Level API – ForAttributeWithMetadataName – Part 8

With the version 4.3.1 of Microsoft.CodeAnalysis.* Roslyn provides a new high-level API - the method "ForAttributeWithMetadataName". Although it is just 1 method, still, it addresses one of the biggest performance issue with Source Generators.
16.05.2023
AI
favicon

Integrating AI Power into Your .NET Applications with the Semantic Kernel Toolkit – an Early View

With the rise of powerful AI models and services, questions come up on how to integrate those into our applications and make reasonable use of them. While other languages like Python already have popular and feature-rich libraries like LangChain, we are missing these in .NET and C#. But there is a new kid on the block that might change this situation. Welcome Semantic Kernel by Microsoft!
03.05.2023
.NET
sg

.NET 7 Performance: Regular Expressions – Part 2

There is this popular quote by Jamie Zawinski: Some people, when confronted with a problem, think "I know, I'll use regular expressions." Now they have two problems."

In this second article of our short performance series, we want to look at the latter one of those problems.
25.04.2023