Dzisiaj aktualizowałem wewnętrzną prezentacje dotyczącą logowania zdarzeń w aplikacjach JEE (prezentowałem ją na 2011 na konferencji 4Developers) o prosty i przydatny wzorzec projektowy.

Często zdarza się że w aplikacji są wykonywane zadania, które zabierają trochę więcej czasu, niż standardowe wygenerowanie strony WWW, załóżmy że ponad 10 sekund. Często są to zadania cykliczne, które np. muszą wykonać jakieś przeliczenia na 10.000 rekordów. Jeżeli programista nie doda poprawnego logowania postępu takiego procesu, to obserwując logi możemy nie wiedzieć czy proces w ogóle wystartował, czy trwa, czy się już zakończył.

Poniższy wzorzec zakłada wypisywanie komunikatów diagnostycznych przy rozpoczęciu procesu, co każde 1000 rekordów i podsumowania na koniec. Dzięki temu obserwacja takiego logu jest pasjonująca niczym film kryminalny:

private void start() {
    log.info("Begin");
    Timer t = new Timer();

    int rows = 1000;
    for(int i = 0; i < rows; i++) {
        doSomething();
        if(i % 100 == 0) {
            log.debug("Processing row {}/{}", i, rows);
        }
    }
    
    t.stop();
    long average = t.elapsed() / rows;
    log.info("Finished, processed {} rows, duration {}, " + 
            "average {} [ms] per row", rows, t.prettyElapsed(), 
            average);
}

Efekt wykonania takiego kodu będzie wyglądać tak:

11:27:44.342 [main] INFO  - Begin
11:27:44.357 [main] DEBUG - Processing row 0/1000
11:27:46.628 [main] DEBUG - Processing row 100/1000
11:27:48.912 [main] DEBUG - Processing row 200/1000
11:27:51.525 [main] DEBUG - Processing row 300/1000
11:27:53.935 [main] DEBUG - Processing row 400/1000
11:27:56.359 [main] DEBUG - Processing row 500/1000
11:27:58.962 [main] DEBUG - Processing row 600/1000
11:28:01.497 [main] DEBUG - Processing row 700/1000
11:28:03.956 [main] DEBUG - Processing row 800/1000
11:28:06.385 [main] DEBUG - Processing row 900/1000
11:28:08.609 [main] INFO  - Finished, processed 1000 rows, 
duration 00:24:259, average 24 [ms] per row

Polecam stosowanie 🙂