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.