In diesem Artikel habe ich Benchmarks für die privatesten Anrufe von Loggern gesetzt. Ich habe alle Experimente mit log4net und NLog unter Intel Windows 10 x64 mit M.2 SSD durchgeführt.
Rohergebnisse können auf GitHub angezeigt werden. Der Code befindet sich im selben Repository (zum Ausführen benötigen Sie .Net 4.7.2 + Microsoft Visual Studio 2017+).
Was, wie und warum - unter dem Schnitt.
Um lange nicht zu lesen, die Ergebnistabelle:
NoOpLogging
Lassen Sie uns zunächst abschätzen, wie viel Zeit wir damit verbringen, eine Protokollierungsmethode aufzurufen, was letztendlich zu nichts führt. In den meisten Fällen (meiner Erfahrung nach) ist das ausführliche Debug auf Kampfservern deaktiviert, aber niemand entfernt Anrufe.
Zunächst das Ergebnis:
Und der Code:
void Log4NetNoParams() => _log4Net.Debug("test"); void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument); void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument); void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void Log4NetMultipleValuesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); void NLogNetNoParams() => _nlog.Debug("test"); void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument); void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument); void NLogNetMultipleReferencesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void NLogNetMultipleValuesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument);
Lassen Sie uns zunächst feststellen, warum solche Tests ausgewählt wurden:
- Die Experimente wurden an den beliebtesten Bibliotheken durchgeführt.
NLog und log4net haben unterschiedliche Funktionssignaturen für eine kleine Anzahl von Argumenten:
void DebugFormat(string format, object arg0)
void Debug(string message, string argument) void Debug<TArgument>(string message, TArgument argument)
- Theorie: Bei der Übertragung eines signifikanten Typs auf log4net sollte ein Boxen auftreten, das einfach Prozessorzeit verbringt und zu nichts führt. Im Fall von NLog gibt es kein solches Verhalten, daher sollte letzteres schneller funktionieren.
- Die Signaturen für eine große Anzahl von Argumenten in Bibliotheken sind ungefähr gleich, daher würde ich gerne wissen:
- Wie viel effizienter ist es, Methoden mit einer kleinen Anzahl von Parametern aufzurufen.
- Gibt es einen Unterschied in der Geschwindigkeit beim Aufrufen der Methode "Is ... Enabled" zwischen den beiden Bibliotheken?
Und nun die Analyse der Ergebnisse:
- Aufgrund der Verwendung generischer Argumente in NLog funktioniert dies schneller, wenn keine direkte Protokollierung erforderlich ist. Das heißt, wenn in Ihrem Debug-Programm die Ebene nur auf dem Testsystem aktiviert ist, kann das Ändern der Bibliothek die Software beschleunigen (und das Leben der Benutzer verbessern).
- Wenn Sie die Protokollierung deaktiviert haben und eine Methode mit einer großen Anzahl von Argumenten aufrufen möchten, ist es effizienter, sie in zwei Teile aufzuteilen. Aus diesem Grund funktionieren die oben genannten Methodenaufrufe zehnmal schneller.
- Wenn Sie eine Funktion schreiben, die ein beliebiges Objekt aufnehmen kann, ist es häufig am effektivsten, verwirrt zu sein und eine generische Funktion zu erstellen. Aufgrund dieser einfachen Optimierung arbeitet der Code schneller (dies zeigt sich deutlich im Zeitunterschied zwischen den Aufrufen von
Log4NetSingleReferenceParam und Log4NetSingleValueParam ).
Filelogging
Die meisten Programme (nach meinen Beobachtungen) protokollieren die Ergebnisse immer noch in einer Datei, daher wählen wir zum Vergleich diese Operation. Der Einfachheit halber nehmen wir nur die Konfiguration der Logger, wenn eine Datei ohne Pufferung, ohne zusätzliche Sperren usw. in die Datei geschrieben wird.
Ergebnisse:
Verwendeter Code:
var roller = new RollingFileAppender(); roller.ImmediateFlush = true; roller.RollingStyle = RollingFileAppender.RollingMode.Once; roller.MaxFileSize = 128 * 1000 * 1000;
new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = false, KeepFileOpen = false };
Wie Sie sehen können, ist die Konfiguration der Logger mehr oder weniger ähnlich und entspricht den Ergebnissen:
- NLog ist etwas schneller als log4net, irgendwo um die 15%.
- Tests zufolge stellte sich heraus, dass es effizienter ist, weniger Parameter zu protokollieren. Man sollte jedoch nicht vergessen, dass mit einer größeren Anzahl von Parametern auch die resultierende Zeichenfolge erweitert wurde. Daher vergleicht die Tabelle NLog nur korrekt mit log4net.
NLog - verschiedene Arten von Schlössern
Quellcode:
new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = XXXXX, KeepFileOpen = YYYYY };
Wenn wir alle möglichen Kombinationen anstelle von XXXXX und JJJJJ einsetzen, erhalten wir den Test aus der Tabelle.
Die Ergebnisse sind ziemlich vorhersehbar:
- Wenn Sie ConcurrentWrites aktivieren, nimmt das System ständig Mutex und gibt es, was nicht kostenlos ist. Wie wir jedoch sehen, entspricht das Schreiben einer Zeile in eine Datei ungefähr einer Systemsperre.
- Wie wir sehen, wirkt sich das Schließen und Öffnen einer Datei noch stärker auf die Systemleistung aus. In den Beispielen mit
KeepFileOpen=true wir für jeden Protokollierungsvorgang eine Datei (zusammen mit Handle) erstellt, auf die Festplatte mit dem Namen Flush geschrieben, Handle zurückgegeben und auch viele Motorhaubenoperationen durchgeführt. Infolgedessen sinkt die Geschwindigkeit hunderte Male.
Asynchrone Protokollierung und verschiedene Sperrmethoden
Die NLog-Bibliothek kann auch alle E / A-Vorgänge für einen anderen Thread ausführen und den aktuellen Thread sofort freigeben. Und er tut es kompetent, indem er die Reihenfolge der Ereignisse beibehält, alle Daten in Blöcken löscht und in jedem Block eine Ganzzahl eine Ereignisnummer ist (so dass keine zugeschnittenen Zeilen erhalten werden) und so weiter.
Die Ergebnisse verschiedener nicht blockierender Methoden:
Der Vergleich von blockierenden und asynchronen Ansätzen wird weiter gehen, aber hier - nur der letzte.
AsyncTargetWrapper Code:
new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync) { OverflowAction = AsyncTargetWrapperOverflowAction.Block, QueueLimit = 10000 }
Wie Sie sehen können, sind die Wrapper-Einstellungen so, dass ein direkter Speicherauszug in die Datei nicht lange dauert. Somit wird ein großer Puffer akkumuliert, was bedeutet, dass alle ressourcenintensiven Operationen wie "offene Datei" einmal für den gesamten Block ausgeführt werden. Ein solcher Algorithmus erfordert jedoch zusätzlichen Speicher (und viel).
Schlussfolgerungen:
- Wenn eine asynchrone Ausgabe verwendet wird, spielt es keine Rolle, welche Ausgabeeinstellungen für die Datei verwendet werden. Sie können die Datei jedes Mal öffnen und schließen. Mit einem großen Puffer ist sie fast nicht wahrnehmbar.
- Alle Messungen gelten nur für den Fall, dass Daten mit ungefähr der gleichen Geschwindigkeit wie das Füllen von Puffern auf die Festplatte gespült werden (ich habe dies aufgrund des schnellen Dateisystems + natürlicher Pausen zwischen den Messungen getan).
Synchrone und asynchrone Protokollierung
Schlussfolgerungen:
- Trotz der schnellen Festplatte (in meinem Fall - M.2 SSD) beschleunigt das Schreiben in eine Datei in einem anderen Stream die Arbeit um ein Vielfaches. Wenn Ihre Anwendung auf Festplatten schreibt und sogar auf einer virtuellen Maschine ausgeführt wird, ist die Verstärkung noch größer.
- Trotz des gleichmäßig schnellen Betriebs des asynchronen Codes führt das Fehlen der Protokollierung zu einem noch größeren Gewinn (wenn auch je nach Bibliothek geringfügig unterschiedlich).
Logger erstellen
Ergebnisse:
Was wurde getestet:
[Benchmark] public object CreateLog4NetFromString() { return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000)); } [Benchmark] public object CreateNLogFromString() { return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000)); } [Benchmark] public object CreateLog4NetLogger() { return new [] { LogManager.GetLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogTypeOfLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogDynamicLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(), // x16 times }; }
Wichtige Bemerkung: Leider war es für mich schwierig, einen reproduzierbaren Benchmark zu erstellen, der nicht zu Speichermangel führte, aber unterschiedliche Logger erzeugte (d. H. Für verschiedene Typen, für verschiedene Zeilen usw.).
Nachdem ich jedoch die Arbeit von Bibliotheken untersucht hatte, stellte ich fest, dass fast die schwierigsten Operationen ausgeführt werden, um einen Protokollierungsschlüssel zu erstellen (d. H. Einen Namen zu bestimmen, generische Argumente zu löschen usw.).
Um den Benchmark für die Erstellung eines Loggers für log4net zu stabilisieren, war es außerdem erforderlich, nicht eine Operation auszuführen, sondern 16 (d. H. Ein Array von 16 identischen Objekten wird zurückgegeben). Wenn Sie nichts zurückgeben, hat .Net die Ausführung für mich optimiert (anscheinend nur das Ergebnis nicht zurückgegeben), was zu falschen Ergebnissen führte.
Und Schlussfolgerungen:
- Logger werden am schnellsten aus Zeichenfolgen erstellt (NLog ist wieder schneller, der Unterschied zwischen den Bibliotheken ist jedoch gering, wenn man bedenkt, dass Logger nicht nur so erstellt werden, sondern für die spätere Arbeit mit ihnen).
- log4net ist beim Initialisieren eines Projekts schneller als NLog. Möglicherweise liegt dies an der zusätzlichen Zwischenspeicherung auf der NLog-Seite, die dazu beiträgt, direkte Aufrufe von
Debug , Info usw. zu beschleunigen. Tatsächlich kennt jeder ILogger die Antwort auf sich selbst: ob die folgenden Methoden aufgerufen werden sollen oder nicht (und dies erfordert zumindest eine Bindung an die allgemeine Konfiguration). Aufgrund dieses Arbeitsschemas wurde Out Of Memory von mir bei den meisten Tests verwendet (wenn ich andere Zeilen usw. verwende). LogManager.GetCurrentClassLogger() ist noch langsamer als LogManager.GetLogget(typeof(XXX)) . Dies ist logisch, selbst NLog-Entwickler empfehlen nicht, die erste Methode in einer Schleife aufzurufen.- Und am wichtigsten: Die Geschwindigkeit all dieser Methoden wirkt sich häufig nur auf den Kaltstart der Anwendung aus, wenn Felder des Formulars
private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . Das heißt, es wirkt sich nicht direkt auf die Leistung des Systems aus.
Fazit
Was ist der beste Weg, um mit Protokollen umzugehen:
- Wenn es möglich ist, sich überhaupt nicht anzumelden, ist dies die schnellste (was bisher offensichtlich ist).
- Wenn das Projekt viele Logger-Aufrufe hat, die keine Daten in eine Datei (an die Konsole usw.) ausgeben, ist NLog schneller. Außerdem werden weniger Objekte auf dem Heap zugewiesen.
- Wenn Sie immer noch in eine Datei schreiben müssen, arbeitet NLog am schnellsten asynchron. Ja, es verbraucht mehr Speicher (im Vergleich zu NLog im synchronen Modus, da log4net nach meinen vorherigen Messungen nicht einmal versucht, Arrays und
Stream wiederzuverwenden). Das Programm kann jedoch schneller ausgeführt werden. - Das Erstellen eines Loggers ist kein freier Vorgang, daher ist es oft besser, ihn mit einem statischen Feld zu erstellen. Dies gilt nicht für das Erstellen aus einer Zeichenfolge,
LogManager.GetLogger("123") . Solche Aufrufe arbeiten schneller, was bedeutet, dass ein Logger für große Instanzen von Objekten erstellt werden kann (z. B. "ein Logger für den Kontext der Abfrage"). - Wenn Sie viele Parameter in das Protokoll ausgeben möchten, in den meisten Fällen jedoch kein direkter Datenauszug in die Datei erfolgt, sollten Sie mehrere Aufrufe durchführen. Daher erstellt NLog keine zusätzlichen Objekte auf dem Heap, wenn sie dort nicht benötigt werden.
Schlussfolgerungen für Ihren Code:
- Wenn Ihre Methode ein beliebiges Objekt (d. H. Ein
object ) akzeptiert und in den meisten Fällen nichts tut (was für Verträge / Validatoren gilt), ist es am korrektesten, Aufrufe in eine generische Form zu verpacken (d. H. Methoden der Form Something<TArg>(TArg arg) ). Dies wird sehr schnell funktionieren. - Wenn in Ihrem Code ein Zurücksetzen der Dateidaten zulässig ist und gleichzeitig mit etwas anderem gearbeitet wird, ist es besser, verwirrt zu sein und dies zu unterstützen. Ja, es scheint offensichtlich, dass die parallele Ausführung die Arbeit beschleunigen kann. Bei E / A-Vorgängen bietet dieser Ansatz jedoch auch eine zusätzliche Leistungssteigerung auf Computern mit langsamen Festplatten.