Быстрое логгирование

Автор оригинала: Igor Manushin

В этой статье я поместил бенчмарки наиболее частных вызовов логгеров. Все эксперименты я проводил над log4net и NLog, на Windows 10 x64 Intel с M.2 SSD.


Сырые результаты можно посмотреть на GitHub. В том же репозитории код (для запуска потребуется .Net 4.7.2 + Microsoft Visual Studio 2017+).


Что, как и почему — под катом.


Чтобы долго не читать, таблица результатов:


Method Mean Error StdDev
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1,144.677 ns 26.3805 ns 77.7835 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=true 1,106.691 ns 31.4041 ns 87.5421 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=true 4,804.426 ns 110.3406 ns 103.2126 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=true 5,303.602 ns 104.3022 ns 102.4387 ns
KeepFileOpen=true, ConcurrentWrites=false, Async=false 5,642.301 ns 73.2291 ns 68.4986 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=false 11,834.892 ns 82.7578 ns 77.4117 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=false 731,250.539 ns 14,612.0117 ns 27,444.8998 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=false 730,271.927 ns 11,330.0172 ns 10,598.1051 ns
CreateLog4NetFromString 1,470.662 ns 19.9492 ns 18.6605 ns
CreateNLogFromString 228.774 ns 2.1315 ns 1.8895 ns
CreateLog4NetLogger 21,046.294 ns 284.1171 ns 265.7633 ns
CreateNLogTypeOfLogger 164,487.931 ns 3,240.4372 ns 3,031.1070 ns
CreateNLogDynamicLogger 134,459.092 ns 1,882.8663 ns 1,761.2344 ns
FileLoggingLog4NetNoParams 8,251.032 ns 109.3075 ns 102.2463 ns
FileLoggingLog4NetSingleReferenceParam 8,260.452 ns 145.9028 ns 136.4776 ns
FileLoggingLog4NetSingleValueParam 8,378.693 ns 121.3003 ns 113.4643 ns
FileLoggingLog4NetMultipleReferencesParam 9,133.136 ns 89.7420 ns 79.5539 ns
FileLoggingLog4NetMultipleValuesParam 9,393.989 ns 166.0347 ns 155.3089 ns
FileLoggingNLogNetNoParams 6,061.837 ns 69.5666 ns 65.0726 ns
FileLoggingNLogNetSingleReferenceParam 6,458.201 ns 94.5617 ns 88.4530 ns
FileLoggingNLogNetSingleValueParam 6,460.859 ns 95.5435 ns 84.6969 ns
FileLoggingNLogNetMultipleReferencesParam 7,236.886 ns 89.7334 ns 83.9367 ns
FileLoggingNLogNetMultipleValuesParam 7,524.876 ns 82.8979 ns 77.5427 ns
NoOpLog4NetNoParams 12.684 ns 0.0795 ns 0.0743 ns
NoOpLog4NetSingleReferenceParam 10.506 ns 0.0571 ns 0.0506 ns
NoOpLog4NetSingleValueParam 12.608 ns 0.1012 ns 0.0946 ns
NoOpLog4NetMultipleReferencesParam 48.858 ns 0.3988 ns 0.3730 ns
NoOpLog4NetMultipleValuesParam 69.463 ns 0.9444 ns 0.8834 ns
NoOpNLogNetNoParams 2.073 ns 0.0253 ns 0.0225 ns
NoOpNLogNetSingleReferenceParam 2.625 ns 0.0364 ns 0.0340 ns
NoOpNLogNetSingleValueParam 2.281 ns 0.0222 ns 0.0208 ns
NoOpNLogNetMultipleReferencesParam 41.525 ns 0.4481 ns 0.4191 ns
NoOpNLogNetMultipleValuesParam 57.622 ns 0.5341 ns 0.4996 ns

NoOpLogging


Сперва оценим, сколько мы тратим времени на то, чтобы вызвать метод для логгирования, который в итоге ни к чему не приведет. В большинстве случаев (по моему опыту) на боевых серверах отключен многословный Debug, однако вызовы никто не убирает.


Сперва результат:


Method Mean Error StdDev
NoOpLog4NetNoParams 12.684 ns 0.0795 ns 0.0743 ns
NoOpLog4NetSingleReferenceParam 10.506 ns 0.0571 ns 0.0506 ns
NoOpLog4NetSingleValueParam 12.608 ns 0.1012 ns 0.0946 ns
NoOpLog4NetMultipleReferencesParam 48.858 ns 0.3988 ns 0.3730 ns
NoOpLog4NetMultipleValuesParam 69.463 ns 0.9444 ns 0.8834 ns
NoOpNLogNetNoParams 2.073 ns 0.0253 ns 0.0225 ns
NoOpNLogNetSingleReferenceParam 2.625 ns 0.0364 ns 0.0340 ns
NoOpNLogNetSingleValueParam 2.281 ns 0.0222 ns 0.0208 ns
NoOpNLogNetMultipleReferencesParam 41.525 ns 0.4481 ns 0.4191 ns
NoOpNLogNetMultipleValuesParam 57.622 ns 0.5341 ns 0.4996 ns

И код:


void Log4NetNoParams() => _log4Net.Debug("test");

void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument);

void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument);

void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat(
    "test {0} {1} {2} {3} {4} {5} {6} {7} {8}",
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument);

void Log4NetMultipleValuesParam() => _log4Net.DebugFormat(
    "test {0} {1} {2} {3} {4} {5} {6} {7} {8}",
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument);

void NLogNetNoParams() => _nlog.Debug("test");

void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument);

void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument);

void NLogNetMultipleReferencesParam() => _nlog.Debug(
    "test {0} {1} {2} {3} {4} {5} {6} {7} {8}",
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument,
    _stringArgument);

void NLogNetMultipleValuesParam() => _nlog.Debug(
    "test {0} {1} {2} {3} {4} {5} {6} {7} {8}",
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument,
    _intArgument);

Во-первых определимся, почему были выбраны именно такие тесты:


  • Эксперименты ставились над наиболее популярными библиотеками
  • В NLog и log4net разные сигнатуры функций для малого числа аргументов:


    • log4net:

    void DebugFormat(string format, object arg0)

    • NLog:

    void Debug(string message, string argument)
    void Debug<TArgument>(string message, TArgument argument)

    • Теория: при передаче значимого типа в log4net должен происходить boxing, который просто тратит процессорное время и ни к чему не приводит. В случае NLog — подобное поведение отсутствует, потому последний должен работать быстрее.

  • Сигнатуры для большого числа аргументов в библиотеках примерно одинаковые, поэтому хотелось бы узнать:
    • Насколько эффективнее вызывать методы с малым числом параметров.
    • Есть ли разница в скорости вызова метода "Is...Enabled" между двумя библиотеками

А теперь анализ результатов:


  • За счет использования generic аргументов в NLog, он быстрее отрабатывает для случая, когда непосредственное логгирование не нужно. То есть для случая, когда в вашей программе Debug уровень включен только на тестовой системе, просто смена библиотеки может ускорить работу ПО (и улучшить жизнь пользователям).
  • Если у вас выключено логгирование, и вы хотите вызвать метод с большим числом аргументов, то эффективнее разбить его на два. За счет этого вызовы методов выше будут работать быстрее в десятки раз.
  • Когда Вы пишете функцию, которая может принимать любой объект, то зачастую эффективнее всего заморочиться и сделать generic функцию. За счет такой простой оптимизации код будет работать быстрее (это хорошо видно на разнице во времени вызовов Log4NetSingleReferenceParam и Log4NetSingleValueParam)

FileLogging


Большинство программ (по моим наблюдениям) все-таки логгируют результаты в файл, поэтому для сравнения выберем именно эту операцию. Для простоты возьмем просто конфигурации логгеров, когда происходит запись в файл без буферизации, без дополнительных блокировок и т.д.


Результаты:


Method Mean Error StdDev
FileLoggingLog4NetNoParams 8,251.032 ns 109.3075 ns 102.2463 ns
FileLoggingLog4NetSingleReferenceParam 8,260.452 ns 145.9028 ns 136.4776 ns
FileLoggingLog4NetSingleValueParam 8,378.693 ns 121.3003 ns 113.4643 ns
FileLoggingLog4NetMultipleReferencesParam 9,133.136 ns 89.7420 ns 79.5539 ns
FileLoggingLog4NetMultipleValuesParam 9,393.989 ns 166.0347 ns 155.3089 ns
FileLoggingNLogNetNoParams 6,061.837 ns 69.5666 ns 65.0726 ns
FileLoggingNLogNetSingleReferenceParam 6,458.201 ns 94.5617 ns 88.4530 ns
FileLoggingNLogNetSingleValueParam 6,460.859 ns 95.5435 ns 84.6969 ns
FileLoggingNLogNetMultipleReferencesParam 7,236.886 ns 89.7334 ns 83.9367 ns
FileLoggingNLogNetMultipleValuesParam 7,524.876 ns 82.8979 ns 77.5427 ns

Использованный код:


  • log4net:

var roller = new RollingFileAppender();
roller.ImmediateFlush = true;
roller.RollingStyle = RollingFileAppender.RollingMode.Once;
roller.MaxFileSize = 128 * 1000 * 1000;

  • NLog:

new FileTarget($"target_{_logIndex++}")
{
    ArchiveAboveSize = 128 * 1000 * 1000,
    MaxArchiveFiles = 16,
    AutoFlush = true,
    ConcurrentWrites = false,
    KeepFileOpen = false
};

Как видно, конфигурация логгеров более-менее схожая, а по результатам:


  • NLog немного быстрее, чем log4net, где-то на 15%.
  • По тестам получилось, что эффективнее логгировать меньшее число параметров. Однако еще нельзя забывать, что при большем числе параметров результирующая строка тоже разрасталась. Поэтому в таблице корректно только сравнивать NLog против log4net.

NLog — разные способы блокировок


Method Mean Error StdDev
KeepFileOpen=true, ConcurrentWrites=false, Async=false 5,642.301 ns 73.2291 ns 68.4986 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=false 11,834.892 ns 82.7578 ns 77.4117 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=false 731,250.539 ns 14,612.0117 ns 27,444.8998 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=false 730,271.927 ns 11,330.0172 ns 10,598.1051 ns

Исходный код:


new FileTarget($"target_{_logIndex++}")
{
    ArchiveAboveSize = 128 * 1000 * 1000,
    MaxArchiveFiles = 16,
    AutoFlush = true,
    ConcurrentWrites = XXXXX,
    KeepFileOpen = YYYYY
};

Если на место XXXXX и YYYYY поставить все возможные комбинации, мы получим тест из таблицы.


Результаты довольно предсказуемые:


  • Если разрешить ConcurrentWrites, то система начнет постоянно брать и отдавать Mutex, что небесплатно. Зато, как мы видим, запись одной строчки в файл примерно эквивалентно одной системной блокировке.
  • Закрытие и открытие файла, как мы видим, еще сильнее влияет на производительность системы. В примерах с KeepFileOpen=true на каждую операцию логгирования у нас создавался файл (вместе с Handle), производилась запись на диск, вызывался Flush, отдавался Handle и еще производилось море подкапотных операций. Как результат — скорость падает в сотни раз.

Асинхронное логгирование и разные способы блокировок


Библиотека NLog также умеет выполнять все IO операции на другом потоке, сразу же освобождая текущий. Причем делает это грамотно, с сохранением порядка событий, сбрасывая все данные блоками, причем в каждом блоке целое число событый (чтобы не получалось обрезанных строк), и так далее.


Результаты разных способов неблокирующй работы:


Method Mean Error StdDev
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1,144.677 ns 26.3805 ns 77.7835 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=true 1,106.691 ns 31.4041 ns 87.5421 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=true 4,804.426 ns 110.3406 ns 103.2126 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=true 5,303.602 ns 104.3022 ns 102.4387 ns

Сравнение блокирующего и асинхронного подходов будут дальше, а здесь — только последний.


Код AsyncTargetWrapper:


new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync)
{
    OverflowAction = AsyncTargetWrapperOverflowAction.Block,
    QueueLimit = 10000
}

Как видно, настройки обертки таковы, что непосредственного сброса в файл не происходит довольно долго. Таким образом копится большой буфер, а значит все ресурсоемкие операции вроде "открыть файл" выполняются один раз для всего блока. Однако такой алгоритм требует дополнительной памяти (и немало).


Выводы:


  • Если используется асинхронный вывод, то не важно, какие настройки выботы с файлом используются. Вы можете каждый раз открывать и закрывать файл, при большом буфере это будет практически незаметно.
  • Все измерения верны только для случая, когда сброс данных на диск происходит примерно с той же скоростю, что и наполнение буферов (у меня такое получилось за счет быстрой файловой системы + естесственных пауз между замерами).

Синхронное и асинхронное логгирование


Результаты: Method Mean Error StdDev Median
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1,835.730 ns 55.3980 ns 163.3422 ns 1,791.901 ns
FileLoggingLog4NetNoParams 7,076.251 ns 41.5518 ns 38.8676 ns 7,075.394 ns
FileLoggingNLogNetNoParams 5,438.306 ns 42.0170 ns 37.2470 ns 5,427.805 ns
NoOpLog4NetNoParams 11.063 ns 0.0141 ns 0.0125 ns 11.065 ns
NoOpNLogNetNoParams 1.045 ns 0.0037 ns 0.0033 ns 1.045 ns

Выводы:


  • Несмотря на быстрый диск (в моем случае — M.2 SSD), запись в файл в другом потоке ускоряет работу в несколько раз. Если ваше приложение пишет на HDD диски, да еще и запущено на виртуальной машине, то выигрыш будет еще больше.
  • Однако, несмотря на даже быструю работу асинхронного кода, отсутствие логгирование дает еще больший выигрыш (хоть и немного разный, в зависимости от библиотеки).

Создание логгеров


Результаты:


Method Mean Error StdDev
CreateLog4NetFromString 1,470.662 ns 19.9492 ns 18.6605 ns
CreateNLogFromString 228.774 ns 2.1315 ns 1.8895 ns
CreateLog4NetLogger 21,046.294 ns 284.1171 ns 265.7633 ns
CreateNLogTypeOfLogger 164,487.931 ns 3,240.4372 ns 3,031.1070 ns
CreateNLogDynamicLogger 134,459.092 ns 1,882.8663 ns 1,761.2344 ns

Что тестировали:


[Benchmark]
public object CreateLog4NetFromString()
{
    return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000));
}
[Benchmark]
public object CreateNLogFromString()
{
    return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000));
}
[Benchmark]
public object CreateLog4NetLogger()
{
    return new []
    {
        LogManager.GetLogger(typeof(BaseTest)), // x16 times
    };
}

[Benchmark]
public object CreateNLogTypeOfLogger()
{
    return new[]
    {
        NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times
    };
}
[Benchmark]
public object CreateNLogDynamicLogger()
{
    return new[]
    {
        NLog.LogManager.GetCurrentClassLogger(), // x16 times
    };
}

Важная ремарка: к сожалению, мне было сложно сделать воспроизводимый бенчмарк, который не приводит к Out Of Memory, однако который создавал бы разные логгеры (т.е. для разных типов, для разных строк и так далее).


Однако, изучив работу библиотек, я нашёл, что едва ли не самые тяжеловеские операции выполняются для создания ключа логгера (т.е. определение имени, очистка от Generic аргументов и так далее).
Более того, чтобы стабилизировать бенчмарк по созданию логгера для log4net, пришлось производить не одну операцию, а 16 (т.е. возвращается массив из 16 одинаковых объектов). Если не возвращать ничего, то .Net для меня оптимизировал выполнение (видимо, просто не возвращая результат), что приводило к некорректным результатам.


И выводы:


  • Быстрее всего создаются логгеры из строк (NLog опять быстрее, однако разница между библиотеками небольшая, если учесть, что для логгеры создаются не просто так, а для последующей работы с ними).
  • log4net работает быстрее, чем NLog, при инициализации проекта. Возможно, дело в дополнительном кешировании на стороне NLog, которое помогает ускорить непосредственно вызовы Debug, Info и т.д. По сути каждый ILogger знает ответ про себя: надо вызывать следующие методы или нет (а подобное требует хоть какой-то привязки к общей конфигурации). Из-за этой схемы работы у меня и выходил Out Of Memory на большинстве тестов (если использовать разные строки и т.д.).
  • LogManager.GetCurrentClassLogger() работает еще медленнее, чем LogManager.GetLogget(typeof(XXX)). Это логично, даже разработчики NLog не рекомедует вызывать первый метод в цикле.
  • И самое главное: скорость работы всех этих методов зачастую влияет только на холодный старт приложения, когда инициализируются поля вида private static readonly ILogger Log = LogManager.GetCurrentClassLogger(). То есть на непосредственно производительность работы системы оно не влияет.

Вывод


Как лучше обращаться с логами:


  • Если есть возможность вообще не логгировать — это будет самым быстрым (что пока очевидно).
  • Если в проекте есть много вызовов логгера, которые не производят сброса данных в файл (на консоль и т.д.), то NLog работает быстрее. К тому же он выделяет меньше объектов в куче.
  • Если таки надо осуществлять запись в файл, то быстрее всего работает NLog в асинхронном режиме. Да, он ест больше памяти (по сравнению с NLog в синхронном режиме, так как по моим предыдущим замерам, log4net даже не пытается переиспользовать массивы и Stream'ы). Однако программа сможет работать быстрее.
  • Создание логгера — небесплатая операция, поэтому зачастую лучше создавать его статическим полем. Это не относится к созданию из строки, то есть что-то вида LogManager.GetLogger("123"). Подобные вызовы работают быстрее, а значит логгер можно создавать и на большие инстансы объектов (например, " один логгер для контекста выполнения запроса").
  • Если Вы хотите вывести в лог много параметров, однако в большинстве случаев непосредственно сброса данных в файл не будет, то лучше всего сделать несколько вызовов. Таким образом NLog не будет создавать дополнительных объектов в куче, если они там не нужны.

Выводы для своего кода:


  • Если ваш метод принимает произвольный объект (т.е. object) и в большинстве случаев ничего не делает (что верно для контрактов/валидаторов), то корректнее всего завернуть вызовы в generic форму (т.е. сделать методы вида Something<TArg>(TArg arg)). Работать такое будет действительно быстрее.
  • Если в вашем коде допустим сброс данных файл и параллельно работа еще с чем-то — лучше заморочиться и поддержать подобное. Да, это кажется очевидным, что параллельное выполнение может ускорить работу, однако в случае с IO операциями подобный подход дает также дополнительный прирост производительности на машинах с медленными дисками.
Поддержать автора
Поделиться публикацией

Похожие публикации

AdBlock похитил этот баннер, но баннеры не зубы — отрастут

Подробнее
Реклама

Комментарии 5

  • НЛО прилетело и опубликовало эту надпись здесь
      0
      Странный подход к наполнению статьи.
      Сначала таблица, понять которую можно только прочтя последующий текст.
      Есть сравнение двух библиотек, но итог сравнения не вынесен в таблички.
      А самое интересное — особенности подкапотной реализации, приводящей к разнице в скорости, сокрыты где-то в недрах.

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

      Ещё не рассмотрен такой акспект, как скорость отработки layout-а записей — там указывается формат строчки в файловом логе и можно напихать много чего. Этой фичей многие пользуются, но знают ли её цену?

      И ещё, у вас заголовок не соответствует контенту. По заголовку подразумевается, что будет описание того, как ускорить запись в лог, а не сравнение некоторого подмножества функций двух библиотек.
        0
        Отдельно отмечу про логгирование с кучей параметров — там изрядное время отъедает сборка строки, но не надо её оптимизировать несколькими вызовами логгера, скорее надо самому ускорять сборку строки.
        Ещё не рассмотрен такой акспект, как скорость отработки layout-а записей — там указывается формат строчки в файловом логе и можно напихать много чего. Этой фичей многие пользуются, но знают ли её цену?

        Я не смогу цифрами обосновать, а угадывать побаиваюсь. Я постараюсь сделать отдельную статью чуть позже (ну то есть сравнить разные способы заливки больших и малых строк в логгер). Мне только достоверно известно лишь то, что особые нюансы есть с log4j2 (см. тут: https://logging.apache.org/log4j/2.x/manual/async.html)


        Есть сравнение двух библиотек, но итог сравнения не вынесен в таблички.

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


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

        Нельзя понять то, как ускорить лог, без анализа бенчмарков. Нельзя понять правильность выбора библиотеки без их сравнения. И невероятно сложно сравнить полное множество всех функций из всех библиотек.


        А самое интересное — особенности подкапотной реализации, приводящей к разнице в скорости, сокрыты где-то в недрах.

        Да, возможно. Для меня были интересны прежде всего цифры — а кто именно быстрее. Самые важные моменты (с моей точки зрения), почему NLog быстрее, я вынес (асинхронность, generics, переиспользование массивов).

        0
        Я не смогу цифрами обосновать, а угадывать побаиваюсь.

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

        Про название — на медиуме она у вас более правильно названа.
          +1
          Это очень легко проверить — сравнить обычный вызов с кучей параметров и вызов с одной готовой строкой, отдельно померив время сборки этой строки.

          Чуть сложнее, однако с общей идеей я согласен. Если не забуду сделать таки статью, то добавлю следующие вещи:


          • Два варианта: включено ли логгирование, или нет. В одном из случаев строка даже не будет создаваться в памяти
          • Несколько библиотек (+ SeriLog, т.к. с ним тоже интересно сравнивать, как сказал автор NLog одном коментариев)
          • Передавать одно из четырех:
            • Заранее сформированную строку
            • В виде куче аргументов (т.е. string format + args) за один вызов Debug
            • В виде куче аргументов (т.е. string format + args) и в двух-трех вызовах Debug
            • В виде StringBuilder'а, без вызова ToString

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

        Самое читаемое