Fortschritt in Logausgaben

Bei langlaufenden iterativen Prozessen ist es häufig nützlich den aktuellen Fortschritt ablesen zu können. Die Angaben innerhalb eines Inkrements in jeweils einer neuen Zeile auszugeben ist zwar ein denkbarer Ansatz, führt aber dazu, dass der Log schnell überflutet wird. Dadurch können andere wichtige Ausgaben verdrängt werden. Was man stattdessen bräuchte, ist eine einzige Zeile, die sich fortlaufend aktualisiert und somit immer den aktuellen Fortschritt der Verarbeitung anzeigt. In diesem Artikel zeige ich, wie eine solche Ausgabe unter Verwendung der Slf4J-API umgesetzt werden kann.

Der Beispielcode für diesen Artikel befindet sich auf GitHub.

Idee

Die Idee ist simple: Einen Marker definieren, der in den Log-Anweisungen des Fortschritts verwendet werden soll; für diesen Marker einen Appender in der logback-spring.xml deklarieren und ihm ein benutzerdefiniertes Pattern zuweisen, das am Ende anstatt des Steuerzeichens \n für einen Zeilenumbruch, das Zeichen \r für den Wagenrücklauf (engl. Carriage Return - CR) enthält. Die Schreibmarke würde damit nach jeder Ausgabe wieder an den Zeilenanfang springen und den bisherigen Inhalt mit der nächsten Ausgabe überschreiben.

Eine Ausgabe, die wir uns dadurch erhoffen, soll in etwa die folgende Struktur aufweisen:

...
2020-08-27 06:57:12,914 INFO - start process ...
                5161 ms INFO - PROGRESS: 45 / 100 items processed ...
...

...
2020-08-27 06:57:12,914 INFO - start process ...
2020-08-27 06:57:23,232 INFO - process finished: 100 items processed
...

Eine Ausgabe am Beginn der Verarbeitung, eine sich fortlaufend aktualisierende Zeile mit dem Fortschritt und eine am Ende, wenn die Verarbeitung abgeschlossen ist.

Appender konfigurieren

Die Definition des Appenders in der logback-spring.xml könnte, wie folgt aussehen (Die Package-Namen in den class Attributen wurden der Lesbarkeit halber gekürzt):

<!-- /resources/logback-spring.xml (Auszug) -->
<appender name="progressAppender" class="...ConsoleAppender">
    <filter class="...EvaluatorFilter">
        <evaluator class="...OnMarkerEvaluator">
            <marker>PROGRESS</marker>
        </evaluator>
        <onMismatch>DENY</onMismatch>
        <onMatch>ACCEPT</onMatch>
    </filter>
    <encoder class="...PatternLayoutEncoder">
        <pattern>
            %20r ms %highlight(%level) - %marker: %green(%msg)\r
        </pattern>
    </encoder>
</appender>

Der im Appender angegebene Filter fängt alle Logausgaben ein, die mit dem Marker PROGRESS gekennzeichnet werden: Z.B.: LOG.info(progressMarker, „My message...“). Diese Ausgaben werden durch ein Layout-Pattern formatiert, das im Gegensatz zum Default kein \n am Ende aufweist. Stattdessen wird das Steuerzeichen \r verwendet, um die Schreibmarke an den Zeilenanfang springen zu lassen.

Das Layout-Pattern ist im encoder-Tag angegeben. Die im Layout-Pattern verwendeten Schlüsselwörter haben die folgende Bedeutung:

• %20 - ein Formatmodifikator, mit dem die Breite des Feldes und der rechte Blocksatz angegeben werden: So lässt sich die Dauer des Fortschritts rechtsbündig mit der Angabe der Uhrzeit im restlichen Log anordnen
• r - gibt die verstrichene Zeit in Milisekunden aus
• %green(...) - stellt den als Parameter angegebenen Inhalt in Grün dar
• %highlight(...) - hebt den als Parameter angegeben Inhalt hervor
• %marker - Schlüsselwort für die Ausgabe des verwendeten Markers
• %msg - Die eigentliche Nachricht der Loganweisung

Die vollständige Definition der logback-spring.xml kann hier eingesehen werden.

Verwendung im Code

Um das Beispiel möglichst kurz zu halten, werden wir uns hier einer einfachen Schleife bedienen:

LOG.info("start process ...");

Marker progress = MarkerFactory.getMarker("PROGRESS");
for (int i=0; i<=100; i++) {
    LOG.info(progress, "items processed - {} / {}", i, 100);
    Thread.sleep(100);
}

LOG.info("process finished.");

Als erstes brauchen wir einen Marker, um unsere Loganweisungen mit dem konfigurierten Appender zu verknüpfen. Wir lassen uns von der MarkerFactory einen Marker mit dem Bezecihner PROGRESS erzeugen, der in der Logger-Konfiguration festgelegt wurde.

Jede Iteration soll stellvertretend für einen Schritt innerhalb eines langlebigen Prozesses stehen: Um die Verarbeitungsdauer eines Schritts zu simulieren, lassen wir den aktuellen Prozess mit Thread.sleep(100) für einen Augenblick anhalten. Anschließend loggen wir den aktuellen Fortschritt, in dem wir den Marker progress an die Log-Anweisung übergeben:

LOG.info(progress,"items processed - {} / {}",i,100);

Fazit

Die vorgestellte Lösung hat noch ein dickes "aber": Sie funktioniert nur dann, wenn die Fortschrittsinformation die einzige Logsausgabe innerhalb des Teilschritts darstellt, die auf System.out schreibt. Weiteres Logging würde die Zeile des Fortschritts überschreiben und am Ende einen Umbruch (\n) einfügen - die ganze Mühe wäre umsonst gewesen. Es wäre jedoch bedenklich, weitere Ausgaben in das gleiche target zu schreiben, weil auch diese bei länger laufenden Prozessen den Log vollschreiben und andere Ausgaben verdrängen würden. Vielmehr könnte es Sinn ergeben, einen FileAppender zu definieren und die relevante Informationen oder Warnungen in eine Datei auszugeben.