Сложные системы логируют большой объём информации. Хорошо продуманные и детализированные записи могут помочь в поиске и устранении серьёзных проблем. У большинства систем нет ограничений, какое логирование использовать ― синхронное или асинхронное. И всё же многие высокопроизводительные системы обычно предпочитают использовать асинхронное логирование без мусора (garbage-free), чтобы избежать задержек при сборке мусора (GC events) и операциях ввода-вывода (IO operations). В этой статье мы заглянем под капот библиотек логирования Java Log4j и Gflog и посмотрим, чем они отличаются с точки зрения управления памятью. Мы узнаем, как они реализованы, чтобы максимально сократить создание короткоживущих объектов.
Введение
Библиотеки асинхронного логирования обычно используют очередь для передачи записей из потоков приложения в фоновый поток. Фоновый поток форматирует записи в указанном формате и пишет или отправляет их в настроенное хранилище или сервис. Обычно логи пишут в файл или отправляют через TCP или UDP соединение в нижестоящий сервис (ELK Stack, Graylog, Splunk, и т. д.).
Длина логируемых сообщений зависит от приложения и может составлять десятки или тысячи символов. Garbage-free логгеры повторно используют одни и те же объекты и структуры, чтобы не создавать короткоживущие объекты на каждую операцию логирования. Длинные записи могут раздувать объекты и структуры и влиять на производительность, особенно на размер занимаемой памяти. Например, запись большой структуры данных в текстовом виде может быть длинной, а некоторые могут состоять всего из нескольких слов. Компромисс между занимаемой и действительно используемой памятью ― это одна из основных проблем при разработке garbage-free логгера. Кроме того, чрезмерное использование пулов объектов отрицательно сказывается на эффективности сборки мусора. Это может проявляться по-разному в зависимости от реализации сборщика и типа цикла сборки мусора. Как правило, увеличивается время выполнения блокирующих (stop-the-world) циклов сборки мусора, а также использование процессора при параллельных (concurrent) циклах.
Давайте пройдёмся по библиотекам Log4j 2.14.0 и Gflog 3.0.1 и посмотрим, чем они отличаются.
Log4j
Log4j ― хорошо известная библиотека логирования. Она поддерживает множество функций, включая garbage-free режим, который нас интересует. Вся магия происходит внутри одного вызова.
Log4j API
log.info("Hello there: {}", message);Log4j использует Disruptor для передачи записей журнала в фоновый поток. Disruptor основан на объектно-ориентированном кольцевом буфере фиксированной длины и поддерживает топологию потребителей. В Log4j кольцевой буфер содержит многократно используемые объекты событий журнала (log events), а потребителем является фоновый поток, который их обрабатывает.
Log4j Structure
Log4j создаёт Disruptor на 256К слотов, исходя из конфигурации, которую использует команда Log4j при тестировании производительности. Каждый слот представляет повторно используемое событие журнала и содержит имя логгера, имя потока, уровень логирования, сообщение и другую информацию. Объект messageText хранит отформатированное сообщение. Он выделяется лениво при первом использовании слота с начальной длиной 128, которая устанавливается системным свойством log4j.initialReusableMsgSize.
Когда вы логируете сообщение, Log4j берёт thread-local транслятор, заполняет параметры записи журнала и вызывает метод Disruptor#publish. Там он запрашивает слот, копирует все ссылки в него и форматирует сообщение в StringBuilder messageText объект слота. После чего Log4j публикует слот и он может быть обработан фоновым потоком.
Таким образом, одно повторяющееся длинное сообщение может раздуть StringBuilder объект во всех слотах, что приведёт к огромной трате памяти. К счастью, Log4j имеет системное свойство log4j.maxReusableMsgSize, которое по умолчанию равно 518. Фоновый поток подрезает StringBuilder объекты, если они длиннее 518, до этой же самой длины. Таким образом, в худшем случае все они могут быть длиной 518, а более длинные сообщения будут приводить к созданию короткоживущих объектов размером более 518 байт.
Gflog
Gflog ― это Java библиотека для асинхронного логирования без мусора. Изначально Gflog был ответвлением библиотеки Gflogger Владимира Долженко. Но дальнейшие улучшения и новый API сделали его отдельным проектом. Gflog API похож на Gflogger API, но реализация отличается.
Gflog Template API
log.info("Hello there: %s").with(message);Gflog использует байтовый off-heap кольцевой буфер (адаптация ManyToOneRingBuffer от Agrona) для передачи записей журнала в фоновый поток. Буфер позволяет записывать байтовые сообщения переменной длины, добавляя небольшие накладные расходы 0-7 байтов на выравнивание записей. К сожалению, вы не можете передавать ссылки. Но в этом нет ничего страшного. Gflog не поддерживает логирования местоположения, откуда вызывается логирующий код, поэтому единственное, что требует исключительного пути ― это исключения. Вся необходимая информация, такая как имя логгера, имя потока, отметка времени, может быть эффективно сериализована.
Gflog Structure
Давайте посмотрим на жизненный цикл и структуру записи журнала, которая используется потоком приложения.
При первой операции логирования поток создает thread-local запись журнала. Имя потока фиксируется и сохраняется в красной области и не обновляется в будущем. Один и тот же объект записи журнала повторно используется в последующих операция логирования в этом потоке.
При каждой операции логирования поток обновляет синюю и зелёную области. Синяя область имеет фиксированную структуру. Все поля являются примитивами и могут обновляться в любом порядке, поскольку они имеют постоянную длину и смещение. Обратите внимание, что имя логгера хранится в индексе, поэтому необходимо передать только 4-байтовое значение индекса и использовать его для получения строки в фоновом потоке. Зелёная зона имеет переменную длину. Поток заполняет её в режиме добавления (append) при построении сообщения.
Когда запись готова поток резервирует место в кольцевом буфере, копирует содержимое и делает запись доступной для обработки в фоновом потоком. Thread-local запись журнала инициализируется размером 4 КБ и может увеличиваться до 64 КБ, в зависимости от конфигурации. Если сообщение больше и не влазит, оно обрезается. Gflog не уменьшает размер записи журнала. Таким образом, в худшем случае у вас может быть 64 КБ на поток приложения, если вы логировали хотя бы одно длинное сообщение в каждом из них. Мусор создается только при расширении записи журнала.
Запись с исключением проходит немного по другому пути. Исключение передается по ссылке через индекс. Фоновый поток использует свой объект записи журнала для восстановления содержимого с подробностями об исключении ― сообщение и стек. Таким образом, исключения раздувают только запись фонового потока.
Время эксперимента
Теперь давайте проведём эксперимент и сравним объём памяти, который используют эти библиотеки.
Мы будем использовать библиотеку JOL (Java Object Layout) для оценки объёма памяти. Обойдём граф живых объектов начиная с объекта логгер после логирования 1/1M/10M/100M сообщений со следующим случайным распределением:
50% ― сообщение длиной от 0 до 100
20% ― сообщение длиной от 0 до 200
10% ― сообщение длиной от 0 до 300
10% ― сообщение длиной от 0 до 400
9% ― сообщение длиной от 0 до 500
1% ― сообщение длиной от 0 до 1000
Мы будем использовать Java 11/8 со следующими параметрами JVM:
-Xms1g ― начальный размер кучи
-Xmx1g ― максимальный размер кучи
Посмотреть код можно здесь:
Обратите внимание, что JOL не учитывает off-heap память, поэтому нужно добавить к результату Gflog размер, который занимает кольцевой off-heap буфер.
Давайте залогируем одно сообщение в Gflog.
Gflog Top 5 (Java 11, 1 message)
Instances | Average (bytes) | Footprint (bytes) | Type |
|---|---|---|---|
3512 | 200 | 702416 | byte[] |
2443 | 36 | 88256 | java.lang.Object[] |
3390 | 24 | 81360 | java.lang.String |
2338 | 32 | 74816 | java.lang.invoke.LambdaForm$Name |
148 | 504 | 74624 | int[] |
24960 | - | 1654232 | (total) |
Мы видим только 1.58 Мб. Добавим 8 МБ, которые занимает кольцевой буфер, и 2 МБ с запасом. Итак, результат будет 11.58 МБ. Самая тяжелая структура ― это буфер.
Теперь залогируем одно сообщение в Log4j.
Log4j Top 7 (Java 11, 1 message)
Instances | Average (bytes) | Footprint (bytes) | Type |
|---|---|---|---|
262144 | 104 | 27262976 | ...log4j.core.async.RingBufferLogEvent |
262143 | 32 | 8388576 | ...log4j.util.SortedArrayStringMap |
262144 | 24 | 6291456 | ...log4j.core.time.MutableInstant |
437 | 2583 | 1128808 | int[] |
601 | 1812 | 1089336 | java.lang.Object[] |
5486 | 148 | 816392 | byte[] |
5331 | 24 | 127944 | java.lang.String |
815846 | - | 45866000 | (total) |
Мы видим, что 43.75 МБ выделено только для повторно используемых объектов. Обратите внимание, что объекты StringBuilder для сообщений ещё не созданы, кроме одного.
Хорошо, залогируем миллион сообщений в Gflog.
Gflog Top 5 (Java 11, 1M messages)
Instances | Average (bytes) | Footprint (bytes) | Type |
|---|---|---|---|
3738 | 190 | 710792 | byte[] |
1235 | 72 | 88920 | java.lang.reflect.Field |
2443 | 36 | 88256 | java.lang.Object[] |
3602 | 24 | 86448 | java.lang.String |
632 | 120 | 75840 | java.lang.Class |
25984 | - | 1702872 | (total) |
Мы видим, что объём памяти практически не изменился. Thread-local запись main потока не расширяется, потому что сообщения слишком короткие для Gflog.
А теперь ― миллион сообщений в Log4j.
Log4j Top 7 (Java 11, 1M messages)
Instances | Average (bytes) | Footprint (bytes) | Type |
|---|---|---|---|
268263 | 283 | 76023096 | byte[] |
262144 | 104 | 27262976 | ...log4j.core.async.RingBufferLogEvent |
262745 | 60 | 15769368 | java.lang.Object[] |
262144 | 24 | 6291456 | java.lang.StringBuilder |
262144 | 24 | 6291456 | ...log4j.core.time.MutableInstant |
452 | 2497 | 1129048 | int[] |
5958 | 24 | 142992 | java.lang.String |
1342827 | - | 133755584 | (total) |
Теперь он занимает 127.56 МБ, и мы видим 256К объектов StringBuilder. Средний размер составляет около 283 байт, что означает, что некоторые объекты всё ещё могут расширяться.
Продолжим логировать до 10/100 миллионов сообщений.
Мы видим, что объём памяти, который занимает Gflog, устойчив и не изменяется. С другой стороны, Log4j занимает всё больше и больше места, потому что объекты StringBuilder расширяются. В конце концов, все они достигнут предела.
Давайте попробуем Java 8. Может что-то изменится.
Действительно, Log4j занимает в Java 8 почти в 1,7 раза больше места. Почему в Java 11 объём памяти меньше? Благодаря Compact Strings фиче, появившейся в Java 9. Объекты StringBuilder занимают почти в 2 раза меньше места, если вы логируете только Latin-1 сообщения. Но они всё равно могут быть раздуты, если иногда вы логируете не Latin-1 сообщения, и останутся такими.
Хорошо, а как насчёт количества живых объектов? После одного миллиона сообщений:
Log4j – 1343 K
Gflog – 26 K
В Log4j много живых объектов. Но как это влияет на сборку мусора? Давайте использовать метод System :: gc для имитации событий полной сборки мусора. Мы вызовем 5 сборок, а затем ещё 10 в каждой из точек:
Clean ― перед инициализацией логгера.
Initialized ― после инициализации логгера, но до логирования сообщений.
Measured ― после логирования 100 миллионов сообщений, но до остановки логгера.
Destroyed ― после остановки логгера.
Первых 5 сборок удаляют мусор между точками. Последних 10 сборок показывают накладные расходы из-за повторно используемых живых объектов при полной сборке мусора.
G1 GC ― это сборщик мусора по умолчанию в Java 11.
Parallel GC ― это сборщик мусора по умолчанию в Java 8.
Мы видим, что чрезмерный пулинг долго живущих объектов, а также создание коротко живущих объектов (мусора) снижает производительность сборки мусора. Это звучит как парадокс, но всё же, мы можем минимизировать и то, и другое. Таким образом, чем меньше у нас любых объектов, тем меньше работы нужно выполнять сборщику мусора.
Заключение
В контексте асинхронной обработки без мусора вы обычно передаете данные по значению ― вы копируете данные в очередь или буфер, а затем делаете их доступными для использования. Здесь вы можете выбрать объектно-ориентированную очередь или байтовую очередь. Первый вариант позволяет передавать ссылки на объекты, но может тратить много памяти, особенно когда данные являются полиморфными или переменной длины. Второй не позволяет передавать ссылки на объекты напрямую, но обеспечивает эффективное управление памятью.
Как видите, байтовая очередь уменьшает объём памяти на порядок, а также количество живых объектов, которыми JVM должна управлять.
В следующей статье мы узнаем, как байтовая очередь может повысить производительность.