Меня зовут Владимир Куропатка, и я старший бэкенд-разработчик в компании Altenar, которая поставляет ПО для зарубежных лицензированных операторов прогнозов на спорт. Наша команда столкнулась с тем, что память забивалась логами, и это приводило к OutOfMemoryException и аварийному закрытию приложений.

В статье разбираю, как устроен процесс логирования в Serilog, почему асинхронная отправка логов не всегда безопасна, как протестировать систему на устойчивость к задержкам и какие настройки и архитектурные приёмы помогут сохранить стабильность под нагрузкой.

Этот текст — переложение моего доклада для весеннего митапа SpbDotNet. Если вам удобнее воспринимать на слух, смотрите запись выступления.

Логи разные нужны, логи разные важны

Логирование — это процесс создания информационных сообщений о событиях, которые происходят в приложении, с фиксацией этих сообщений в журнале.

Как правило, логирование оформлено в приложении отдельным сервисом. В .NET для этого существует стандартный интерфейс ILogger: вызывается метод логирования, и дальше фреймворк сам заботится о том, чтобы доставить сообщение в нужное хр��нилище.

Основные цели логирования обычно такие:

• Мониторинг состояния приложения, сбор метрик. Журнал логов выступает как приборная панель или дашборд, по которому можно отслеживать, нет ли проблем в системе.

• Расследование инцидентов. Когда случается сбой или ошибка, логи позволяют по идентификатору запроса (Trace ID) восстановить картину событий и понять, где и что пошло не так.

• Отладка и аудит. Даже если инцидента еще нет, подробные логи помогают держать руку на пульсе и глубоко заглядывать во внутренние процессы приложения.

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

Логирование в наших проектах

В экосистеме .NET существует множество библиотек для логирования, таких как NLog, Log4Net и другие. Мы используем Serilog — и вот почему:

• Простота использования логгера через стандартный интерфейс ILogger. Логгер Serilog легко интегрировать в .NET-приложение через стандартные абстракции Microsoft.Extensions.Logging. Достаточно подключить нужный пакет и вызвать UseSerilog при конфигурировании приложения. 

• Активное развитие. Библиотека регулярно обновляется не только ради новых фич, но и с упором на оптимизацию. Вокруг этой библиотеки очень активное сообщество, которое охотно делится обратной связью.

• Гибкость. Serilog поддерживает множество форматов логов и интеграций. Логи можно отправлять в различные системы: Azure, Elastic, Google Cloud, «Яндекс» и другие. Microsoft в своей документации по Azure не стесняется рекомендовать Serilog наряду с другими библиотеками логирования.

Наши приложения пишут логи через абстракцию ILogger и стандартные методы LogInformation, LogWarning и другие. Под капотом работает Serilog. В качестве основного хранилища логов мы используем Google Cloud Logging. Принципиально выбор сервиса хранения логов (например, Google Cloud Logging) ничего не меняет — все они работают по схожей механике, и проблематика использования удалённых приёмников логов остаётся одинаковой. 

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

В определённый момент мы столкнулись с проблемой: в часы пиковой нагрузки приложения начали падать с ошибкой OutOfMemoryException (нехватка памяти). Проанализировав дампы, мы обнаружили, что память забита большим количеством неотправленных логов. Нужно было срочно понять, как с этим бороться.

Внутри Serilog: как работает логирование

Начнем с базового сценария. Разработчик вызывает в коде, например:

logger.LogInformation("Что-то произошло")

Что происходит дальше?

1. Вызов через ILogger
   Сообщение попадает в стандартный логгер Microsoft (реализация ILogger и его расширения), который перенаправляет его всем зарегистрированным логгерам.

2. Передача в Serilog
   Один из таких логгеров — это Serilog, а точнее обёртка над логгером Serilog, реализующая майкрософтовский интерфейс ILogger. Внутри него вызывается метод Write из серилоговского логгера, который начинает обработку события.

3. Передача в приёмники (sinks)
   Метод Write передаёт событие в один или несколько приёмников. Помимо того, что приёмников может быть множество, при этом каждый приёмник может включать в себя другие приёмники — своего рода «матрёшка». Таким образом, можно писать логи одновременно и в консоль, и в файл, и в удалённое хранилище.

4. Завершение
   После обработки всеми приёмниками управление возвращается в код приложения.

Приёмники Serilog делятся на синхронные и асинхронные (или локальные и удалённые).

Синхронные приёмники логов предназначены для фиксации одиночных записей. Простейший пример синхронного синка — запись в консоль. Интерфейс такой: 

public interface ILogEventSink
{
    void Emit(LogEvent logEvent);
}

Событие считается записанным сразу после вызова Emit. Казалось бы, проще простого — но на самом деле не все так однозначно, и дальше станет понятно почему.

Асинхронные приемники логов отправляют их батчами (пакетами). Интерфейс у них, соответственно, другой:

public interface IBatchedLogEventSink
{
    Task EmitBatchAsync(IReadOnlyCollection<LogEvent> batch);
}

Внешне все методы логирования выглядят синхронными — они возвращают void и не предполагают await. Разработчик, вызывая методы логгера, не ожидает ответа от него. Однако как это работает, если в цепочке есть удаленный сервис?

Когда приложение вызывает логгер, сообщение сначала передаётся в метод Emit синхронного приемника. Таким образом, какой бы сервис для хранения логов мы ни использовали (локальный или удалённый), на верхнем уровне мы всегда работаем с синхронными приёмниками. Он кладет запись в буфер. Параллельно запущен поток-потребитель, который считывает накопленные в буфере записи, формирует из них пакет (batch) и уже этот пакет отправляет во внешний сервис логирования. Потоки приложения пишут в буфер, поток-потребитель — читает, собирает пакеты и отправляет.

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

Слать каждый лог по отдельности сразу в облако не лучшая идея. На то есть несколько причин:

• Возможен троттлинг на стороне приемника. Если начать бомбардировать Google/Яндекс/Elastic миллионами маленьких запросов, они, скорее всего, начнут ставить их в очередь или отклонять избыточные.

• Повышается нагрузка на сеть. Каждое сообщение превращается в сетевой пакет. Сотни тысяч пакетов в секунду ощутимо просадят пропускную способность и увеличат время обработки.

• Нарушение порядка сообщений. Сеть не гарантирует, что запросы дойдут в том же порядке. Если слать по одному, легко получить ситуацию, когда лог A отправлен раньше B, а дошел позже — хронология нарушится.

• Стоимость обслуживания. Многие облачные провайдеры считают биллинг в том числе по количеству запросов. Отправляя логи батчами, можно сократить число запросов и сэкономить деньги.

Пакетная отправка сглаживает эти проблемы. Основная работа по сохранению лога — это быстрая запись объекта в буфер (память). Типичным решением тут стали структуры данных наподобие ConcurrentQueue или Channel. Они позволяют выдерживать всплески нагрузки: даже если внезапно количество запросов подскочит, вставка нового элемента в очередь останется дешевой операцией, и приложение, скорее всего, даже не почувствует, что логи стали обрабатываться медленнее. В итоге мы получаем компромисс между нагрузкой на ввод-вывод и производительностью.

Подводные камни отправки в удалённый приёмник

Буферизация и отложенная отправка значительно ускоряют работу приложения под нагрузкой. Однако, как показал наш опыт, у такого решения есть свои риски.

• Задержк�� доставки. Лог-сообщение появляется в удаленном сервисе не мгновенно, а спустя время — когда накопится пакет. 

• Потеря буфера при сбое приложения. Если приложение внезапно упадет или перезапустится, то всё, что было не выгружено, будет потеряно. Логи из очереди хранятся только в ОЗУ и при поломке процесса исчезают.

• Буфер хранится в оперативной памяти. ОЗУ — ресурс конечный, и нельзя бесконечно копить там события. Не ограниченный по максимальному количеству элементов буфер может заполнить всю память, если в течение продолжительного отрезка времени приложение пишет логи быстрее, чем фоновый отправитель отсылает их в удалённый приёмник. В результате мы получим OutOfMemoryException. Если ограничение на количество элементов установлено, есть риск потерять логи в том случае, когда буфер заполнен полностью в момент записи.

Именно последняя проблема — переполнение буфера — оказалась для нас самой болезненной.

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

С этим не получится что-то сделать: приемник нам ничего не гарантирует, проблемы с сетью тоже зачастую находятся за гранью нашего влияния. Однако мы нашли определённые решения, которые помогают нивелировать эти факторы. 

Настройки буферизации Serilog

Serilog даёт набор параметров для настройки, наибольший интерес из которых представляет следующая:

Максимальный размер очереди (Queue Limit) — жесткое ограничение на максимальное количество сообщений во внутреннем буфере. Если лимит достигнут на момент попытки записи, новые логи отбрасываются. 

Queue Limit — пожалуй, самый спорный параметр. С одной стороны, он защищает от переполнения памяти (достаточно подобрать разумное значение по объему, например, 5000 сообщений). С другой — может привести к потере логов. Это скорее аварийная защита, чем рабочий режим. Однако это единственный 100% рабочий способ обезопасить себя от аварийного закрытия приложения из-за заполнения оперативной памяти логами. 

Настройки — это хорошо, но по отдельности они не решают проблемы. 

Так что необходимо оптимизировать саму систему логирования.

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

Исходя из вышеописанных проблем, мы приходим к критериям оптимизации логировани��:

• Снижение вероятности падения приложения из-за переполнения памяти логами.

• Минимизация возможной потери логов (стремиться к нулевой потере).

И теперь расскажу про варианты технических решений.

Персистентный буфер и отдельное приложение-потребитель 

Как мы выяснили, находящийся в памяти буфер — потенциальный источник проблем, т.к заполнение его логами может привести либо к падению приложения из-за OOM, либо к потере логов. При использовании Serilog с удалёнными приёмниками логов внутри одного приложения происходит полный цикл обращения с логами: формирование записей, буферизация и отправка. Отправка — наиболее слабое место данного процесса, поскольку постоянное время отклика гарантировать невозможно. Замедление какого-либо сегмента сети либо задержки на стороне удалённого сервиса — всё это сулит нам вышеописанные неприятности. Наиболее рабочий способ обезопасить себя в данном случае следующий:

• Вместо отправки в удалённый приёмник — писать логи в персистентный буфер. Например, на persistent volume на базе хранилища того облака, в котором развёрнут кластер. 

• Отправку осуществлять в отдельном приложении.

В качестве сервиса хранения логов мы используем Google Cloud Logging, поэтому отталкивались от его характеристик. Результаты тестирования показали, что в рамках одного и того же штата задержка между нами и сервисами Гугла в лучшем случае 15—20 мс (миллисекунд). Это много или мало? Смотря с чем сравнивать. Например, задержка при записи на SSD — это единицы миллисекунд. Разница ощутимая, но ценности здесь добавляет тот факт, что подобное хранилище куда стабильнее в плане задержек, нежели удалённый сервис. 

Плюсы:

• Решаются проблемы задержек. Запись на локальный диск предсказуемо быстрая.

• Ошибки внешнего сервиса не приводят к потере данных. Ни один лог не пропадет (разве что диск физически выйдет из строя, но тогда это и без логов серьезная проблема).

• Независимость от качества работы сети: увеличение задержек не влияет на основное приложение.

Минусы:

• Дополнительные затраты на разработку. Придётся писать или интегрировать компонент, осуществляющий фоновую пересылку с диска в облако.

• Усложнение архитектуры.

• Потребуются аппаратные ресурсы для нового приложения. 

Полагаю, многие видели такую схему в работе. Мы не претендуем на новаторство. Возникает вопрос: а почему сразу нельзя было пойти данным путём? Ответ простой. Пока всё было стабильно, мы радовались простоте работы с Google Cloud Logging. Куда проще подключить готовую библиотеку, прописать конфигурацию и ключи доступа, и наслаждаться доступностью логов в удобном дашборде. А потом появились нюансы. 

Оптимизация потребителя логов

Итак, запись в персистентный буфер позволяет снизить задержки потребителя логов до единиц миллисекунд. Это серьёзный шаг к повышению стабильности системы логирования, но можно и нужно пойти дальше. Отправке логов куда-либо предшествует сериализация. Теперь, когда запись осуществляется в наше собственное хранилище, мы не привязаны к тому механизму сериализации, который предоставляет нам библиотека Google (или какого-либо ещё сервиса хранения логов).

Заботят нас только два аспекта:

• максимально быстрая работа;

• возможность десериализовать запись лога в первозданном виде на стороне фонового приложения-потребителя.

Наш взор упал на библиотеку Serilog.Formatting.Compact, которую мы использовали для тестирования производительности. Для тестирования мы генерировали 1000 записей лога с несколькими структурированным параметрами и сравнивали производительность сериализации с помощью сериализатора из пакета Google Cloud Logging и упомянутого выше Serilog.Formatting.Compact.

Результаты получились следующие:

• выигрыш во времени почти 2,5 раза (420 мкс у Serilog.Compact.Formatter против 1,1 мс у сериализатора от Google);

• выигрыш в аллокациях почти в 3 раза не в пользу Google (800 кб против 2,2 Мб).

Логи попадают в буфер в виде объектов, а в приёмнике фиксируются в сериализованном виде. Сериализацию можно ускорить, как мы показали выше, но от неё можно и избавиться путём передачи этой ответственности поставщикам логов (потокам приложения). Таким образом, в буфере будут храниться предварительно сериализованные логи, и сериализация перестанет быть ответственностью потока-потребителя. Решение довольно спорное по следующим причинам:

• Дополнительные затраты на разработку, т.к. потребуется кастомизация имеющейся в Serilog реализации схемы «поставщик-потребитель». По сути, речь о разработке собственного логгера.

• Понижение качества обслуживания из-за появления дополнительной ответственности у потоков, обслуживающих пользовательский функционал приложения.

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

Как оценить влияние задержек

Прежде чем бросаться реализовывать кастомные решения, полезно понять, нужно ли это делать и насколько задержки сети окажут влияние на стабильность приложения. 

Как было сказано выше, проблематика у всех удалённых приёмников логов в Serilog одинакова. Заключается она в том, что каждый такой приёмник даёт задержку при отправке. Таким образом, чтобы в условиях тестового стенда протестировать поведение системы логирования под нагрузкой, не нужно подписываться на сервис обработки логов. Достаточно просто реализовать интерфейс IBatchedLogEventSink, снабдив его лишь одной функцией — задержкой:

public class RemoteLoggingSink : IBatchedLogEventSink
{
    public Task EmitBatchAsync(IReadOnlyCollection<LogEvent> batch)
        => Task.Delay(50);
}

И зарегистрировать его:

services.AddLogging(x => 
    x.AddSerilog(
        new LoggerConfiguration()
            .WriteTo.Sink(
                new RemoteLoggingSink(),
                new BatchingOptions())
            .CreateLogger()));

Параметры конфигурации (размер батча, период, лимит очереди и т. д.) можно задать в коде или вынести в JSON — как удобно.

С помощью простой доработки мы можем реализовать счетчик дошедших до приёмника логов: 

public class RemoteLoggingSink : IBatchedLogEventSink
{
    private int LogCount = 0;

    public Task EmitBatchAsync(IReadOnlyCollection<LogEvent> batch)
    {
        LogCount += batch.Count;
        return Task.Delay(50);
    }
}

И наш стенд готов к тестированию. Дальше нужно запустить приложение, подать нагрузку, которая приведёт к заранее известному количеству использований логгера, и снять следующие показатели:

• Сколько логов были успешно записаны и сколько потерялось?

• Были ли проблемы со стабильностью (падения приложения, просадки производительности)?

Типичный результат: чем выше искусственная задержка, тем сильнее деградируют показатели — вплоть до того, что при большой задержке приложение начнет терять логи тысячами или падать (если не ограничивать буфер).

Можно варьировать другие параметры: например, снять ограничение размера очереди и увеличивать нагрузку, тем самым увеличивая количество записей в лог в единицу времени, чтобы понять, какая нагрузка приведёт к потере стабильности приложения (OOM) в случае неограниченного по размеру буфера или же потере консистентности журнала логов в противном случае. 

Такие тесты наглядно показывают, нужно ли вам оптимизировать логирование, и помогают выбрать ключевые параметры.

Итого

Главная уязвимость логирования с помощью Serilog при использовании удалённых сервисов хранения логов — это буфер в памяти. Он спасает от тормозов, но ставит перед неприятным выбором: либо неограниченный рост очереди (риск падения приложения из-за OOM), либо ограничение буфера (риск потерять логи).

Serilog в целом отлично справляется со своей задачей. Стандартные настройки Serilog подходят для большинства сценариев, но в экстремальных случаях может потребоваться более тонкая работа, а именно кастомизация.

Ограничение размера очереди (Queue Limit) надежно предотвратит OOM, но чревато тихой потерей логов — здесь нужно четко понимать, приемлемо ли это для вас.

Для высоконагруженных приложений стоит рассмотреть дополнительные меры:

• использование локального персистентного хранилища (например, запись логов на смонтированный том с последующей отправкой силами другого приложения);

• разгрузка потребителя логов внутри основного приложения (подбор оптимального сериализатора, вынос сериализации на потоки, пишущие логи).

Такие решения требуют времени разработчиков, но способны значительно повысить отказоустойчивость.

Надеюсь, наш опыт окажется полезным и поможет настроить логирование под реальные задачи.