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

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

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

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

NoOpLogging

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

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

И код:

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

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

Результаты:

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

• 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 — разные способы блокировок

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

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 операции на другом потоке, сразу же освобождая текущий. Причем делает это грамотно, с сохранением порядка событий, сбрасывая все данные блоками, причем в каждом блоке целое число событый (чтобы не получалось обрезанных строк), и так далее.

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

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

Код AsyncTargetWrapper:

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

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

Выводы:

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

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

Выводы:

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

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

Результаты:

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

[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 операциями подобный подход дает также дополнительный прирост производительности на машинах с медленными дисками.