Hallo Habr!

Ich denke, fast jedes Programm hat Protokollierung. Darüber hinaus werden in einer Reihe bereits neuer Anwendungen (dh mit einer Vielzahl nicht trivialer Bedingungen) Protokolle auf einem Kampfserver häufig von entscheidender Bedeutung.

Trotz der Bedeutung und Verbreitung einer solchen Technologie habe ich festgestellt, dass Menschen bei der Arbeit mit ihnen häufig Standardfehler machen. Dieser Artikel beschreibt das Verhalten von .Net in vielerlei Hinsicht. Ich habe jedoch kleine Einfügungen aus der Java-Welt erstellt, um einen Vergleich zu ermöglichen.

Zuordnungen (Speicherzuordnung)

Der häufigste Fehler (nach meinen Beobachtungen) ist eine Nachlässigkeit in Bezug auf kleine Speicherzuordnungen in der Nähe des Ortes des Aufrufs der Funktion log.Debug(...) .

Also, unser Standardcode in .Net:

 private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 } 

In vielerlei Hinsicht habe ich nur die log4net- und NLog- Bibliotheken gesehen und werde sie daher in den Beispielen verwenden.

Die Fragen sind also:

• In welchen Zeilen wird Speicher zugewiesen, auch wenn Debug deaktiviert ist?
• Wie einfach ist es, in derselben dotTrace zu erkennen, dass speziell Logger für diese Speicherzuweisung verantwortlich sind, wenn Speicher zugewiesen wird?

Die richtige Antwort auf die erste Frage: Speicher wird nicht nur in Absatz "6" zugewiesen. Und die Antwort auf die zweite Frage: Es ist unglaublich schwer zu fangen, da dieser Code häufig über das Projekt verteilt ist. Sie können sich an eine typische .Net-Anwendung erinnern. Es wird oft ähnlichen Code geben, mit dem GC funktioniert.

Lassen Sie uns jedoch die technischen Details durchgehen, um genau zu verstehen, wo wir einen Einfluss auf die Leistung haben werden.

Also der erste Punkt:

 Log4NetLog.Debug($"Id={id}"); // 1 

Tatsächlich konvertiert der Compiler es in:

 var temp = string.Format("Id={0}", id); // <--       Log4NetLog.Debug(temp); 

Das heißt, der erste Ausdruck zwingt den Prozessor im Wesentlichen dazu, eine Zeichenfolge zu erstellen und diese an den Logger zu übergeben. Er wird schnell überprüfen, ob Sie sich nicht anmelden müssen, und daher wurde die Zeile nur im Speicher erstellt. Und was wichtig ist, wenn Sie mehr solchen Code kopieren, werden die Zeilen in Haufen von Programmstellen erstellt, dh das Programm arbeitet nur ein wenig langsamer. Überall.

Das zweite Beispiel ist etwas effizienter, da darin keine Zeile erstellt wird:

 Log4NetLog.DebugFormat("Id={0}", id); 

Hier wird jedoch noch Speicher zugewiesen, da Boxen auftreten wird. Ich möchte Sie an die Signatur der DebugFormat-Methode erinnern:

 void DebugFormat(string format, object arg0) 

Wie Sie sehen können, erfordert die Eingabe einen Referenztyp. Wir versuchen jedoch, einen aussagekräftigen int Typ zu übergeben. Infolgedessen führt jeder Aufruf dazu, dass die Heap-Parameter- id übergeben wird, um sie an die Methode zu übergeben. Und ich möchte Sie daran erinnern, dass der Parameter selbst in der Methode selbst nicht benötigt wird, da Debug durch die Bedingung der Aufgabe Debug ist.

Das folgende Beispiel ist geladen und einfach:

 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 

Ich bin sicher, dass Sie bereits verstanden haben, dass die Linie wieder auf dem Haufen auffallen wird und so weiter. Überspringen Sie daher sofort dieses Beispiel. Die folgende Aufrufmethode sieht effizienter aus:

 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 

Berechnen wir jedoch, wie oft ein Speicher reserviert werden muss:

• email.Normalize() führt zur Erstellung eines Objekts. Daher wird dieses Objekt auf dem Heap (oder auf dem Stapel - es spielt keine Rolle, da das Boxen es erforderlich macht, alles auf dem Heap auszuwählen) zugewiesen.
• id wird auf einen Haufen gehen, wie wir bereits früher in Betracht gezogen haben.
• Log4net verfügt über die folgende Schnittstelle für solche lang formatierten Aufrufe: void DebugFormat(string format, params object[] args) . Wie Sie sehen können, erstellt .Net ein Array auf dem Heap, um es an die DebugFormat Methode zu übergeben.

Infolgedessen führt ein ziemlich typischer Aufruf des Protokollierungsvorgangs zur Erstellung eines Haufens von Objekten im Speicher. Das ist ziemlich enttäuschend, da die Protokollierung selbst oft deaktiviert ist. Fahren wir jedoch mit NLog fort.

Diese Zeile provoziert die Zuordnung des Objekts auf dem Heap:

 NLogLog.Debug($"Id={id}"); 

Hier ist alles offensichtlich, aber die folgende Zeile hat keinen solchen Nachteil mehr:

 NLogLog.Debug("Id={0}", id); 

Und der Grund ist, dass NLog eine spezielle Signatur für Ints hat: void Debug(string message, int argument) . Selbst wenn Sie eine andere Struktur übertragen, wird die void Debug<TArgument>([Localizable(false)] string message, TArgument argument) . Und diese Methode erfordert kein Boxen, da nach JIT für jeden Typ eine eigene Funktion erstellt wird (dies ist natürlich nicht ganz richtig, aber der wichtige Punkt ist: Es wird kein Boxen geben).

Ich überspringe das leicht verständliche Skript mit einer großen Eingabezeile und gehe direkt zu:

 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); 

Seltsamerweise hat NLog die Anzahl der generischen Parameter für Methoden nicht erhöht, und daher wird die Signatur verwendet: void Debug([Localizable(false)] string message, params object[] args) . Und es wird wieder zur Schaffung von Objekten in Haufen und so weiter führen.

Schlussfolgerungen und Verbesserungen

Die Hauptschlussfolgerung: Wenn Sie viele Aufrufe an die Protokollierungsmethoden im Programm haben, die nicht zum physischen Schreiben in die Datei führen, können Sie aus heiterem Himmel viele unnötige Objekte auf dem Heap zuweisen. Und damit die Arbeit des Programms behindern.

Schlussfolgerung 2: Wenn Sie nicht viele Objekte an eine Methode übergeben, verwenden Sie NLog. Aufgrund der Tatsache, dass die generischen Parameter berücksichtigt wurden, können Sie die Leistung entspannter gestalten.

Um jedoch völlig sicher zu sein, ist es logischer, dies zu tun:

 if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); } 

Hier wird die Protokollierungsmethode nicht aufgerufen, wenn dies nicht erforderlich ist. Wenn Sie die Daten dennoch in das Protokoll kopieren müssen, wird die praktische Zeichenfolgeninterpolation verwendet. Im Inneren haben Logger (mindestens das gleiche NLog) Optimierungen, um eine Zeile direkt in die Protokolle zu schreiben (d. H. Die Formatierung erfolgt sofort in Stream , anstatt eine Zeile im Speicher zu erstellen). Diese Optimierung von NLog verschwindet jedoch mit der Tatsache, dass Sie die Daten auf eine Datei zurücksetzen müssen.

Kotlin Beispiel

Um die Beschreibung der Arbeit beliebter Logger in .Net zu verwässern, werde ich eine interessante Möglichkeit geben, Anrufe in Kotlin zu verpacken. Die Idee basiert buchstäblich auf einem interessanten Merkmal der Sprache: Inline-Methoden . Ein einfacher Code, um etwas zum Debuggen auszugeben:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } } 

Und es wird vom Compiler in so etwas konvertiert:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ /*handle*/ } } } } 

Hier ist es wichtig: Alles in geschweiften Klammern in der Nähe des debug ist ein Lambda. Es wird jedoch in Ihre Methode eingebettet, dh es wird kein Funktionsobjekt im Heap erstellt. Auf diese Weise können Sie große Operationen ausblenden, die nur aufgerufen werden, wenn Sie das Ergebnis zum debug ausgeben möchten. Zum Beispiel:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } } 

Hier wird getIdList nur aufgerufen, wenn Sie etwas an die Datei senden müssen. Und das alles, weil der Code konvertiert wird in:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ /*handle*/ } } logger.debug { "Identity: $id" } } } 

Großes Objekt ==> Großer Objekthaufen

Neben dem vorherigen Beispiel. Ich bin sicher, dass viele Leute wissen, dass .Net / JVM das Konzept des "Large Object Heap" hat. Genauer gesagt gibt es in Java keine spezielle Definition. Allokatoren erstellen jedoch häufig große Objekte sofort in der neuesten Generation (um die Bewegung von Objekten zu minimieren und das Problem der schnellen Speicherdurchdringung für einen Streaming-Allokator zu lösen).

Zurück zum Beispiel:

 NLogLog.Debug($"Id={id}"); 

Wenn das id Objekt über eine Implementierung von ToString , die eine Zeichenfolge von der Größe eines Megabytes erstellt, werden im LOH-Bereich die folgenden Treffer angezeigt:

• ToString ruft sich selbst auf
• Formatieren von $"Id={id}"
• Und wenn die Entwickler des Loggers all diese Dinge nicht verstanden haben (und es äußerst schwierig ist, einen Test für das Fehlen von Objekten in LOH zu schreiben), fügt der Logger Probleme hinzu.

Und hier können Sie drei Methoden zum Protokollieren solcher Dinge verwenden:

• Verwenden Sie ein spezielles Layout und benötigen Sie keinen Aufruf von ToString . Beispielsweise verfügt NLog über ein JsonLayout . Auf diese Weise können Sie einfach ein Objekt an den Logger übertragen, das sofort in den resultierenden Stream (z. B. in eine Datei) serialisiert wird.
• Schreiben Sie selbst in die Datei. Oder mit anderen Worten - verwenden Sie den Logger nicht. Ich kann nur selbst beraten, wie ich herausfinden kann, in welche Datei NLog schreiben wird: var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . FileTarget gibt diese Funktion das erste FileTarget , das FileTarget wird. Wenn jedoch alle FileTarget in denselben Ordner schreiben, können Sie auf ähnliche Weise den Ordner für die Aufzeichnung ermitteln und dann direkt einen Speicherauszug Ihres Objekts an die Datei senden.
• Wenn Sie log4j2 haben (das zweite ist wichtig), können Sie StringBuilderFormattable verwenden . Es wurde nur erstellt, um Daten in Teilen in den Logger auszugeben (außerdem, um keinen Teil der Teile im Heap zuzuweisen, da sie bereits ausgewählt sind).

 public interface StringBuilderFormattable { /** * Writes a text representation of this object into the specified {@code StringBuilder}, ideally without allocating * temporary objects. * * @param buffer the StringBuilder to write into */ void formatTo(StringBuilder buffer); } 

Synchronität (und Asynchronitätsprobleme)

Einmal bemerkte ich in einem Programm, dass während geladener Vorgänge etwa die Hälfte der Wartezeit der Benutzeroberfläche durch Protokollierungsvorgänge berücksichtigt wurde. Noch einmal: Die Hälfte der Programmzeit wurde für einen Aufruf von logger.Debug oder ähnlichem logger.Debug . Und der Grund dafür ist einfach: Wir haben log4net verwendet, das Dateien nur synchron schreiben kann.

Von hier habe ich Regel 1 abgeleitet: Der Logger sollte immer in einem anderen Thread arbeiten. Sie sollten den Anwendungscode nicht aus Gründen der Ablaufverfolgung blockieren, da dies unglaublich seltsam ist. Mit anderen Worten - mit NLog müssen Sie immer async=true in das nlog Tag nlog (es ist das Haupt-Tag). Oder wie das Beispiel sagt:

 <targets async="true"> ... your targets go here ... </targets> 

Wenn Sie log4net verwenden, leiten Sie es entweder zu NLog um oder erstellen Sie AsyncFileAppender.

Für die Java-Welt: Sowohl Logback als auch Log4J2 können asynchrone Protokollierung durchführen. Hier ist ein Vergleich von der offiziellen Seite :

Wenn jedoch alles asynchron geschrieben wird, tritt ein anderes Problem auf - was ist bei kritischen Fehlern zu tun? Schließlich kommt es vor, dass ein Programm nicht beendet wird, weil es den Hauptthread verlassen hat (z. B. kann ein Programm durch Aufrufen von Application.Exit oder Environment.FailFast , was nicht sehr schön ist, aber tatsächlich auftritt). In diesem Fall müssen Sie immer Flush aufrufen, bevor Sie Ihren Prozess Flush . Andernfalls werden die wertvollsten Informationen übersehen, wenn Sie auf den Kampfserver fallen.

Fazit

Ich hoffe, dieser Artikel hilft Ihnen beim Schreiben schneller Programme mit bequemer Protokollierung. Ich habe nur einen Teil der Probleme hervorgehoben, die ich im Code sehe. Alle von ihnen sind nicht die offensichtlichsten, aber nicht die schwierigsten.

Wie ich eingangs sagte, ist die Arbeit mit Loggern in fast jeder Anwendung. Außerdem gibt nach meinen Notizen etwa die Hälfte der Klassen selbst etwas in das Protokoll aus. Der korrekte Betrieb mit diesen Funktionen wirkt sich somit auf fast die gesamte Anwendung aus.