Czy w log4j sprawdzanie isDebugEnabled przed zalogowaniem poprawia wydajność?

Korzystam z Log4J w mojej aplikacji do logowania. Wcześniej używałem połączenia debugowania, takiego jak:

Opcja 1:

logger.debug("some debug text");

ale niektóre linki sugerują, że lepiej isDebugEnabled()najpierw sprawdzić , na przykład:

Opcja 2:

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

Więc moje pytanie brzmi: „ Czy opcja 2 poprawia wydajność w jakikolwiek sposób? ”.

Ponieważ w każdym przypadku środowisko Log4J ma takie samo sprawdzenie pod kątem debugEnabled. W przypadku opcji 2 może być korzystne, jeśli używamy wielu instrukcji debugowania w pojedynczej metodzie lub klasie, gdzie środowisko nie musi wywoływać isDebugEnabled()metody wiele razy (przy każdym wywołaniu); w tym przypadku wywołuje isDebugEnabled()metodę tylko raz, a jeśli Log4J jest skonfigurowany do debugowania poziomu, w rzeczywistości wywołuje isDebugEnabled()metodę dwukrotnie:

1. W przypadku przypisania wartości zmiennej debugEnabled, oraz
2. W rzeczywistości wywoływany przez metodę logger.debug ().

Nie sądzę, że jeśli napiszemy wiele logger.debug()instrukcji w metodzie lub klasie i wywołujemy debug()metodę zgodnie z opcją 1, to jest to narzut dla frameworka Log4J w porównaniu z opcją 2. Ponieważ isDebugEnabled()jest to bardzo mała metoda (pod względem kodu), może bądź dobrym kandydatem do inklinacji.

W tym konkretnym przypadku opcja 1 jest lepsza.

Instrukcja warta (sprawdzanie isDebugEnabled()) ma na celu zapobieganie potencjalnie kosztownym obliczeniom komunikatu dziennika, gdy obejmuje wywołanie toString()metod różnych obiektów i połączenie wyników.

W podanym przykładzie komunikat dziennika jest ciągiem ciągłym, więc zezwolenie programowi rejestrującemu na odrzucenie jest tak samo skuteczne, jak sprawdzenie, czy program rejestrujący jest włączony, i zmniejsza złożoność kodu, ponieważ jest mniej rozgałęzień.

Jeszcze lepiej jest użyć bardziej aktualnej struktury rejestrowania, w której instrukcje dziennika przyjmują specyfikację formatu i listę argumentów, które mają zostać zastąpione przez program rejestrujący - ale „leniwie”, tylko jeśli program rejestrujący jest włączony. Takie jest podejście slf4j .

Zobacz moją odpowiedź na powiązane pytanie, aby uzyskać więcej informacji i przykład robienia czegoś takiego z log4j.

Ponieważ w opcji 1 ciąg komunikatu jest stały, nie ma absolutnie żadnego zysku na zawijaniu instrukcji rejestrowania warunkiem, przeciwnie, jeśli instrukcja dziennika jest włączona do debugowania, będziesz oceniać dwa razy, raz w isDebugEnabled()metodzie i raz w debug()metoda. Koszt wywołania isDebugEnabled()jest rzędu od 5 do 30 nanosekund, co powinno być nieistotne dla większości praktycznych celów. Dlatego opcja 2 nie jest pożądana, ponieważ zanieczyszcza twój kod i nie zapewnia żadnych innych korzyści.

Używanie isDebugEnabled()jest zarezerwowane do tworzenia wiadomości dziennika poprzez łączenie ciągów:

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

Jednak w twoim przykładzie nie ma przyrostu prędkości, ponieważ po prostu rejestrujesz ciąg znaków i nie wykonujesz operacji takich jak konkatenacja. Dlatego dodajesz do swojego kodu rozdęcie i utrudniasz czytanie.

Osobiście używam wywołań w formacie Java 1.5 w klasie String w następujący sposób:

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

Wątpię, by było wiele optymalizacji, ale łatwiej to odczytać.

Należy jednak pamiętać, że większość interfejsów API do rejestrowania oferuje takie formatowanie od razu po wyjęciu z pudełka: na przykład slf4j zapewnia:

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

co jest jeszcze łatwiejsze do odczytania.

W Javie 8 nie musisz używać isDebugEnabled()do poprawy wydajności.

https://logging.apache.org/log4j/2.0/manual/api.html#Java_8_lambda_support_for_lazy_logging

import java.util.logging.Logger;
...
Logger.getLogger("hello").info(() -> "Hello " + name);

Krótka wersja: Równie dobrze możesz sprawdzić wartość logiczną isDebugEnabled ().

Powody:
1 - jeśli skomplikowana logika / ciąg konkat. jest dodawany do wyciągu debugowania, będziesz już mieć czek na miejscu.
2- Nie trzeba selektywnie dołączać instrukcji do „złożonych” instrukcji debugowania. Wszystkie oświadczenia są uwzględniane w ten sposób.
3- Wywołanie log.debug wykonuje następujące czynności przed zalogowaniem:

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

Jest to w zasadzie to samo, co dziennik połączeń. lub kot. isDebugEnabled ().

JEDNAK! Tak myślą deweloperzy log4j (tak jak w ich javadoc i prawdopodobnie powinieneś przejść przez to.)

To jest metoda

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

To jest javadoc

/**
*  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.
*   */

Jak wspomnieli inni, użycie instrukcji guard jest naprawdę przydatne tylko wtedy, gdy utworzenie łańcucha jest czasochłonnym wywołaniem. Konkretnymi przykładami tego są przypadki, gdy utworzenie łańcucha spowoduje pewne leniwe ładowanie.

Warto zauważyć, że problemu tego można uniknąć, używając Simple Logging Facade for Java lub (SLF4J) - http://www.slf4j.org/manual.html . Umożliwia to wywołania metod, takie jak:

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

Spowoduje to konwersję przekazanych parametrów na ciągi, tylko jeśli włączone jest debugowanie. SLF4J, jak sama nazwa wskazuje, jest tylko fasadą, a wywołania rejestrowania można przekazać do log4j.

Możesz również bardzo łatwo „stworzyć własną” wersję tego.

Mam nadzieję że to pomoże.

Opcja 2 jest lepsza.

Sam w sobie nie poprawia wydajności. Ale zapewnia wydajność nie pogarsza się. Oto jak.

Zwykle oczekujemy logger.debug (someString);

Ale zwykle, gdy aplikacja rośnie, zmienia wiele rąk, szczególnie początkujących programistów, widać

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

i tym podobne.

Nawet jeśli poziom dziennika jest ustawiony na ERROR lub FATAL, konkatenacja ciągów się dzieje! Jeśli aplikacja zawiera wiele komunikatów poziomu DEBUG z łączeniem łańcuchów, to z pewnością wymaga wydajności, szczególnie w przypadku Jdk 1.4 lub niższej. (Nie jestem pewien, czy późniejsze wersje jdk internall wykonują jakiś stringbuffer.append ()).

Właśnie dlatego Opcja 2 jest bezpieczna. Nawet konkatenacje łańcuchów nie zdarzają się.

Podobnie jak @erickson, zależy. O isDebugEnabledile pamiętam, jest już wbudowany w debug()metodę Log4j.
Dopóki nie wykonujesz drogich obliczeń w instrukcjach debugowania, takich jak pętla na obiektach, wykonywanie obliczeń i łączenie ciągów, moim zdaniem jest w porządku.

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

byłoby lepiej jak

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());
}

W przypadku pojedynczego wiersza używam trójki w komunikacie rejestrowania. W ten sposób nie wykonuję konkatenacji:

ej:

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

Ja robię:

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

Ale dla wielu wierszy kodu

ej.

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

Ja robię:

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

Ponieważ wiele osób prawdopodobnie przegląda tę odpowiedź podczas wyszukiwania log4j2 i prawie wszystkie aktualne odpowiedzi nie uwzględniają log4j2 ani ostatnich zmian w nim, mam nadzieję, że powinno to odpowiedzieć na pytanie.

log4j2 obsługuje Dostawcy (obecnie ich własna implementacja, ale zgodnie z dokumentacją planowane jest użycie interfejsu dostawcy Java w wersji 3.0). Możesz przeczytać o tym trochę więcej w instrukcji . Pozwala to umieścić kosztowne tworzenie wiadomości dziennika u dostawcy, który tworzy wiadomość tylko wtedy, gdy ma być zalogowany:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());

Poprawia szybkość, ponieważ często łączy się ciągi w tekście debugowania, co jest kosztowne, np .:

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

Od wersji Log4j2.4 (lub slf4j-api 2.0.0-alpha1) znacznie lepiej jest używać płynnego API (lub obsługi lambda Java 8 dla leniwego rejestrowania ), obsługującej Supplier<?>argument komunikatu dziennika, który może podać lambda :

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

LUB z API slf4j:

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

Jeśli użyjesz opcji 2, przeprowadzasz szybkie sprawdzenie logiczne. W opcji pierwszej wykonujesz wywołanie metody (wypychanie rzeczy na stos), a następnie sprawdzanie boolowskie, które jest nadal szybkie. Problem, który widzę, to spójność. Jeśli niektóre z instrukcji debugowania i informacji są opakowane, a niektóre nie, to nie jest to spójny styl kodu. Dodatkowo ktoś może później zmienić instrukcję debugowania, aby zawierała łańcuchy konkatenacji, co wciąż jest dość szybkie. Przekonałem się, że kiedy wypakowaliśmy debugowanie i instrukcję informacyjną w dużej aplikacji i profilowaliśmy ją, zaoszczędziliśmy kilka punktów procentowych wydajności. Niewiele, ale wystarczająco, by było warto. Mam teraz kilka ustawień makr w IntelliJ, aby automatycznie generować opakowane instrukcje debugowania i informacyjne.

Polecam korzystanie z Opcji 2 jako de facto dla większości, ponieważ nie jest ona bardzo droga.

Przypadek 1: log.debug („jeden ciąg”)

Przypadek 2: log.debug („jeden ciąg” + „dwa ciąg” + object.toString + object2.toString)

W momencie wywołania któregokolwiek z nich należy ocenić łańcuch parametrów w log.debug (CASE 1 lub Case2). To właśnie wszyscy rozumieją jako „drogi”. Jeśli masz przed nim warunek „isDebugEnabled ()”, nie trzeba ich oceniać, w którym zapisywana jest wydajność.

Począwszy od wersji 2.x, Apache Log4j ma tę funkcję wbudowaną, więc isDebugEnabled()nie jest już konieczne. Po prostu wykonaj a, debug()a wiadomości nie zostaną włączone, jeśli nie zostaną włączone.

Log4j2 pozwala sformatować parametry w szablon wiadomości, podobnie jak String.format(), dzięki czemu nie trzeba tego robić isDebugEnabled().

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

Przykładowe proste 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