Verbessert die Überprüfung von isDebugEnabled vor der Protokollierung in log4j die Leistung?

207

Ich verwende Log4J in meiner Anwendung für die Protokollierung. Zuvor verwendete ich einen Debug-Aufruf wie:

Option 1:

logger.debug("some debug text");

Einige Links deuten jedoch darauf hin, dass es besser ist, isDebugEnabled()zuerst zu überprüfen , z.

Option 2:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text");
}

Meine Frage lautet also " Verbessert Option 2 die Leistung in irgendeiner Weise? ".

Denn in jedem Fall hat das Log4J-Framework die gleiche Prüfung für debugEnabled. Für Option 2 kann es vorteilhaft sein, wenn wir mehrere Debug-Anweisungen in einer einzelnen Methode oder Klasse verwenden, wobei das Framework die isDebugEnabled()Methode nicht mehrmals (bei jedem Aufruf) aufrufen muss. In diesem Fall wird die isDebugEnabled()Methode nur einmal aufgerufen. Wenn Log4J für die Debug-Ebene konfiguriert ist, wird die isDebugEnabled()Methode tatsächlich zweimal aufgerufen :

  1. Im Fall der Zuweisung eines Werts zur debugEnabled-Variablen und
  2. Wird tatsächlich von der Methode logger.debug () aufgerufen.

Ich denke nicht, dass wenn wir mehrere logger.debug()Anweisungen in Methode oder Klasse schreiben und debug()Methode gemäß Option 1 aufrufen , dies für das Log4J-Framework im Vergleich zu Option 2 isDebugEnabled()ein Overhead ist. Da es sich um eine sehr kleine Methode handelt (in Bezug auf Code), könnte dies der Fall sein sei ein guter Kandidat für Inlining.

Stiller Krieger
quelle

Antworten:

247

In diesem speziellen Fall ist Option 1 besser.

Die Guard-Anweisung (Überprüfung isDebugEnabled()) soll eine möglicherweise teure Berechnung der Protokollnachricht verhindern, wenn die toString()Methoden verschiedener Objekte aufgerufen und die Ergebnisse verkettet werden.

In dem angegebenen Beispiel ist die Protokollnachricht eine konstante Zeichenfolge. Das Verwerfen des Protokollierers ist also genauso effizient wie das Überprüfen, ob der Protokollierer aktiviert ist, und verringert die Komplexität des Codes, da weniger Verzweigungen vorhanden sind.

Besser noch ist es, ein aktuelleres Protokollierungsframework zu verwenden, bei dem die Protokollanweisungen eine Formatspezifikation und eine Liste von Argumenten enthalten, die vom Protokollierer ersetzt werden sollen - jedoch "träge", nur wenn der Protokollierer aktiviert ist. Dies ist der Ansatz von slf4j .

Weitere Informationen und ein Beispiel für die Ausführung einer solchen Frage mit log4j finden Sie in meiner Antwort auf eine verwandte Frage .

erickson
quelle
3
log5j erweitert log4j ähnlich wie slf4j
Bill Michell
Dies ist auch der Ansatz von java.util.Logging.
Paul
@Geek Es ist effizienter, wenn das Protokollereignis deaktiviert ist, da die Protokollstufe hoch eingestellt ist. Siehe den Abschnitt "Die Notwendigkeit der bedingten Protokollierung" in meiner Antwort hier.
erickson
1
Hat sich dies in log4j 2 geändert?
SnakeDoc
3
@SnakeDoc Nein. Für den Methodenaufruf ist es von grundlegender Bedeutung: Ausdrücke in Methodenarg-Listen werden vor dem Aufruf effektiv ausgewertet. Wenn diese Ausdrücke a) als teuer erachtet werden und b) nur unter bestimmten Bedingungen gewünscht werden (z. B. wenn das Debuggen aktiviert ist), besteht Ihre einzige Wahl darin, eine Bedingungsprüfung um den Aufruf herum durchzuführen, und das Framework kann dies nicht für Sie tun. Bei formatiererbasierten Protokollmethoden können Sie einige Objekte übergeben (die im Wesentlichen kostenlos sind), und der Protokollierer ruft toString()nur bei Bedarf auf.
SusanW
31

Da in Option 1 die Nachrichtenzeichenfolge eine Konstante ist, ist es absolut kein Vorteil, die Protokollierungsanweisung mit einer Bedingung zu versehen. Wenn die Protokollanweisung dagegen debuggen aktiviert ist, werden Sie zweimal ausgewertet, einmal in der isDebugEnabled()Methode und einmal in debug()Methode. Die Kosten für das Aufrufen isDebugEnabled()liegen in der Größenordnung von 5 bis 30 Nanosekunden, was für die meisten praktischen Zwecke vernachlässigbar sein sollte. Daher ist Option 2 nicht wünschenswert, da sie Ihren Code verschmutzt und keinen anderen Gewinn bietet.

Ceki
quelle
17

Die Verwendung von isDebugEnabled()ist reserviert, wenn Sie Protokollnachrichten durch Verketten von Strings erstellen:

Var myVar = new MyVar();
log.debug("My var is " + myVar + ", value:" + myVar.someCall());

In Ihrem Beispiel gibt es jedoch keinen Geschwindigkeitsgewinn, da Sie nur einen String protokollieren und keine Vorgänge wie die Verkettung ausführen. Daher fügen Sie Ihrem Code nur Aufblähung hinzu und erschweren das Lesen.

Ich persönlich verwende die Aufrufe im Java 1.5-Format in der String-Klasse wie folgt:

Var myVar = new MyVar();
log.debug(String.format("My var is '%s', value: '%s'", myVar, myVar.someCall()));

Ich bezweifle, dass es viel Optimierung gibt, aber es ist einfacher zu lesen.

Beachten Sie jedoch, dass die meisten Protokollierungs-APIs eine sofort einsatzbereite Formatierung bieten: slf4j bietet beispielsweise Folgendes:

logger.debug("My var is {}", myVar);

das ist noch einfacher zu lesen.

Alex
quelle
8
Ihre Verwendung von String.format (...) erleichtert zwar das Lesen der Protokollzeile, kann jedoch die Leistung beeinträchtigen. Die SLF4J-Methode sendet die Parameter an die logger.debug-Methode und dort erfolgt die Auswertung von isDebugEnabled, bevor die Zeichenfolge erstellt wird. So wie Sie es tun, wird mit String.format (...) die Zeichenfolge erstellt, bevor der Methodenaufruf für logger.debug ausgeführt wird, sodass Sie die Strafe für die Zeichenfolgenerstellung auch dann bezahlt haben, wenn die Debugstufe erreicht ist nicht aktiviert. Entschuldigung für die Nit Picking, nur um Verwirrung für Neulinge zu vermeiden
;-)
2
String.format ist 40-mal langsamer als concat & slf4j hat eine Beschränkung von 2 Parametern. Siehe Zahlen hier: stackoverflow.com/questions/925423/… Ich habe so manche Profiler-Grafik gesehen, bei der die Formatierungsoperation in Debug-Anweisungen verschwendet wird, wenn das Produktionssystem ist Laufen auf Log-Ebene von INFO oder ERROR
AztecWarrior_25
8

Kurzversion: Sie können auch die boolesche Prüfung isDebugEnabled () durchführen.

Gründe:
1- Wenn komplizierte Logik / String concat. Wird Ihrer Debug-Anweisung hinzugefügt, ist die Prüfung bereits vorhanden.
2- Sie müssen die Anweisung nicht selektiv in "komplexe" Debug-Anweisungen aufnehmen. Alle Aussagen sind auf diese Weise enthalten.
3- Wenn Sie log.debug aufrufen, wird vor dem Protokollieren Folgendes ausgeführt:

if(repository.isDisabled(Level.DEBUG_INT))
return;

Dies entspricht im Wesentlichen dem Aufruf des Protokolls. oder Katze. isDebugEnabled ().

JEDOCH! Dies ist, was die log4j-Entwickler denken (wie es in ihrem Javadoc ist und Sie sollten es wahrscheinlich befolgen.)

Dies ist die Methode

public
  boolean isDebugEnabled() {
     if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }

Dies ist der Javadoc dafür

/**
*  Check whether this category is enabled for the <code>DEBUG</code>
*  Level.
*
*  <p> This function is intended to lessen the computational cost of
*  disabled log debug statements.
*
*  <p> For some <code>cat</code> Category object, when you write,
*  <pre>
*      cat.debug("This is entry number: " + i );
*  </pre>
*
*  <p>You incur the cost constructing the message, concatenatiion in
*  this case, regardless of whether the message is logged or not.
*
*  <p>If you are worried about speed, then you should write
*  <pre>
*    if(cat.isDebugEnabled()) {
*      cat.debug("This is entry number: " + i );
*    }
*  </pre>
*
*  <p>This way you will not incur the cost of parameter
*  construction if debugging is disabled for <code>cat</code>. On
*  the other hand, if the <code>cat</code> is debug enabled, you
*  will incur the cost of evaluating whether the category is debug
*  enabled twice. Once in <code>isDebugEnabled</code> and once in
*  the <code>debug</code>.  This is an insignificant overhead
*  since evaluating a category takes about 1%% of the time it
*  takes to actually log.
*
*  @return boolean - <code>true</code> if this category is debug
*  enabled, <code>false</code> otherwise.
*   */
Andrew Carr
quelle
1
Vielen Dank, dass Sie JavaDoc hinzugefügt haben. Ich wusste, dass ich diesen Rat irgendwo zuvor gesehen hatte und versuchte, eine endgültige Referenz zu finden. Dies ist, wenn auch nicht endgültig, zumindest sehr gut informiert.
Simon Peter Chappell
7

Wie andere bereits erwähnt haben, ist die Verwendung der Guard-Anweisung nur dann wirklich nützlich, wenn das Erstellen der Zeichenfolge ein zeitaufwändiger Aufruf ist. Spezifische Beispiele hierfür sind, dass beim Erstellen der Zeichenfolge ein verzögertes Laden ausgelöst wird.

Es ist erwähnenswert, dass dieses Problem mithilfe von Simple Logging Facade für Java oder (SLF4J) - http://www.slf4j.org/manual.html vermieden werden kann . Dies ermöglicht Methodenaufrufe wie:

logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);

Dadurch werden die übergebenen Parameter nur in Zeichenfolgen konvertiert, wenn das Debuggen aktiviert ist. SLF4J ist, wie der Name schon sagt, nur eine Fassade, und die Protokollierungsaufrufe können an log4j weitergeleitet werden.

Sie könnten auch sehr leicht "Ihre eigene" Version davon rollen.

Hoffe das hilft.

Pablojim
quelle
6

Option 2 ist besser.

An sich verbessert es die Leistung nicht. Es stellt jedoch sicher, dass die Leistung nicht beeinträchtigt wird. Hier ist wie.

Normalerweise erwarten wir logger.debug (someString);

Aber normalerweise, wenn die Anwendung wächst, wechselt man viele Hände, besonders Anfänger, wie man sehen kann

logger.debug (str1 + str2 + str3 + str4);

und dergleichen.

Selbst wenn die Protokollstufe auf ERROR oder FATAL eingestellt ist, kommt es zu einer Verkettung von Zeichenfolgen! Wenn die Anwendung viele Nachrichten auf DEBUG-Ebene mit Zeichenfolgenverkettungen enthält, ist ein Leistungseinbruch besonders bei JDK 1.4 oder niedriger erforderlich. (Ich bin nicht sicher, ob spätere Versionen von jdk intern stringbuffer.append () ausführen).

Deshalb ist Option 2 sicher. Sogar die String-Verkettungen treten nicht auf.

Sathya
quelle
3

Wie bei @erickson kommt es darauf an. Wenn ich mich recht erinnere, isDebugEnabledist bereits in der debug()Methode von Log4j gebaut.
Solange Sie in Ihren Debug-Anweisungen keine teuren Berechnungen durchführen, z. B. Schleifen für Objekte, Berechnungen durchführen und Zeichenfolgen verketten, ist dies meiner Meinung nach in Ordnung.

StringBuilder buffer = new StringBuilder();
for(Object o : myHugeCollection){
  buffer.append(o.getName()).append(":");
  buffer.append(o.getResultFromExpensiveComputation()).append(",");
}
log.debug(buffer.toString());

wäre besser als

if (log.isDebugEnabled(){
  StringBuilder buffer = new StringBuilder();
  for(Object o : myHugeCollection){
    buffer.append(o.getName()).append(":");
    buffer.append(o.getResultFromExpensiveComputation()).append(",");
  }
  log.debug(buffer.toString());
}
Michael Myers
quelle
3

Für eine einzelne Zeile verwende ich eine ternäre Nachricht innerhalb der Protokollierungsnachricht. Auf diese Weise mache ich keine Verkettung:

ej:

logger.debug(str1 + str2 + str3 + str4);

Ich mache:

logger.debug(logger.isDebugEnable()?str1 + str2 + str3 + str4:null);

Aber für mehrere Codezeilen

ej.

for(Message mess:list) {
    logger.debug("mess:" + mess.getText());
}

Ich mache:

if(logger.isDebugEnable()) {
    for(Message mess:list) {
         logger.debug("mess:" + mess.getText());
    }
}
rbeltrand
quelle
3

Da diese Antwort wahrscheinlich von vielen Personen bei der Suche nach log4j2 angezeigt wird und fast alle aktuellen Antworten log4j2 oder die jüngsten Änderungen nicht berücksichtigen, sollte dies hoffentlich die Frage beantworten.

log4j2 unterstützt Lieferanten (derzeit eigene Implementierung, laut Dokumentation ist jedoch geplant, die Lieferantenschnittstelle von Java in Version 3.0 zu verwenden). Mehr dazu lesen Sie im Handbuch . Auf diese Weise können Sie die Erstellung teurer Protokollnachrichten einem Lieferanten zuweisen, der die Nachricht nur erstellt, wenn sie protokolliert werden soll:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());
Marcono1234
quelle
2

Es verbessert die Geschwindigkeit, da es üblich ist, Zeichenfolgen im Debug-Text zu verketten, was teuer ist, z.

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text" + someState);
}
Tom
quelle
1
Wenn wir jdk 1.5 und höher verwenden, werden verkettete Zeichenfolgen meiner Meinung nach keinen Unterschied machen.
Silent Warrior
Woher? Was würde JDK5 anders machen?
Javashlook
1
Wenn wir in jdk 1.5 Zeichenfolgen in einer einzelnen Anweisung verketten, wird intern nur die Methode StringBuffer.append () verwendet. Dies wirkt sich also nicht auf die Leistung aus.
Silent Warrior
2
Die Verkettung von Strings braucht zweifellos Zeit. Ich bin mir jedoch nicht sicher, ob ich es als "teuer" bezeichnen würde. Wie viel Zeit wird im obigen Beispiel gespart? Im Vergleich zu dem, was der umgebende Code tatsächlich tut? (zB Datenbanklesevorgänge oder In-Memory-Berechnung). Ich denke, diese Art von Aussagen müssen qualifiziert werden
Brian Agnew
1
Selbst JDK 1.4 erstellt keine neuen String-Objekte mit einfacher String-Verkettung. Die Leistungsbeeinträchtigung ergibt sich aus der Verwendung von StringBuffer.append (), wenn überhaupt keine Zeichenfolge angezeigt werden soll.
Javashlook
1

Seit der Log4j- Version 2.4(oder slf4j-api 2.0.0-alpha1) ist es viel besser, eine fließende API (oder Java 8-Lambda-Unterstützung für die verzögerte Protokollierung ) zu verwenden, die das Supplier<?>Argument der Protokollnachricht unterstützt , das von Lambda angegeben werden kann :

log.debug("Debug message with expensive data : {}", 
           () -> doExpensiveCalculation());

ODER mit slf4j API:

log.atDebug()
            .addArgument(() -> doExpensiveCalculation())
            .log("Debug message with expensive data : {}");
Dan Brandt
quelle
0

Wenn Sie Option 2 verwenden, führen Sie eine schnelle Boolesche Prüfung durch. In Option eins führen Sie einen Methodenaufruf durch (Verschieben von Daten auf den Stapel) und führen dann eine Boolesche Prüfung durch, die immer noch schnell ist. Das Problem, das ich sehe, ist die Konsistenz. Wenn einige Ihrer Debug- und Info-Anweisungen eingeschlossen sind und andere nicht, handelt es sich nicht um einen konsistenten Codestil. Außerdem könnte später jemand die Debug-Anweisung so ändern, dass sie verkettete Zeichenfolgen enthält, was immer noch ziemlich schnell ist. Ich habe festgestellt, dass wir beim Einpacken der Debug- und Info-Anweisung in eine große Anwendung und beim Profilieren ein paar Prozentpunkte an Leistung eingespart haben. Nicht viel, aber genug, um die Arbeit wert zu machen. Ich habe jetzt ein paar Makros in IntelliJ eingerichtet, um automatisch umschlossene Debug- und Info-Anweisungen für mich zu generieren.

Javamann
quelle
0

Ich würde empfehlen, Option 2 für die meisten de facto zu verwenden, da es nicht sehr teuer ist.

Fall 1: log.debug ("eine Zeichenfolge")

Fall 2: log.debug ("eine Zeichenfolge" + "zwei Zeichenfolgen" + object.toString + object2.toString)

Zum Zeitpunkt des Aufrufs muss die Parameterzeichenfolge in log.debug (sei es CASE 1 oder Case2) ausgewertet werden. Das ist es, was jeder unter "teuer" versteht. Wenn Sie die Bedingung 'isDebugEnabled ()' vor sich haben, müssen diese nicht ausgewertet werden. Hier wird die Leistung gespeichert.

Jolly1234
quelle
0

Ab 2.x ist in Apache Log4j diese Prüfung integriert, sodass dies isDebugEnabled()nicht mehr erforderlich ist. debug()Wenn Sie einfach a ausführen, werden die Nachrichten unterdrückt, wenn sie nicht aktiviert sind.

ha9u63ar
quelle
-1

Mit Log4j2 können Sie Parameter in eine Nachrichtenvorlage formatieren, ähnlich wie in Log4j2 String.format(), wodurch die Notwendigkeit entfällt isDebugEnabled().

Logger log = LogManager.getFormatterLogger(getClass());
log.debug("Some message [myField=%s]", myField);

Beispiel für einfache log4j2.properties:

filter.threshold.type = ThresholdFilter
filter.threshold.level = debug
appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d %-5p: %c - %m%n
appender.console.filter.threshold.type = ThresholdFilter
appender.console.filter.threshold.level = debug
rootLogger.level = info
rootLogger.appenderRef.stdout.ref = STDOUT
Andre
quelle