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);
}
}
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.
- elmah.io
- Graylog / GELF
- JSNLog
- Kisslog
- log4net (Apache)
- Microsoft.Extensions.Logging
- NLog
- NReco
- Sentry
- Serilog
- Stackdriver
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.Defineaufrufen. 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:
- 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 DEBUGCompiler-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. - 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. - 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. - 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. - 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. - 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 durchLoggerMessage.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. 😉
