Java logging performance

17.1.2013 15:37 | Přečteno: 984×

Nazov blogu znie honosne, ale zaujimalo ma, aky dopad na vykon maju rozne scenare pouzitia loggeru.

Na testy som pouzil oracle java 1.7 64bit, slf4j + logback, meranie prebehlo vzdy 3x na nezatazenom kompe. Je to sice primitivne, ale hrat sa s profilerom nemam cas. Vysledky si sem ukladam pre buducu argumentaciu, ale mozu sa takisto hodit niekomu dalsiemu a usetrim mu tak 10 minut prace.

 

Kod na ktorom som testoval:

private static final Logger logger = LoggerFactory.getLogger(App.class);
    private static final boolean loggerInfoEnabled = logger.isInfoEnabled();

    public static void main(String[] args) {

        long t1 = System.currentTimeMillis();
        long x=0;
        for(long l = 0; l < 1000000000;l++ ) {

            // 1
            logger.info("A {}", l);

            // 2
            if ( logger.isInfoEnabled()) {
                logger.info("A {}",l);
            }


            // 3
            if ( loggerInfoEnabled ) {
                logger.info("A {}",l);
            }

            x++;
        }

        long t2 = System.currentTimeMillis();
        System.out.println(t2-t1);

    }

Komentarmi 1,2 a 3 su oznacene bloky kodu, ktore som mal za/odkomentovane. Vzdy sa vykonaval len jeden zo scenarov. Scenar 0 je s uplne zakomentovanym kodom loggeru a vykonava sa len x++;

 

Vysledky:

 

 

 

0 - 2034, 2307, 2306
1 - 20192, 20395, 20625
2 - 8905, 8930, 8941
3 - 2306, 2301, 2309

 

Vysledok je teda jasny, pokial pracujem v casovo narocnom prostredi, ale chcem mat moznost logovat, pouzijem variantu 3. Nevyhoda je jasna - nebude mi fungovat reloading konfiguracie loggerov za behu aplikacie.

       

Komentáře

[Člověk z Horní Dolní]

Cili overhead je naprosto zanedbatelny.

[Člověk z Horní Dolní]

Pro zajimavost: How do I write a correct micro-benchmark in Java?.

[Franta]

Vysledok je teda jasny, pokial pracujem v casovo narocnom prostredi, ale chcem mat moznost logovat, pouzijem variantu 3.

To mi až tak jasné nepřijde. Protože za 2,0192 ms stihneš zalogovat 100 000 zpráv, to není málo I při variantě #1 jich zaloguješ 10 000, což je stále dost velká rychlost.

Klíčové je hlavně to, dát tam ten IF (klidně s logger.isInfoEnabled()), pokud do logovacích hlášek dáváme parametry, jejichž získání/vypočtení trvá dlouho.

[rastos]

Ja teda neviem ale ... mne to pripadá ani nie tak o rýchlosti logovania ako o rýchlosti -

1. volania funkcie + odovzdanie parametrov ... tou funkciou je .info(...)
2. volania funkcie ... tou funkciou je .isInfoEnabled()
3. prečítanie hodnoty premennej

Optimazizácia kúzelného kompilátora by 2. zredukovala na 3., ale ja by som jednoducho aj bez empirického testovania a bez ohľadu na jazyk vsadil na 3.

[msk]

Je to tak, blbo som sa vyjadril. Ten logger samozrejme neloguje ( je nastaveny vyzsi level ), slo mi o to zistit, aky je rozdiel vo volani loggera roznymi sposobmi ( a aky to ma dopad na vykon v pripade, ked nelogujem ).