W końcu logować z IF (isDebugEnabled()) czy nie?!

Ostatnio staram się pisać małe metody, w imię czytelności kodu. W związku z tym każda dodatkowa linijka zwiększa objętość metody. W malutkich metodach jedna linia to nawet kilkadziesiąt procent objętości :) A co z logowaniem informacji debugujących? Zgodnie z zaleceniami autora Log4j (bo tego loggera zazwyczaj używam), przed zalogowaniem debug() powinno się sprawdzić czy ten poziom jest włączony, aby niepotrzebnie nie tracić czasu procesora na inicjalizowanie stringa do zalogowania. Ceki Gülcü, autor Log4j, w 2002 przekonywał, że sprawdzanie IFem poziomu na PII 233MHz zajmuje nanosekundy, co stanowi mały narzut. Rzeczywiście. A co, gdyby w imię czytelności kodu zrezygnować z tego sprawdzania? Co się wówczas stanie? Ile czasu stracimy? I czy mimo wyłączonego logowania niepotrzebnie wiadomość będzie przetwarzana wewnątrz loggera?

Otóż, oba popularne loggery Log4j i java.utils.Logging sprawdzają czy dany poziom jest włączony i oczywiście nie logują komunikatu, jeśli nie pasuje do poziomu. W takim razie jedynym istotnym problemem jest czas konstruowania wiadomości do zalogowania. Zazwyczaj jest to operacja sklejania kilku stringów, bo chcemy zalogować jakąś operacje np. z jej parametrami. Warto przy tym zauważyć, że czasy kiedy "jakiś string" + "inny" powodowało kilka wywołań konstruktora String(). Od javy 1.5 (lub wcześniej, bo nie wiem) , sklejanie stringów zawsze jest zastępowane StringBuilderem, a więc jest bardzo efektywne. W związku z tym, każdorazowo należy rozważyć czy dany string, który chcemy zalogować jest złożony czy nie. Jeśli nie, to moim zdaniem nie warto stosować IFów, tylko bezwzględnie pchać go loggera.

A teraz konkretne miary, jako, że jestem inżynierem. Test wykonany na procku dual core 2.66GHz, czyli rząd wielkości szybszy od twórcy Log4j. Dzisiaj uważany za przeciętnie dobry sprzęt.
Napisałem program, który 100 000 razy loguje wiadomość, przy wyłączonym debugowaniu. Przy czym w pierwszym teście odbija się od sprawdzenia IFem czy włączone jest debugowanie, a w drugim wchodzi do środka metody logującej. Logowany string to

"Wiadomosc testowa, index " + i + " i jeszcze string"

Mamy tu 3 operacjie StringBuilder.add(), przy czym dla int i jest najbardziej kosztowna, bo i jest od razu zamieniane na string. Wynik:

Test logow bez wlaczonego debuga, ze sprawdzaniem IF
Czas 0ms
Test logow bez wlaczonego debuga, bez sprawdzania IF
Czas 93ms

0 ms oznacza rzeczywiście submilisekundowe czasy sprawdzania czy poziom to DEBUG. 93 ms w rozłożeniu na 100 tyś. wywołań daje nam 93 ns (nano sekund!) na sklejanie. Dodam na koniec, że zaskoczony wynikiem podejrzewałem mocną optymalizację ze strony JVM, czego nie da się wykluczyć, ale drugi test z wielokrotnym powtórzeniem logowanej wiadomości (czyli rezygnacja z pętli) dało również submilisekundowe wyniki. Wkleiłem setkę razy

logger.debug("Wiadomosc testowa, index " + (i++) + " i jeszcze string");

Konkluzja: moim zdaniem przy prostej treści logowanej wiadomości, można zrezygnować ze sprawdzania poziomu logowania na rzecz uproszczenia (wizualnego) kodu.

Źródełko:

[sourcecode language="java"]
package pl.ostrejezyki.zdanek;

import org.apache.log4j.ConsoleAppender;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class LoggingEffectivenessTests {

private static Logger logger = Logger.getLogger(LoggingEffectivenessTests.class);

public static void main(String[] args) {

initLog4j();

testCheckingIfDebugIsEnabled();
testWithoutCheckingIfDebugIsEnabled();

}

private static void testWithoutCheckingIfDebugIsEnabled() {
long start;
long stop;
System.out.println("Test logow bez wlaczonego debuga, bez sprawdzania IF");

start = System.currentTimeMillis();
for (int i = 0; i < 100000; i++) {
logger.debug("Wiadomosc testowa, index " + i + " i jeszcze string");
}
stop = System.currentTimeMillis();

System.out.println("Czas " + (stop - start) + "ms");
}

private static void testCheckingIfDebugIsEnabled() {
System.out.println("Test logow bez wlaczonego debuga, ze sprawdzaniem IF");

long start = System.currentTimeMillis();
for (int i = 0; i < 100000; i++) {
if (logger.isDebugEnabled()) {
throw new IllegalStateException("Debug wlaczony, a powinien byc wylaczony");
}
}
long stop = System.currentTimeMillis();

System.out.println("Czas " + (stop - start) + "ms");
}

private static void initLog4j() {
Logger l = Logger.getRootLogger();
ConsoleAppender ca = new ConsoleAppender();
l.addAppender(ca);
l.setLevel(Level.ERROR);
}
}
[/sourcecode]