Сильная производительность Serilog при включении уровня журнала отладки - PullRequest
Новая
       13

Сильная производительность Serilog при включении уровня журнала отладки

4 голосов
/ 22 марта 2019

Я использую Serilog в приложении .NET Core Service Fabric.
Мы заметили проблемы с производительностью, и после расследования выясняется, что Serilog является виновником.

Мы регистрируем ~ 2000 сообщений отладки, и это занимает более 10 секунд.
Это даже в том случае, если только консольный приемник настроен и настроен на фильтрацию только на уровне информационного журнала (поэтому сообщения отладки не отображаются).
Если для параметра MinimumLevel задано значение Information, выполнение одного и того же кода будет выполняться менее 1 секунды (даже с настроенными приемниками).

Наш проект использует:

  • netcoreapp2.0
  • Serilog NuGet, пакет 2.8.0 (последняя версия)

Это тот тип производительности, который ожидается от Serilog?

РЕДАКТИРОВАТЬ : я заметил такое же поведение в другом (гораздо) меньшем проекте. Это позволило мне изолировать проблему: у меня был специальный обогащатель, который извлекал ProcessId. Звонить Process.GetCurrentProcess() невероятно дорого. Делать это для каждого звонка было то, что убивало производительность. Я сохранил идентификатор процесса в поле экземпляра, и производительность возросла.

1 Ответ

2 голосов
/ 23 марта 2019

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

Это, вероятно, указывает на проблему с вашим журналом отладки - сам Serilog работает быстро, но если ваши события отладки сериализуют произвольные большие вещи, например полезные нагрузки запрос / ответ, или DTO, ваше приложение в конечном итоге выполнит много размышлений, обращений к свойствам ваших объектов (которые могут блокировать, выполнять ввод-вывод и другие сумасшедшие вещи), выделения и сборку мусора.

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

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

Использование Debug, а затем более позднего фильтра Information на приемнике консоли приведет к выполнению всей этой работы, а затем ее выбрасыванию. Установка минимального уровня на Information предотвратит выполнение этой работы.

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

...