Przejdź do głównej zawartości

Pułapki logowania w Javie

Czy spotkałeś kiedyś się z kodem takim jak poniższy?
if (logger.isDebugEnabled()) {
    logger.debug("Request: " + requestObject);
}

Ja tak. Jakiś czas temu napotkałem na mnóstwo takich fragmentów w kodzie, który analizowałem. Zastanowiło mnie po co została wykorzystana tutaj instrukcja warunkowa - a jako, że if-y uwazam za zło konieczne postanowiłem to zbadać. Czy nie do tego właśnie służą biblioteki do logowania i udostępniane przez nie metody jak debug żeby właśnie sterowane konfiguracją decydowały co zalogować a co nie? Co więcej, okazało się, że instrukcję warunkową wprowadził ktoś w ramach większej akcji. I jak się okazuje, prawdopodobnie znacznie zwiększył dzieki temu wydajność aplikacji.

W dzisiejszym wpisie postaram się wyjaśnić jak korzystać z loggera aby nie zaszkodziło to wydajności.

Po co if-y?

Na początek wyjaśnić trzeba czemu ten if tak na prawdę służy. Korzystamy z biblioteki do logowania i spodziewamy się, że wykorzystujac wybraną metodę, zostanie wykonana ona wyłącznie gdy wybrany poziom logowania jest aktualnie włączony. Czyli dla podanego na początku przykładu byłyby to poziomy DEBUG lub TRACE. I tak się dzieje. Można jednak zapomnieć o tym co dzieje się zanim zostanie wywołana metoda. A dzieje się coś co możemy nazwać ewaluacją parametrów. W javie operator + wymaga aby oba jego argumenty były tego samego typu. Jeśli zatem jeden jest literałem typu String to JVM podejmie próbę niejawnego rzutowania zmiennej, która jest drugim argumentem. Najczęściej będzie sie to sprowadzać do tego, że zostanie wywołana metoda toString za każdym razem - nawet jeśli dany poziom logowania jest nieaktywny. Jeśli obiekt jest stosunkowo duży, zawiera wiele pól, a metoda toString ma domyślną implementację to koszt jej wykonania może być już zauważalny. I to rozwiązaniem właśnie tego problemu jest wykorzystanie instrukcji warunkowej. Czy można zrobić to lepiej? Owszem.

Korzystajmy z API prawidłowo

Czy można się obyć bez instrukcji warunkowych, których nadmierne stosowanie psuje czytelność i estetykę kodu pisanego w sposób imperatywny (lista instrukcji do wykonania krok po kroku)? W wielu wypadkach można. Wystarczy zapoznać się z API biblioteki z której korzystamy. To jest akurat częsty błąd, który popełniamy - my programiści. Zdarza się nam korzystać z różnych bibliotek zgodnie z intuicją, na zasadzie prób i błędów, bez wcześniejszego zapoznania się z jej przeznaczeniem i interfejsem.

Wróćmy do loggera. Najpopularniejszym API do logowania w świecie javy jest Slf4j. Jest ono implementowane przez co najmniej kilka różnych bibliotek z logback-iem na czele. Oferuje ono możliwość późnej ewaluacji parametrów. Tym samym przedstawiony wcześniej fragment kodu możemy zamienić na:
logger.debug("Request: {}", requestObject);
Jak się okazuje efekt będzie ten sam. Metoda toString nie zostanie wywołana dopóki poziom logowania DEBUG nie będzie aktywny. Warto zauważyć, że nie zawsze można skorzystać z tego rozwiąnia. Chodzi tutaj m.in. o przypadki kiedy parametr wyliczany jest za pomocą metody wywoływanej jawnie. Wtedy prawdopodobnie ciężko będzie uniknąć sprawdzania poziomu logowania. Można również próbować korzystać z różnych rozszerzeń takich jak np. fluent API dostępne w slf4j od wersji 2.0.0, która nie jest jeszcze wersją stabilną (http://www.slf4j.org/manual.html#fluent) lub slf4j-fluent. Nie są to jednak rozwiązania uznawane obecnie za standard.

Na problemy z wczesną ewaluacją parametrów możemy spotkać również w innych wypadkach, niezwiązanych z logowaniem. Kto korzysta ze statycznej analizy kodu za pomocą narzędzi takich jak np Sonar to kojarzy pewnie rulkę o identyfikatorze squid:S2629. Ona często wskaże nam miejsce, które wymaga poprawy.

Test

W celu zobrazowania różnic w czasie wykonania kodu przygotowałem test obrazujący czas wykonania w przypadku prawidłowego wykorzystania api, wczesnej ewaluacji oraz logowania warunkowego. Poniżej kod:

pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
        xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>dev.maczkowski</groupId>
    <artifactId>log-level-checking</artifactId>
    <version>1.0-SNAPSHOT</version>

    <properties>
        <maven.compiler.source>11</maven.compiler.source>
        <maven.compiler.target>11</maven.compiler.target>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <version>1.18.16</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.30</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-simple</artifactId>
            <version>1.7.30</version>
        </dependency>
        <dependency>
            <groupId>org.fissore</groupId>
            <artifactId>slf4j-fluent</artifactId>
            <version>0.13.3</version>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
            <version>3.11</version>
        </dependency>
    </dependencies>
</project>
simplelogger.properties
org.slf4j.simpleLogger.showDateTime=true
org.slf4j.simpleLogger.dateTimeFormat=yyyy-MM-dd HH:mm:ss:SSS Z
org.slf4j.simpleLogger.defaultLogLevel=info
Main.java
import static org.fissore.slf4j.Util.lazy;

import java.time.Duration;
import java.time.LocalDateTime;
import java.util.List;
import java.util.Random;
import java.util.stream.Collectors;
import java.util.stream.Stream;

import org.apache.commons.lang3.time.DurationFormatUtils;
import org.fissore.slf4j.FluentLogger;
import org.fissore.slf4j.FluentLoggerFactory;

import lombok.AllArgsConstructor;
import lombok.Builder;
import lombok.Data;
import lombok.NoArgsConstructor;
import lombok.extern.slf4j.Slf4j;

@Slf4j
public class Main {

    private static final FluentLogger FLUENT_LOGGER = FluentLoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        List<ExampleData> randomData = Stream.generate(() -> ExampleData.builder()
                .a(new Random().nextDouble())
                .b(new Random().nextDouble())
                .c(new Random().nextDouble())
                .d(new Random().nextDouble())
                .e(new Random().nextDouble())
                .f(new Random().nextDouble())
                .g(new Random().nextDouble())
                .build())
                .limit(5000000)
                .collect(Collectors.toList());

        log.info("Warm up");
        randomData.forEach(data -> log.debug("Log entry: " + data));

        log.info("Start test (eager evaluation, without loglevel checking)");
        LocalDateTime start1 = LocalDateTime.now();
        randomData.forEach(data -> log.debug("Log entry: " + data));
        LocalDateTime stop1 = LocalDateTime.now();
        log.info("Stop test");


        log.info("Start test (eager evaluation, with loglevel checking)");
        LocalDateTime start2 = LocalDateTime.now();
        randomData.forEach(data -> {
            if (log.isDebugEnabled()) {
                log.debug("Log entry: " + data);
            }
        });
        LocalDateTime stop2 = LocalDateTime.now();
        log.info("Stop test");

        log.info("Start test (lazy evaluation)");
        LocalDateTime start3 = LocalDateTime.now();
        randomData.forEach(data -> log.debug("Log entry: {}", data));
        LocalDateTime stop3 = LocalDateTime.now();
        log.info("Stop test");


        FLUENT_LOGGER.info().log("Time1: {}", lazy(() -> formatDuration(start1, stop1)));
        FLUENT_LOGGER.info().log("Time2: {}", lazy(() -> formatDuration(start2, stop2)));
        FLUENT_LOGGER.info().log("Time3: {}", lazy(() -> formatDuration(start3, stop3)));
    }

    private static String formatDuration(LocalDateTime a, LocalDateTime b) {
        return DurationFormatUtils.formatDuration(Duration.between(a, b).toMillis(), "**H:mm:ss:SSS**", true);
    }
}

@Data
@Builder
@NoArgsConstructor
@AllArgsConstructor
class ExampleData {
    private Double a;
    private Double b;
    private Double c;
    private Double d;
    private Double e;
    private Double f;
    private Double g;
}
Dla leniwych rezultaty z wykonania powyższego kodu:
2021-05-19 20:00:04:864 +0200 [main] INFO Main - Warm up
2021-05-19 20:00:18:652 +0200 [main] INFO Main - Start test (eager evaluation, without loglevel checking)
2021-05-19 20:00:32:791 +0200 [main] INFO Main - Stop test
2021-05-19 20:00:32:791 +0200 [main] INFO Main - Start test (eager evaluation, with loglevel checking)
2021-05-19 20:00:32:885 +0200 [main] INFO Main - Stop test
2021-05-19 20:00:32:886 +0200 [main] INFO Main - Start test (lazy evaluation)
2021-05-19 20:00:33:003 +0200 [main] INFO Main - Stop test
2021-05-19 20:00:33:042 +0200 [main] INFO Main - Time1: **0:00:14:100**
2021-05-19 20:00:33:042 +0200 [main] INFO Main - Time2: **0:00:00:093**
2021-05-19 20:00:33:043 +0200 [main] INFO Main - Time3: **0:00:00:116**
Analizę rezultatu pozostawiam czytelnikowi. Dla jednego zysk może się wydawać niewielki, a dla kogoś innego znaczący.

Komentarze

  1. Fajny wpis, acz polecam przepisać benchmark na JMH. Logowanie przed i po foreachu może wpływać na wyniki.
    Foreach również jest nieco śliski.
    Warmup nie uwzględnia metody isDebugEnabled().

    Przeniesienie na JMH z pewnością rozwieje tutaj wątpliwości, a porównanie benchmarku manualnego z benchmarkiem frameworkowym może być też ciekawym doświadczeniem ;)

    OdpowiedzUsuń
  2. a czy to nie jest tak, że jak metoda będzie dostatecznie często wykorzystywana to zostanie przez JIT zoptymalizowana i wtedy właściwie już różnic w wykonaniu nie będzie?

    OdpowiedzUsuń
    Odpowiedzi
    1. Ciężko mi się wypowiadać na temat JIT-a bo po prostu nie wiem jak on dokładnie działa. Jednak nawet jeśli jest on w stanie zoptymalizować wykonanie metody to nadal trzeba ją wykonać. Przypuszczam, że różnie będzie to się zachowywać w zależności od implementacji danej metody - jeśli opiera ona swoje wyliczenia na wielu zmiennych parametrach to trudno mi sobie wyobrazić sensowna optymalizację.

      Usuń

Prześlij komentarz

Popularne posty z tego bloga

Spring Data - save vs saveAndFlush

Cześć, dzisiaj będzie znowu trochę o warstwie persystencji. Czasami kodzie aplikacji korzystającej ze Spring Data można napotkać użycia metody repozytorium save , a czasami saveAndFlush , a z kolei innym razem brak jakiejkolwiek z nich podczas zapisu obiektu. Wszystkie trzy metody mają swoje zastosowanie choć nieco się różnią. Teoria W teorii, różnica jest prosta. Metody save oraz saveAndFlush dodają obiekt do kontekstu persystencji danej sesji i zwracają obiekt zarządzany. Ponadto druga z nich wymusza wymusza wykonanie nagranych przez ORM akcji na bazie danych przez co dane zostają przesłane do silnika bazy. Może się to okazać przydatne w przypadku gdy w ramach jednej transakcji chcemy jeszcze wykonać kolejne zapytania, które mają być świadome wprowadzonych wcześniej zmian. Natychmiastowa synchronizacja może się również przydać gdy wykorzystujemy poziom izolacji READ_UNCOMMITTED . Czasami jednak w kodzie nie ma żadnej z nich. Wtedy możliwe jest wykonywanie tylko zapytań UPDATE

Sneaky throws, czyli checked i unchecked exception w jednym!

Często podczas pisania kodu Java korzystam z wyrażeń lambda wprowadzonych wraz z Java 8. Często prowadzi to też do pewnych nowych problemów i zmusza do szukania rozwiązań. Przyjrzyjmy się jednemu z nich. Checked exception w wyrażeniu lambda Często zdarza się, że metoda wywoływana wewnątrz lambdy rzuca wyjątek. Nie ma sprawy gdy wyjątek jest obiektem klasy będącej podklasą RuntimeException . Wtedy po prostu się nim nie przejmujemy. Wyjątek jest przekazywany w górę stosu wywołań. Problem zaczyna się gdy kompilator zmusza nas do obsługi wyjątku. Jak zwykle mamy 2 wyjścia: obsłużyć wyjątek za pomocą bloku try-catch , bądź zadeklarować przekazanie wyjątku dalej za pomocą słowa kluczowego throws . O ile wiemy co zrobić po złapaniu wyjątku to wszystko gra. Co natomiast gdy chcemy wybrać drugą opcję? Większość interfejsów stosowanych jako typy parametrów, często przekazywanych jako lambdy jak np: Function , Consumer czy Supplier nie deklarują, że mogą rzucić wyjątek. W takim wypadku druga