Logowanie postępu operacji długotrwających

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.

screenshot_blog

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 🙂

O autorze

Marek Berkan Marek Berkan: programista, entuzjasta tworzenia oprogramowania, zarządzania zespołami technicznymi. Prywatnie motocyklista, kolarz MTB, biegacz, żeglarz, rekreacyjny wspinacz, zamiłowany turysta. Witryny: , , .

Share Button

1 myśl w temacie “Logowanie postępu operacji długotrwających

Dodaj komentarz

Twój adres email nie zostanie opublikowany. Pola, których wypełnienie jest wymagane, są oznaczone symbolem *