Асинхронное логирование с log4j для любознательных

В статье рассматриваются основы асинхронного логирования с помощью log4j2.
Рассмотрим что это, для чего нужно и как можно реализовать.



Давайте начнем с того, что разберемся, что такое асинхронное логировагие.
Представим – есть основной поток программы, в нем делается полезная работа. Время от времени программа логирует свою работу. Если запись в лог делается в основном потоке программы, прерывая полезную работу, значит это синхронное логирование. Если лог пишется в другом потоке и полезную работу не прерывает, значит это логирование асинхронное. При этом будем считать, что вычислительных ресурсов достаточно и для потока логирования и для основного потока.

Зачем кому-то может понадобиться асинхронное логирование? Ну, прервется выполнение полезной работы на мгновение, кому от этого будет плохо? Понятно, что есть вид особо требовательных приложений, супер оптимизированных на максимальную производительность, там каждая микросекунда на счету, с ними все понятно. Однако в современном мире микросервисов в облаках асинхронное логирование может быть полезно и в приложениях «общего назначения» без особых требований к скорости работы. Например, такое приложение пишет логи на удаленный сервер в GrayLog. Сетевое соединение может прерваться, и если логирование синхронное, это неприятно повлияет на работу приложения. Чтобы защититься от такой напасти можно писать логи асинхронно.

Давайте смоделируем пример.
Для имитации «сломанного сетевого логера» сделаем свой appender. Самодельный appender будет писать в system.out, но с задержкой в несколько секунд, как будто бы это проблемы с сетью.

Вот как может выглядеть Apender. Это максимально-максимально простой appender, делает абсолютный минимум работы:

@Plugin(name = "SlowAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class SlowAppender extends AbstractAppender {
    private static final DateTimeFormatter FORMATTER = DateTimeFormatter.ofPattern("HH:mm:ss.SSS");

    protected SlowAppender(String name, Filter filter) {
        super(name, filter, null, true, Property.EMPTY_ARRAY);
    }

    @PluginFactory
    public static SlowAppender createAppender(
            @PluginAttribute("name") String name,
            @PluginElement("Filter") Filter filter) {
        return new SlowAppender(name, filter);
    }

    @Override
    public void append(LogEvent event) {
        sleep();
        System.out.println(LocalDateTime.now().format(FORMATTER) + " : Thread:[" + Thread.currentThread().getName()
                + "] : " + event.getMessage().getFormattedMessage());
    }

    private void sleep() {
        try {
            Thread.sleep(TimeUnit.SECONDS.toMillis(3));
        } catch (InterruptedException e) {
            Thread.currentThread().interrupt();
        }
    }
}

Создадим минимальную конфигурацию log4j и подключим наш appender
(Конфигурация приведена с сокращениями)

<Configuration packages="ru.logs.appender">
    <Appenders>
...
        <SlowAppender name="SlowAppender"/>
...
    </Appenders>
    <Loggers>
...
        <Logger name="ru.logs.LoggerTest.slow" level="info" additivity="false">
            <AppenderRef ref="SlowAppender"/>
        </Logger>
...
    </Loggers>
</Configuration>

А теперь применим:

public class LoggerTest {
    private static final Logger logger = LogManager.getLogger(LoggerTest.class);
    private static final Logger loggerSlow = LogManager.getLogger(LoggerTest.class.getName() + ".slow");
   ...
    public static void main(String[] args) {
        someActionWithLog(loggerSlow);
    }

    private static void someActionWithLog(Logger loggerExperimental) {
        for (int idx = 0; idx < 1_000; idx++) {
            logger.info("action before:{}", idx);
            loggerExperimental.info("logging in slow:{}", idx);
            logger.info("action after:{}", idx);

            sleep();
        }
    }
...
    }
}

Чтобы было удобнее понимать временные затраты для эмуляции полезной работы, будем использовать обычный консольный логгер (logger), а loggerExperimental – наш сломанный логгер.
Запустим и видим такую картину:

23:03:47.837 [main] INFO ru.logs.LoggerTest — action before:0
23:03:50.840: Thread:[main]: logging in slow:0
23:03:50.841 [main] INFO ru.logs.LoggerTest — action after:0

Видно, как сломанный логгер остановил работу на 3 сек. Обратите внимание, для наглядности сломанный логгер выводит имя потока, в котором запущен, т.е. это main – основной поток приложения. Давайте это изменим и выведем логирование в другой поток. Для этого надо сконфигурировать appender как асинхронный. Вариантов конфигурации может быть много, это один из возможных.
Конфигурирование делается добавлением такого раздела в конфиг:

  <Async name="Async-SlowAppender" blocking="false" bufferSize="10" errorRef="Console">
     <AppenderRef ref="SlowAppender"/>
     <DisruptorBlockingQueue/>
  </Async>

Тут мы говорим, что теперь SlowAppender будет асинхронным. Это значит, что основной поток (main) положит сообщение в очередь. А другой выделенный поток логирования обратится к этой очереди и передаст сообщение в appender, т.е. в нашем эмуляторе просто выведет в консоль.

Если есть очередь – значит надо задать ее предельный размер, это делается с помощью параметра bufferSize. В примере у меня это 10, чтобы проще показать эффект заполнения очереди.

А что делать, если очередь заполнена? За это отвечает параметр blocking. В этом примере blocking=«false», это значит, что в логгер errorRef=«Console» будет выведено сообщение об ошибке, и сообщение, которое надо залогировать. При этом основной поток продолжит работать. Т.е. получается, что в случае заполнения очереди сообщение выведется не в «сломанный логгер», а в errorRef.

В отладке это выглядит так:

23:23:34.865 [main] INFO ru.logs.LoggerTest — action before:29
2020-06-06 23:23:34,865 main ERROR Appender Async-SlowAppender is unable to write primary appenders. queue is full
23:23:34.865 [main] INFO ru.logs.LoggerTest.slowAsync — logging in slow: 29
23:23:34.866 [main] INFO ru.logs.LoggerTest — action after:29
23:23:35.856: Thread:[AsyncAppender-Async-SlowAppender]: logging in slow: 9
23:23:35.866 [main] INFO ru.logs.LoggerTest — action before:30

Обратите внимание на сообщение о заполнении очереди, и что следующее сообщение попало не в сломанный логгер, а в errorRef.

Если blocking=«true», то основной поток заблокируется, пока в очереди сломанного логера ни появится место, т.е. в случае заполнения очереди логирование станет синхронным, но все сообщения попадут в тот логгер, в который должны (т.е. в сломанный).
Что выбрать, blocking=«true» или blocking=«false»? Это зависит от характера приложения, и того какие логи вы пишите. Обратите внимание, что при blocking=«true» очередь может «подстраховать» приложение при непродолжительных обрывах сети, т.е. эта опция тоже достойна рассмотрения.

Теперь давайте внимательнее посмотрим на эту очередь. Очевидно, что это очень важная часть системы. Есть пара вариантов очередей, я применил самый скоростной вариант – Disruptor. Чтобы его использовать, надо подключить пару дополнительных зависимостей.

И так, что в итоге получается?

Получается так:

23:23:05.848 [main] INFO ru.logs.LoggerTest — action before:0
23:23:05.851 [main] INFO ru.logs.LoggerTest — action after:0
23:23:06.851 [main] INFO ru.logs.LoggerTest — action before:1
23:23:06.851 [main] INFO ru.logs.LoggerTest — action after:1
23:23:07.851 [main] INFO ru.logs.LoggerTest — action before:2
23:23:07.851 [main] INFO ru.logs.LoggerTest — action after:2
23:23:08.852 [main] INFO ru.logs.LoggerTest — action before:3
23:23:08.852 [main] INFO ru.logs.LoggerTest — action after:3
23:23:08.854: Thread:[AsyncAppender-Async-SlowAppender]: logging in slow: 0

Т.е. приложение работает и не ощущает влияния сломанного логгера. Понятно, что после заполнения очереди начнутся неприятности – или приложение начнет тормозить или сообщения теряться (зависит от параметра blocking). Но это все равно лучше, чем просто синхронное логирование.

Внимательный читатель наверняка предложит полностью перейти на синхронные логгеры. Почему бы и нет? У асинхронных логгеров есть неприятность – они сильно нагружают cpu. Например, в моем случае с асинхронным логгером загрузка cpu ~100% (по данным утилиты top), а в синхронном варианте порядка 10-20%. Если асинхронных логгеров будет больше, то и загрузка cpu значительно поднимется.

Вопрос — почему так? Я ведь логирую с большими паузами, sleep в секундах измеряется,
на что уходит cpu?

Интересно?

11 июня в 20:00 будет открытый вебинар, в конце вебинара можно будет обсудить этот вопрос.

UPD:
часть вебинара про логирование с рассказом про нагрузку на cpu.

Исходный код примера можно посмотреть тут.