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


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


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


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


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


Method Mean Error StdDev Median Ratio Rank
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1,835.730 ns 55.3980 ns 163.3422 ns 1,791.901 ns 1.00 1
KeepFileOpen=true, ConcurrentWrites=true, Async=true 1,910.814 ns 37.9116 ns 90.1008 ns 1,908.513 ns 1.00 1
KeepFileOpen=false, ConcurrentWrites=false, Async=true 1,765.390 ns 34.5893 ns 33.9713 ns 1,764.598 ns 1.00 1
KeepFileOpen=false, ConcurrentWrites=true, Async=true 1,834.002 ns 36.2599 ns 56.4523 ns 1,838.500 ns 1.00 1
KeepFileOpen=true, ConcurrentWrites=false, Async=false 5,387.220 ns 77.9523 ns 69.1027 ns 5,376.298 ns 1.00 1
KeepFileOpen=true, ConcurrentWrites=true, Async=false 11,171.048 ns 58.5253 ns 54.7446 ns 11,186.697 ns 1.00 1
KeepFileOpen=false, ConcurrentWrites=false, Async=false 652,512.923 ns 8,856.6000 ns 8,284.4691 ns 650,545.605 ns 1.00 1
KeepFileOpen=false, ConcurrentWrites=true, Async=false 642,003.054 ns 12,750.3183 ns 31,515.6277 ns 645,749.609 ns 1.00 1
CreateLog4NetFromString 1,271.456 ns 3.9287 ns 3.4827 ns 1,271.722 ns 1.00 1
CreateNLogFromString 199.004 ns 0.3101 ns 0.2901 ns 199.046 ns 1.00 1
CreateLog4NetLogger 18,564.228 ns 44.6344 ns 41.7510 ns 18,564.598 ns 1.00 1
CreateNLogTypeOfLogger 140,220.404 ns 188.8802 ns 176.6787 ns 140,235.303 ns 1.00 1
CreateNLogDynamicLogger 115,329.549 ns 243.0537 ns 227.3526 ns 115,361.597 ns 1.00 1
FileLoggingLog4NetNoParams 7,076.251 ns 41.5518 ns 38.8676 ns 7,075.394 ns 1.00 1
FileLoggingLog4NetSingleReferenceParam 7,464.427 ns 36.0445 ns 33.7161 ns 7,470.789 ns 1.00 1
FileLoggingLog4NetSingleValueParam 7,684.635 ns 49.2505 ns 46.0690 ns 7,693.219 ns 1.00 1
FileLoggingLog4NetMultipleReferencesParam 8,207.387 ns 79.5855 ns 74.4443 ns 8,220.897 ns 1.00 1
FileLoggingLog4NetMultipleValuesParam 8,477.657 ns 63.4105 ns 59.3143 ns 8,472.385 ns 1.00 1
FileLoggingNLogNetNoParams 5,438.306 ns 42.0170 ns 37.2470 ns 5,427.805 ns 1.00 1
FileLoggingNLogNetSingleReferenceParam 5,734.572 ns 46.0770 ns 40.8461 ns 5,729.974 ns 1.00 1
FileLoggingNLogNetSingleValueParam 5,834.548 ns 40.4125 ns 35.8246 ns 5,838.905 ns 1.00 1
FileLoggingNLogNetMultipleReferencesParam 6,445.663 ns 57.5870 ns 53.8669 ns 6,440.509 ns 1.00 1
FileLoggingNLogNetMultipleValuesParam 6,784.489 ns 43.9255 ns 38.9388 ns 6,782.898 ns 1.00 1
NoOpLog4NetNoParams 11.063 ns 0.0141 ns 0.0125 ns 11.065 ns 1.00 1
NoOpLog4NetSingleReferenceParam 9.206 ns 0.0321 ns 0.0300 ns 9.203 ns 1.00 1
NoOpLog4NetSingleValueParam 11.423 ns 0.0147 ns 0.0131 ns 11.421 ns 1.00 1
NoOpLog4NetMultipleReferencesParam 44.472 ns 0.0474 ns 0.0396 ns 44.475 ns 1.00 1
NoOpLog4NetMultipleValuesParam 58.138 ns 0.1598 ns 0.1416 ns 58.139 ns 1.00 1
NoOpNLogNetNoParams 1.045 ns 0.0037 ns 0.0033 ns 1.045 ns 1.00 1
NoOpNLogNetSingleReferenceParam 1.994 ns 0.0033 ns 0.0028 ns 1.994 ns 1.00 1
NoOpNLogNetSingleValueParam 2.025 ns 0.0044 ns 0.0042 ns 2.024 ns 1.00 1
NoOpNLogNetMultipleReferencesParam 34.800 ns 0.0374 ns 0.0312 ns 34.798 ns 1.00 1
NoOpNLogNetMultipleValuesParam 47.509 ns 0.1199 ns 0.1063 ns 47.511 ns 1.00 1

NoOpLogging


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


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


Method Mean Error StdDev Median
NoOpLog4NetNoParams 11.063 ns 0.0141 ns 0.0125 ns 11.065 ns
NoOpLog4NetSingleReferenceParam 9.206 ns 0.0321 ns 0.0300 ns 9.203 ns
NoOpLog4NetSingleValueParam 11.423 ns 0.0147 ns 0.0131 ns 11.421 ns
NoOpLog4NetMultipleReferencesParam 44.472 ns 0.0474 ns 0.0396 ns 44.475 ns
NoOpLog4NetMultipleValuesParam 58.138 ns 0.1598 ns 0.1416 ns 58.139 ns
NoOpNLogNetNoParams 1.045 ns 0.0037 ns 0.0033 ns 1.045 ns
NoOpNLogNetSingleReferenceParam 1.994 ns 0.0033 ns 0.0028 ns 1.994 ns
NoOpNLogNetSingleValueParam 2.025 ns 0.0044 ns 0.0042 ns 2.024 ns
NoOpNLogNetMultipleReferencesParam 34.800 ns 0.0374 ns 0.0312 ns 34.798 ns
NoOpNLogNetMultipleValuesParam 47.509 ns 0.1199 ns 0.1063 ns 47.511 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 Median
FileLoggingLog4NetNoParams 7,076.251 ns 41.5518 ns 38.8676 ns 7,075.394 ns
FileLoggingLog4NetSingleReferenceParam 7,464.427 ns 36.0445 ns 33.7161 ns 7,470.789 ns
FileLoggingLog4NetSingleValueParam 7,684.635 ns 49.2505 ns 46.0690 ns 7,693.219 ns
FileLoggingLog4NetMultipleReferencesParam 8,207.387 ns 79.5855 ns 74.4443 ns 8,220.897 ns
FileLoggingLog4NetMultipleValuesParam 8,477.657 ns 63.4105 ns 59.3143 ns 8,472.385 ns
FileLoggingNLogNetNoParams 5,438.306 ns 42.0170 ns 37.2470 ns 5,427.805 ns
FileLoggingNLogNetSingleReferenceParam 5,734.572 ns 46.0770 ns 40.8461 ns 5,729.974 ns
FileLoggingNLogNetSingleValueParam 5,834.548 ns 40.4125 ns 35.8246 ns 5,838.905 ns
FileLoggingNLogNetMultipleReferencesParam 6,445.663 ns 57.5870 ns 53.8669 ns 6,440.509 ns
FileLoggingNLogNetMultipleValuesParam 6,784.489 ns 43.9255 ns 38.9388 ns 6,782.898 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 Median
KeepFileOpen=true, ConcurrentWrites=false, Async=false 5,387.220 ns 77.9523 ns 69.1027 ns 5,376.298 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=false 11,171.048 ns 58.5253 ns 54.7446 ns 11,186.697 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=false 652,512.923 ns 8,856.6000 ns 8,284.4691 ns 650,545.605 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=false 642,003.054 ns 12,750.3183 ns 31,515.6277 ns 645,749.609 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 Median
KeepFileOpen=true, ConcurrentWrites=false, Async=true 1,835.730 ns 55.3980 ns 163.3422 ns 1,791.901 ns
KeepFileOpen=true, ConcurrentWrites=true, Async=true 1,910.814 ns 37.9116 ns 90.1008 ns 1,908.513 ns
KeepFileOpen=false, ConcurrentWrites=false, Async=true 1,765.390 ns 34.5893 ns 33.9713 ns 1,764.598 ns
KeepFileOpen=false, ConcurrentWrites=true, Async=true 1,834.002 ns 36.2599 ns 56.4523 ns 1,838.500 ns

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


Код AsyncTargetWrapper:


new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync)
{
    OverflowAction = AsyncTargetWrapperOverflowAction.Block,
    BatchSize = 4096,
    FullBatchSizeWriteLimit = 128
}

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


Выводы:


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

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


Результаты: 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 Median
CreateLog4NetFromString 1,271.456 ns 3.9287 ns 3.4827 ns 1,271.722 ns
CreateNLogFromString 199.004 ns 0.3101 ns 0.2901 ns 199.046 ns
CreateLog4NetLogger 18,564.228 ns 44.6344 ns 41.7510 ns 18,564.598 ns
CreateNLogTypeOfLogger 140,220.404 ns 188.8802 ns 176.6787 ns 140,235.303 ns
CreateNLogDynamicLogger 115,329.549 ns 243.0537 ns 227.3526 ns 115,361.597 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 операциями подобный подход дает также дополнительный прирост производительности на машинах с медленными дисками.




К сожалению, не доступен сервер mySQL