В этой статье рассматриваются основы асинхронного ведения журналов с использованием log4j2. Давайте рассмотрим, что это такое, зачем это нужно и как это можно реализовать.
Давайте начнем с понимания того, что такое асинхронное ведение журнала.
Представим себе — есть основной поток программы, в нем совершается полезная работа.
Время от времени программа протоколирует свою работу.
Если запись в лог происходит в основном потоке программы, прерывая полезную работу, то это означает синхронный Ведение журнала.
Если лог пишется в другом потоке и не прерывает полезную работу, то это логирование асинхронный .
В этом случае мы будем предполагать, что вычислительных ресурсов достаточно как для потока протоколирования, так и для основного потока.
Зачем кому-то асинхронное ведение журнала? Ну а если на минутку будет прервана полезная работа, кому будет от этого плохо? Понятно, что есть тип особо требовательных приложений, супероптимизированных под максимальную производительность, где каждая микросекунда на счету, с ними все понятно.
Однако в современном мире микросервисов в облаках асинхронное журналирование может быть полезно и в приложениях «общего назначения» без особых требований к скорости.
Например, такое приложение записывает логи на удаленный сервер в GrayLog. Сетевое соединение может прерваться, и если логирование будет синхронным, это неприятно отразится на приложении.
Чтобы обезопасить себя от такой напасти, можно писать логи асинхронно.
Давайте смоделируем пример.
Чтобы имитировать «сломанный сетевой регистратор», мы создадим собственный аппендер.
Самодельный аппендер напишет в system.out, но с задержкой в несколько секунд, как будто были проблемы с сетью.
Вот как может выглядеть Apender. Это очень простое приложение, которое выполняет абсолютный минимум работы:
Давайте создадим минимальную конфигурацию log4j и подключим наше приложение.@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(); } } }
(Конфигурация показана с сокращениями) <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(); } } .
}
}
Чтобы было удобнее понимать время, необходимое для эмуляции полезной работы, мы будем использовать обычный консольный логгер, а loggerExperimental будет нашим ломаным логгером.
Давайте запустим его и посмотрим на эту картинку:
23:03:47.837 [main] INFO ru.logs.LoggerTest — действие до:0 23:03:50.840: Тема:[main]: вход в систему медленный:0 23:03:50.841 [main] INFO ru.logs.LoggerTest — действие после:0Вы можете видеть, как сломанный логгер перестал работать на 3 секунды.
Обратите внимание, что для наглядности сломанный логгер отображает имя потока, в котором он запущен, т.е.
это main — основной поток приложения.
Давайте изменим это и выведем журнал в другой поток.
Для этого вам необходимо настроить аппендер как асинхронный.
Вариантов конфигурации может быть много, это один из возможных.
Настройка осуществляется путем добавления в конфигурацию следующего раздела: <Async name="Async-SlowAppender" blocking="false" bufferSize="10" errorRef="Console">
<AppenderRef ref="SlowAppender"/>
<DisruptorBlockingQueue/>
</Async>
Здесь мы говорим, что SlowAppender теперь будет асинхронным.
Это означает, что основной поток поместит сообщение в очередь.
А другой выделенный поток логирования будет обращаться к этой очереди и передавать сообщение аппендиперу, т.е.
в нашем эмуляторе оно просто выведет на консоль.
Если очередь есть, то нужно задать ее максимальный размер; это делается с помощью параметра bufferSize. В моем примере — 10, чтобы было проще показать эффект заполнения очереди.
Что делать, если очередь переполнена? За это отвечает параметр блокировки.
В данном примере блокировка="false" означает, что в логгере будет отображено сообщение об ошибке errorRef="Console" и сообщение, которое необходимо зарегистрировать.
Основной поток продолжит работу.
Те.
Получается, что если очередь заполнена, то сообщение будет выводиться не в «сломанный логгер», а в errorRef. В отладке это выглядит так:
23:23:34.865 [main] INFO ru.logs.LoggerTest — действие до:29 2020-06-06 23:23:34,865 основная ОШИБКА Appender Async-SlowAppender не может записывать основные приложения.Обратите внимание, что очередь заполнена, и следующее сообщение находится не в сломанном логгере, а в errorRef. Если locking="true", то основной поток будет заблокирован до тех пор, пока в очереди сломанного логгера не останется места, т.е.очередь заполнена 23:23:34.865 [main] INFO ru.logs.LoggerTest.slowAsync — медленный вход: 29 23:23:34.866 [main] INFO ru.logs.LoggerTest — действие после:29 23:23:35.856: Тема: [AsyncAppender-Async-SlowAppender]: медленный вход в систему: 9 23:23:35.866 [main] INFO ru.logs.LoggerTest — действие до:30
если очередь заполнена, логирование станет синхронным, но все сообщения попадут в логгер, как и должны ( то есть сломанный).
Что выбрать, блокировку = «истина» или блокировку = «ложь»? Это зависит от характера приложения и того, какие логи вы пишете.
Обратите внимание, что при блокировке="true" очередь может "подстраховать" приложение при кратковременных отключениях сети, т.е.
этот вариант тоже стоит рассмотреть.
Теперь давайте более подробно рассмотрим эту очередь.
Конечно, это очень важная часть системы.
Есть пара вариантов очереди, я использовал самый быстрый вариант — Disruptor. Чтобы использовать его, вам необходимо включить пару дополнительных зависимостей.
Так каков конечный результат? Получается вот так:
23:23:05.848 [main] INFO ru.logs.LoggerTest — действие до:0 23:23:05.851 [main] INFO ru.logs.LoggerTest — действие после:0 23:23:06.851 [main] INFO ru.logs.LoggerTest — действие до:1 23:23:06.851 [main] INFO ru.logs.LoggerTest — действие после:1 23:23:07.851 [main] INFO ru.logs.LoggerTest — действие до:2 23:23:07.851 [main] INFO ru.logs.LoggerTest — действие после:2 23:23:08.852 [основная] ИНФО ru.logs.LoggerTest — действие до:3 23:23:08.852 [main] ИНФО ru.logs.LoggerTest — действие после:3 23:23:08.854: Тема: [AsyncAppender-Async-SlowAppender]: медленный вход в систему: 0Те.
приложение работает, и на него не влияет сломанный регистратор.
Понятно, что после заполнения очереди начнутся неприятности — либо приложение начнет тормозить, либо сообщения будут теряться (в зависимости от параметра блокировки).
Но это все же лучше, чем просто синхронное ведение журнала.
Внимательный читатель, вероятно, предложит полностью перейти на синхронные логгеры.
Почему нет? У асинхронных логгеров есть проблема — они сильно нагружают процессор.
Например, в моем случае с асинхронным логгером загрузка процессора составляет ~100% (по данным топовой утилиты), а в синхронном варианте около 10-20%.
Если асинхронных логгеров будет больше, то нагрузка на процессор значительно увеличится.
Вопрос - почему это так? Захожу с длинными паузами, сон измеряется секундами, на что идет процессор? Интересный? 11 июня в 20:00 состоится открытый вебинар , в конце вебинара можно будет обсудить этот вопрос.
УПД: часть вебинара о логировании с рассказом о загрузке процессора .
Исходный код примера можно посмотреть здесь .
Теги: #java #ведение журнала #многопоточность #многопоточность #log4j2
-
У Меня Есть Мнение
19 Oct, 24
