В этой статье я поместил бенчмарки наиболее частных вызовов логгеров. Все эксперименты я проводил над 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 |
Сперва оценим, сколько мы тратим времени на то, чтобы вызвать метод для логгирования, который в итоге ни к чему не приведет. В большинстве случаев (по моему опыту) на боевых серверах отключен многословный 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 разные сигнатуры функций для малого числа аргументов:
void DebugFormat(string format, object arg0)
void Debug(string message, string argument)
void Debug<TArgument>(string message, TArgument argument)
А теперь анализ результатов:
Log4NetSingleReferenceParam
и Log4NetSingleValueParam
)Большинство программ (по моим наблюдениям) все-таки логгируют результаты в файл, поэтому для сравнения выберем именно эту операцию. Для простоты возьмем просто конфигурации логгеров, когда происходит запись в файл без буферизации, без дополнительных блокировок и т.д.
Результаты:
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 |
Использованный код:
var roller = new RollingFileAppender();
roller.ImmediateFlush = true;
roller.RollingStyle = RollingFileAppender.RollingMode.Once;
roller.MaxFileSize = 128 * 1000 * 1000;
new FileTarget($"target_{_logIndex++}")
{
ArchiveAboveSize = 128 * 1000 * 1000,
MaxArchiveFiles = 16,
AutoFlush = true,
ConcurrentWrites = false,
KeepFileOpen = false
};
Как видно, конфигурация логгеров более-менее схожая, а по результатам:
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 поставить все возможные комбинации, мы получим тест из таблицы.
Результаты довольно предсказуемые:
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 |
Выводы:
Результаты: | 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 для меня оптимизировал выполнение (видимо, просто не возвращая результат), что приводило к некорректным результатам.
И выводы:
Debug
, Info
и т.д. По сути каждый ILogger
знает ответ про себя: надо вызывать следующие методы или нет (а подобное требует хоть какой-то привязки к общей конфигурации). Из-за этой схемы работы у меня и выходил Out Of Memory на большинстве тестов (если использовать разные строки и т.д.).LogManager.GetCurrentClassLogger()
работает еще медленнее, чем LogManager.GetLogget(typeof(XXX))
. Это логично, даже разработчики NLog не рекомедует вызывать первый метод в цикле.private static readonly ILogger Log = LogManager.GetCurrentClassLogger()
. То есть на непосредственно производительность работы системы оно не влияет.Как лучше обращаться с логами:
Stream
'ы). Однако программа сможет работать быстрее.LogManager.GetLogger("123")
. Подобные вызовы работают быстрее, а значит логгер можно создавать и на большие инстансы объектов (например, " один логгер для контекста выполнения запроса").Выводы для своего кода:
object
) и в большинстве случаев ничего не делает (что верно для контрактов/валидаторов), то корректнее всего завернуть вызовы в generic форму (т.е. сделать методы вида Something<TArg>(TArg arg)
). Работать такое будет действительно быстрее.К сожалению, не доступен сервер mySQL