Повышение производительности Mule 4 с помощью пакетного HTTP-аппендера для логов

После тысяч обращений в службу поддержки MuleSoft начинаешь замечать одни и те же повторяющиеся проблемы, и эта — одна из самых стойких. Представьте приложение Mule, которое месяцами работало безупречно: трафик растет, и оно начинает «тормозить» — никаких изменений в коде, никаких новых потоков, просто возросшая нагрузка. Начинаешь разбираться и находишь типичного виновника: приложение пересылает свои логи стороннему агрегатору через стандартный HTTP-аппендер Log4j2, независимо от того, какой вендор находится на другом конце. На ноутбуке вы этого не заметите, но на небольшом воркере CloudHub под нагрузкой логирование начинает конкурировать с запросами, ради обработки которых приложение и существует.

Дороговизну этого процесса определяет не какой-то отдельный инцидент, а его постоянная повторяемость: это приводит к эскалациям, трате времени инженеров и службы поддержки, а также подрывает доверие клиента к приложению, которое на самом деле не было сломано. Именно поэтому проблему стоит решить один раз и правильно, а не разбираться с каждым случаем по отдельности. В этой статье объясняется, почему это происходит, и предлагается один из способов решения.

Логирование и производительность приложения

Спросите разработчика, что замедляет работу приложения под нагрузкой, и логирование вряд ли будет упомянуто — оно воспринимается как фоновая задача, строка, которую записали и забыли. Для консоли или локального файла это оправданно, так как запись занимает микросекунды. Однако отправка той же строки по сети агрегатору логов полностью меняет экономику процесса, поэтому путь логирования заслуживает гораздо большего внимания, чем обычно. Пересылка логов по HTTP удобна, но отправка их по одному запросу за раз — это то, где скрываются издержки. В документации Log4j2 предупреждается, что синхронная отправка логов по одному на HTTP-бэкенд — редко хорошая идея. Каждый вызов логирования может блокировать поток на десятки или сотни миллисекунд — на порядки дольше, чем аппендер для консоли или файла, — и любой сетевой сбой или задержка на бэкенде сразу отражаются на ваших логгерах. Рекомендация заключается в том, чтобы как минимум использовать асинхронные логгеры (которые в приложениях Mule 4 используются по умолчанию) или рассмотреть сторонний аппендер.

Некоторые вендоры поставляют свои собственные оптимизированные аппендеры, которые, в двух словах, отправляют события пакетами, и в службе поддержки MuleSoft мы рекомендуем их там, где они есть. Но не каждый вендор предлагает такое решение. В базе знаний по рекомендуемым аппендерам логов перечислены специализированные аппендеры для Splunk, New Relic и Sumo Logic, однако для некоторых вендоров там могут лишь посоветовать обратиться в их собственную поддержку. Более того, вендор может прекратить поддержку своей библиотеки логирования для Java. Какой бы аппендер ни отправлял ваши логи, он опирается на ту же инфраструктуру Log4j2, и эта инфраструктура под нагрузкой может работать гораздо хуже, чем ожидают многие разработчики.

Почему асинхронное логирование становится синхронным под нагрузкой

Асинхронное логирование — это то, что обычно делает логирование «дешевым». В Log4j2 оно работает через кольцевой буфер (ring buffer): ваше приложение передает каждое событие в буфер фиксированного размера и сразу возвращается к обслуживанию запроса, в то время как отдельный фоновый поток обрабатывает буфер и выполняет более медленную часть — непосредственную отправку. Ожидание сети никогда не ложится на потоки, выполняющие основную работу, поэтому логирование кажется почти бесплатным. На рисунке 1 показан этот путь и то, что происходит, когда фоновый поток не справляется.

Рисунок 1. Асинхронный кольцевой буфер Log4j2 под нагрузкой — показано состояние блокировки потока. Один фоновый поток очищает буфер и передает по одному событию стандартному HTTP-аппендеру, который выполняет один блокирующий POST-запрос на событие и ждет завершения полного цикла; как только события начинают поступать быстрее, чем обрабатываться, буфер переполняется, и потоки самого приложения блокируются. Исправление с помощью пакетирования показано на рисунке 2. Альтернативный текст: диаграмма кольцевого буфера с двенадцатью слотами (девять заняты событиями, три свободны), производитель App/Log4j2 ставит события в очередь, одна зеленая стрелка потока очистки к стандартному HttpAppender, красная стрелка «один блокирующий POST на событие» к API вендора с пунктирной линией ожидания ответа, и красная обратная связь, показывающая, как производители блокируются при заполнении буфера. Источник: оригинальная диаграмма автора.

Это работает только до тех пор, пока фоновый поток успевает справляться — а это зависит от того, как быстро аппендер очищает буфер, а не от самого буфера и не от выбора между диском и сетью. Файловый аппендер очищается за микросекунды, поэтому он почти всегда успевает; сетевой аппендер, отправляющий события пакетами, тоже успевает, очищая много слотов за один запрос. Тот, что отстает, — медленный и последовательный: сетевой аппендер, который отправляет по одному событию через HTTP и ждет каждого ответа, тратя на это десятки или сотни миллисекунд. При малом объеме это нормально, так как фоновый поток успевает очистить одно событие до прихода следующего.

Однако при увеличении объема логов события начинают поступать быстрее, чем отправляться. Буфер заполняется, потокам вашего приложения некуда передавать данные, и они начинают ждать — логирование незаметно становится синхронным. Каждая строка лога теперь ждет своего собственного блокирующего POST-запроса к бэкенду вендора, используя те самые потоки, которые обслуживают ваших клиентов, — именно тот результат, для предотвращения которого и существует асинхронное логирование.

Когда специализированного аппендера нет, вы возвращаетесь к стандартному HTTP-аппендеру и наследуете его синхронное поведение «один запрос на событие».

Текущее состояние: один запрос на событие

Это унаследованное поведение легко упустить из виду. Оно ничего не стоит при малом объеме и проявляется только под постоянной нагрузкой — чем занятее ваше приложение, тем больше задач по логированию ложится на потоки, обслуживающие ваших клиентов. Мы регулярно видим последствия этого в службе поддержки MuleSoft, и базовый механизм описан в статье базы знаний о деградации производительности из-за логирования.

Симптом четко виден в дампе потоков. Поскольку стандартный HTTP-аппендер отправляет один блокирующий POST-запрос на событие, он начинает отставать под нагрузкой, и поток приложения оказывается заблокирован на пути логирования, ожидая места для передачи следующего события:

Этот заблокированный поток — то, как выглядит «один запрос на событие» в продакшене: один синхронный POST на строку лога, занимающий путь каждого запроса. Устранение этого «бутылочного горлышка» — именно то, для чего создан пакетный HTTP-аппендер.

Пакетный HTTP-аппендер для логов

Пакетный HTTP-аппендер для логов — это замена стандартного HTTP-аппендера, созданная специально для решения этой проблемы: он переносит доставку логов с потоков вашего приложения и превращает тысячи крошечных синхронных POST-запросов в несколько крупных, сжатых запросов.

Эта передача проста: каждое событие ставится в очередь в памяти с ограниченным размером, и поток потока (flow thread) немедленно возвращается к работе, поэтому сетевое ожидание никогда не попадает на путь обслуживания ваших клиентов. Затем фоновый рабочий поток объединяет эти события и отправляет каждый пакет как один gzip-сжатый запрос.

Отправка каждого пакета определяется тремя триггерами сброса — срабатывает тот, который наступит первым: количество записей (maxBatchRecords), размер полезной нагрузки (maxBatchBytes) или возраст самого старого события в очереди (lingerMillis). Таким образом, один и тот же аппендер (appender) адаптируется от высокопроизводительной пакетной доставки до доставки с низкой задержкой в режиме, близком к реальному времени, без изменения ни одной строки кода приложения. Одни и те же события достигают одного и того же бэкенда; вы просто перестаете платить за каждый запрос тысячи раз.

На рисунке 2 показан этот шаблон от начала до конца, включая путь обработки сбоев, поскольку перенос доставки из ваших потоков имеет смысл только в том случае, если эти логи все равно дойдут до места назначения, даже если конечная точка не может принять их немедленно. То, как аппендер удерживает их, вместо того чтобы потерять, — это история об отказоустойчивости, которую рассказывает остальная часть этого раздела.

Рисунок 2. Архитектура пакетного HTTP-аппендера — решение для пакетной обработки для стандартного пути, показанного на рисунке 1. Замещающий текст (для публикации): блок-схема, показывающая события логов, помещаемые в ограниченную очередь в памяти, объединяемые в пакеты с помощью триггеров сброса, отправляемые по HTTPS в систему приема поставщика, с хранилищем на диске (включено по умолчанию) и фоновым механизмом повторной отправки на пути обработки сбоев. Источник: диаграмма архитектуры в README репозитория batch-http-log-appender.

Доставка производственных логов также должна выдерживать ограничение скорости приема (throttling), нестабильную сеть и перезапуск воркера, поэтому отказоустойчивость встроена в систему, а не добавлена поверх:

• Повторные попытки с учетом состояния сервера. Временные сбои — 408, 429, 5xx и сетевые ошибки — повторяются с использованием экспоненциальной задержки с джиттером (от 200 мс до верхнего предела в 10 с). Когда система приема с ограничением скорости возвращает заголовок Retry-After, аппендер учитывает его (с тем же верхним пределом в 10 с), замедляя работу в соответствии с бэкендом, вместо того чтобы перегружать его.
• Быстрый отказ при постоянных ошибках. Неверный ключ API или неправильная конечная точка выявляются немедленно, а не переповторяются бесконечно, а слишком большое событие ограничивается до того, как оно сможет переполнить очередь.
• Отказоустойчивый буфер сброса на диск, включенный по умолчанию. Когда конечная точка недоступна или очередь в памяти переполняется, события сохраняются в ротируемые сегментные файлы, а фоновый механизм повторной отправки отправляет их снова, как только доставка восстанавливается — по принципу «как минимум один раз» (at-least-once), поэтому временный сбой может стоить вам случайных дубликатов, а не потери логов.

Как настроить пакетный HTTP-аппендер в приложении Mule 4

Внедрение пакетного HTTP-аппендера требует трех небольших изменений: добавьте зависимость batch-http-log4j2 в файл pom.xml вашего приложения (соберите его один раз с помощью mvn install, как описано в README репозитория); добавьте packages=”com.mulesoft.support.batchhttp.log4j2″ в элемент <Configuration> вашего файла log4j2.xml, так как без этого Log4j2 молча игнорирует аппендер и логи не отправляются; и замените стандартный аппендер <Http> на <BatchHttp>. В документации по пользовательским аппендерам логов описано, как конфигурация Log4j2 загружается на платформе. Соедините аппендер с асинхронными логгерами, и все ваше приложение будет отправлять логи, не блокируя поток.

Вот пример конфигурации для Datadog (установите site на хост приема логов вашего сайта Datadog):

Обратитесь к репозиторию batch-http-log-appender для получения полных фрагментов кода для каждого поставщика и полного списка параметров конфигурации.

Аппендер не использует SDK поставщиков и, помимо самого Log4j2, не имеет сторонних зависимостей времени выполнения: одна библиотека, построенная на собственном HTTP-клиенте JDK.

Поддерживаемые поставщики

Пакетный HTTP-аппендер создан для поддержки практически любого поставщика: если есть публично документированная конечная точка приема HTTP-логов, этого поставщика можно добавить в аппендер.

Поддержка поставщиков, реализованная на данный момент (Datadog и New Relic — два поставщика, протестированные ниже):

• Datadog
• Splunk HEC
• New Relic
• Dynatrace

Также доступна общая конфигурация для пересылки логов в любую другую службу, которая принимает JSON с разделителями в виде новой строки (NDJSON) или массив JSON. Поддержка поставщиков все еще находится в процессе разработки, поэтому ожидайте некоторых шероховатостей.

Ключевые атрибуты конфигурации

Все параметры пакетной обработки являются необязательными и имеют разумные значения по умолчанию, поэтому аппендер работает «из коробки». Наиболее полезные из них:

• Триггеры сброса, срабатывает тот, который наступит первым: maxBatchRecords (по умолчанию 200), maxBatchBytes (1 МБ) и lingerMillis (1000 мс).
• queueCapacity (10000) для ограниченной очереди в памяти.
• gzip (включено по умолчанию).
• maxRetries (3, т.е. до четырех попыток; обработка задержки и Retry-After, как описано выше).
• spillEnabled (включено) для отказоустойчивого буфера сброса на диск.

Полный справочник атрибутов и значений по умолчанию находится в репозитории batch-http-log-appender вместе с запускаемыми демо-приложениями, которые вы можете развернуть самостоятельно. Разумные значения по умолчанию — это одно, а то, что пакетная обработка дает вам при устойчивой нагрузке — другое, поэтому мы измерили это. Приведенные ниже тесты сравнивают пакетный HTTP-аппендер со стандартным HTTP-аппендером в условиях реального нагрузочного тестирования.

Тесты производительности

Чтобы показать, что на самом деле дает пакетная обработка, мы провели нагрузочное тестирование одного и того же приложения Mule 4 со стандартным и пакетным HTTP-аппендерами бок о бок на CloudHub 1.0 и CloudHub 2.0 и рассмотрели две вещи: какую пропускную способность получает приложение и как быстро его логи достигают агрегатора логов. Вот как была настроена лаборатория и что мы поддерживали неизменным во всех запусках.

Настройка тестовой лаборатории

Мы развернули четыре сборки одного и того же приложения hello-world Mule 4 (стандартный и пакетный HTTP-аппендеры, каждый в паре с Datadog и New Relic) на воркерах 0.1 vCore на CloudHub 1.0 и CloudHub 2.0 и провели их через четыре теста:

• Тест 1 (1 мин)
• Тест 2 (повтор в течение 1 мин без перезапуска, «churn»-запуск)
• Тест 3 (5 мин)
• Тест 4 (5 мин с тайм-аутом 30 с на запрос)

Каждый воркер перезапускался и прогревался перед каждым запуском (кроме Теста 2), ни одна система приема поставщика не загружалась двумя приложениями одновременно, а gzip и буфер сброса на диск были отключены, чтобы пакетный HTTP-аппендер измерялся на тех же условиях, что и стандартный. Полная методика, таблицы по каждому тесту и руководство по воспроизведению каждого запуска находятся в результатах тестов и руководстве по запуску тестов репозитория.

Что показывают тесты

Рисунок 3. Устойчивая пропускная способность запросов (Тест 3, пятиминутное окно прогрева): пакетная обработка против стандартной (запросов/с), по платформам и поставщикам. Сравнивайте внутри одной платформы, а не между ними — две плоскости работали с разной степенью параллелизма на разных процессорах. Замещающий текст (для публикации): сгруппированная горизонтальная гистограмма запросов в секунду, где полосы пакетной обработки во много раз длиннее, чем у стандартных аналогов как на CloudHub 1.0, так и на CloudHub 2.0. Источник: в репозитории batch-http-log-appender.

Рисунок 4. Задержка запросов (Тест 3) — среднее значение, p90 и p99 на логарифмической шкале, представленные в виде графика диапазона: маркеры стандартного и пакетного аппендеров для каждой пары соединены разрывом улучшения. Поскольку нагрузка является замкнутой, более низкая средняя задержка и более высокая пропускная способность — это один и тот же эффект, видимый с двух сторон. Замещающий текст (для публикации): график-гантель, где маркеры стандартной задержки находятся далеко справа от маркеров пакетной обработки, а соединительная линия помечена как N-кратный разрыв для каждой метрики. Источник: в репозитории batch-http-log-appender.

Рисунок 5. Эффект «прогрева» / «холодного старта»: сравнение пакетной отправки (batch) и стандартной (stock) req/s в ходе Теста 1 (1 мин) → Теста 2 (отток) → Теста 3 (5 мин). Пропускная способность пакетной отправки растет по мере того, как фиксированные затраты на «холодный старт» распределяются на более длительный интервал, в то время как стандартная отправка остается на прежнем уровне или падает, причем на гораздо более низких значениях — именно поэтому одноминутный Тест 1 занижает показатели пропускной способности прогретого пакетного режима. Замещающий текст (для публикации): две сгруппированные гистограммы, по одной на платформу; столбцы пакетной отправки растут слева направо на всех трех этапах, в то время как столбцы стандартной отправки почти не меняются. Источник: в репозитории batch-http-log-appender.

На тех же воркерах с 0,1 vCore, при отправке тем же вендорам, Batch HTTP appender обеспечил примерно 56-кратную (Datadog) и 134-кратную (New Relic) пропускную способность по сравнению со стандартным аппендером на CloudHub 1.0, и примерно 8-кратную и 56-кратную на CloudHub 2.0 (Тест 3, пять минут).

Задержка при приеме: когда ваш дашборд отстает

На рисунках ниже показана задержка между двумя метками времени: моментом, когда приложение Mule 4 сгенерировало сообщение журнала, и моментом, когда агрегатор журналов его принял. Batch HTTP appender демонстрирует минимальную задержку или ее отсутствие, в то время как стандартный HTTP appender показывает значительную задержку при приеме журналов. Это не связано с проблемами производительности стороннего вендора — это стандартный аппендер, который все еще разгружает кольцевой буфер приложения. В более раннем сеансе Datadog на CloudHub 2.0 с теми же приложениями стандартное приложение отставало примерно на три минуты уже через несколько минут нагрузки. При более высокой и продолжительной производственной нагрузке мы наблюдали задержки в 10–15 минут и более, при этом сообщения журналов продолжали поступать в агрегатор еще долго после прекращения нагрузки.

Примечание: на каждом рисунке метки времени слева показаны по местному времени (AEST, UTC+10), а справа — по UTC. Поскольку различаются только часовые пояса, для определения истинной задержки приема сравнивайте минуты и секунды, а не часы.

Рисунок 6. Задержка приема Batch-app в Datadog — почти нулевая задержка; время генерации (generatedAt) каждого события остается синхронизированным со временем его получения даже под нагрузкой. Замещающий текст (для публикации): скриншот Datadog Log Explorer с журналами пакетного приложения, где одно событие развернуто, чтобы показать выделенную метку времени generatedAt, которая совпадает со временем получения до миллисекунды, рядом с устойчивой зеленой гистограммой объема журналов. Источник: docs/img/datadog-batch-ingest-lag.png в репозитории batch-http-log-appender.

Рисунок 7. Задержка приема Stock-app в Datadog — отставание примерно на три минуты, так как синхронный аппендер не справляется и продолжает разгружать очередь после прекращения нагрузки. Замещающий текст (для публикации): тот же вид Datadog Log Explorer для стандартного приложения, где выделенная метка времени generatedAt развернутого события более чем на три минуты раньше времени, когда Datadog его получил. Источник: docs/img/datadog-stock-ingest-lag.png в репозитории batch-http-log-appender.

Рисунок 8. Объем журналов, доставленных в Datadog за тот же интервал запроса (оба запуска плюс разгрузка очереди стандартного приложения) — около 84,7 тыс. событий от пакетного приложения против около 5,66 тыс. от стандартного. Замещающий текст (для публикации): список фасетов Datadog, показывающий два фильтра хостов с количеством событий рядом, datadog-batch-http — 84,7 тыс. и datadog-stock-http — 5,66 тыс. Источник: docs/img/datadog-log-volume-batch-vs-stock.png в репозитории batch-http-log-appender.

Заключение

По сравнению со стандартным HTTP appender, Batch HTTP appender меняет способ отправки ваших журналов — и эта разница наиболее заметна под нагрузкой:

• Более высокая пропускная способность при тех же ресурсах. Одно и то же приложение выполняет значительно больше работы (примерно в 8–134 раза в наших тестах) на тех же процессоре и памяти — вы возвращаете пропускную способность, которую синхронный аппендер тратил на тысячи крошечных блокирующих POST-запросов.
• Отсутствие саморегулирования при скачках нагрузки. Со стандартным аппендером, как только доставка журналов начинает отставать, потоки потока блокируются на каждом POST-запросе, и приложение незаметно начинает ограничивать само себя, обрабатывая меньше запросов именно тогда, когда трафик максимален. Неблокирующая постановка в очередь Batch HTTP appender устраняет это противодавление: всплеск нагрузки при продвижении или инциденте поглощается очередью в памяти и разгружается фоновым воркером, поэтому ваши потоки продолжают обслуживать клиентов на полной скорости, вместо того чтобы простаивать из-за собственных журналов.
• Дашборды, которые не отстают. Журналы достигают вашего агрегатора почти в реальном времени, а не с отставанием в несколько минут (около трех в нашем лабораторном тесте и 10–15 или более при более высокой производственной нагрузке), поэтому то, что вы видите во время инцидента, соответствует действительности.
• Журналы переживают сбои. Повторные попытки с учетом состояния сервера и устойчивый к сбоям буфер сброса на диск сохраняют ваши журналы во время сбоев конечных точек и перезагрузок — с гарантией доставки «как минимум один раз», поэтому в худшем случае вы получите дубликат, а не пропуск.

Вывод прост: ведение журналов должно быть побочным эффектом, а не узким местом. Вынесите доставку журналов из потока приложения, объединяйте их в пакеты по сети, и то же самое приложение Mule 4 будет выполнять больше работы на тех же ресурсах, при этом ваши журналы будут доставлены. Ссылки ниже описывают, как это внедрить.

Попробуйте сами

Batch HTTP log appender распространяется с открытым исходным кодом по лицензии Apache License 2.0. Если это решение подходит для вашей проблемы, перейдите в репозиторий GitHub, следуйте инструкциям по настройке и замените аппендер в вашем log4j2.xml — никаких изменений в коде приложения и сторонних SDK не требуется.

Клонируйте его, запустите демо-приложения для вашего вендора и измерьте разницу на своей собственной рабочей нагрузке.

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

Дополнительная литература

Рекомендуемые аппендеры журналов для сторонних агрегаторов — база знаний MuleSoft, на которой основана эта статья.

— механизм кольцевого буфера.

Batch HTTP log appender на GitHub — эталонная реализация с открытым исходным кодом. Документация репозитория охватывает установку, полную конфигурацию и справочник атрибутов, лицензирование и информацию о том, где сообщать о проблемах.

Ссылки: oha