В обсуждениях этой статьи, возникло наконец у меня желание оценить в цифрах скоростные характеристики API логгеров.
Решил провести сравнение задержек при использовании логгеров NLog и Log4Net, а также осветить немного общих вопросов по замерам производительности участков кода в .Net и Mono.
Для случая когда лог включен производительность складывается из следующих компонент:
В NLog и Log4Net все эти системы сильно различаются и составом и архитектурой. Кроме того они, могут быть по разному настроены с целью улучшения производительности. Поэтому, для включенного лога я не смог сформулировать не «холиварных» тестов.
Но, как уже упоминалось, отключенный логгер должен минимально влиять на скорость работы приложения. Поэтому, попробуем сравнить производительность именно отключенного логгера. В этом случае, затрагиваются только передача параметров в сам вызов логирования и выяснение текущего уровня логирования.
Для начала, покаюсь и признаю, что мои надежды на оптимизацию при jit-компиляции пока не оправдались. Ускорения производительности, от гипотетических inline-вставок не обнаружено. Но, кто знает, может позже фреймворки научатся…
Консольное приложение вычисляет в цикле функцию в которой выводится Debug сообщение.
Взято 6 функций.
Для увеличения точности, замеры группировались так, чтобы группа выполнялась более 100 тиков системного таймера. Общее количество замеров групп — 200000 для каждой функции.
Для предварительной оценки распределения по полученным данным строилась гистограмма. Правые 5% значений были исключены, как случайные задержки обусловленные влиянием операционной системы. Таким образом в таблице представлены средние оценки для 95% случаев и отклонения для них.
Замеры проводились на .Net (Windows 7) и Mono 2.10.2 (OpenSUSE 11.3).
Колонка «замедление» — это замедление Log4Net относительно NLog. Рассчитывалась с поправкой на время выполнения вызова функции (время Em_1).
Каждый последующий запуск теста может возвращать результаты выходящие из посчитанных доверительных интервалов, а в рамках одного запуска этот интервал не нарушается. Поэтому оценку производительности можно использовать только относительную. И поэтому замеры для обеих систем логирования проводятся в одном запуске.
Распределение времени выполнения функций с Log4Net:
Здесь: синий — N0_1, фиолетовый — N0_100, зеленый — N1_1, красный — N3_1.
Распределение NLog не привожу, т.к. это просто очень узкий выброс на 2-3 значения и формы распределения на графике все равно нет.
Распределение времени выполнения функций с Log4Net:
Здесь: синий — N0_1, фиолетовый — N0_100, зеленый — N1_1, красный — N3_1.
Аналогично, распределение NLog не привожу.
Если интересно, то можно самому построить графики.
Исходные коды бенчмарков лежат здесь. Отдельно сохранены бинарники, результаты тестирования, данные для гистограмм и графики. Там же примеры построения гистограмм для GnuPlot.
Замеры проводились на разных машинах, поэтому не следует сравнивать производительность Mono и .Net. Если интересно именно сравнение производительности платформ, то об этом можно более подробно прочитать в этой работе.
Из таблиц понятно, что для тривиального вызова мы получим ухудшение скорости у Log4Net более чем в 8 раз. Для более реального применения, следует смотреть пример вывода с 3-мя параметрами, т.е. 13 и 32 для DotNet и Mono соответственно.
В Log4Net странно большое время проверки уровня логирования. Настолько, что не имеет особого смысла использовать предпроверку.
Если Log4Net применяется под Mono, то мы можем наблюдать довольно причудливые распределения. Исходя из своего опыта сразу могу сказать, что это происки GC. По видимому, Mono хуже справляется с массированным боксингом параметров функций, а Log4Net все параметры приводит к типу object. Из-за этого, время выполнения еще более не предсказуемо — абсолютная погрешность превышает саму величину.
В реальной жизни, скорее всего, не понадобится настолько подробное логирование, что скорость вызова отключенного лога окажет влияние на скорость алгоритма. Сложно представить, как поведет себя сервис, если такой лог включить. Также, следует отдавать себе отчет, что речь идет о десятках наносекунд.
Полезная нагрузка логируемого участка кода обычно бывает на три порядка больше вызова лога (десятки микросекунд), а операции связанные с вводом/выводом еще на три порядка (десятки миллисекунд). Таким образом критерий скорости, при выборе логгера, пока не существенен.
Удачной разработки!
Решил провести сравнение задержек при использовании логгеров NLog и Log4Net, а также осветить немного общих вопросов по замерам производительности участков кода в .Net и Mono.
Для случая когда лог включен производительность складывается из следующих компонент:
- Рендеринг сообщения. Возможно кэширование одних параметров и расчет других асинхронно.
- Система распределения сообщения по target/appender'ам.
- Система сохранения потока сообщений.
В NLog и Log4Net все эти системы сильно различаются и составом и архитектурой. Кроме того они, могут быть по разному настроены с целью улучшения производительности. Поэтому, для включенного лога я не смог сформулировать не «холиварных» тестов.
Но, как уже упоминалось, отключенный логгер должен минимально влиять на скорость работы приложения. Поэтому, попробуем сравнить производительность именно отключенного логгера. В этом случае, затрагиваются только передача параметров в сам вызов логирования и выяснение текущего уровня логирования.
Для начала, покаюсь и признаю, что мои надежды на оптимизацию при jit-компиляции пока не оправдались. Ускорения производительности, от гипотетических inline-вставок не обнаружено. Но, кто знает, может позже фреймворки научатся…
Методика тестирования
Консольное приложение вычисляет в цикле функцию в которой выводится Debug сообщение.
Взято 6 функций.
- N0_1 — вывод константной строки.
- N0_100 — вывод константной строки из 100 разных потоков
- N1_1 — вывод форматированного сообщения с 1 параметром.
- N3_1 — вывод форматированного сообщения с 3-мя параметрами.
- P0_1 — вывод строки с предпроверкой (количество параметров не имеет значения)
- Em_1 — пустая (для оценки скорости обвязки измерения)
Для увеличения точности, замеры группировались так, чтобы группа выполнялась более 100 тиков системного таймера. Общее количество замеров групп — 200000 для каждой функции.
Для предварительной оценки распределения по полученным данным строилась гистограмма. Правые 5% значений были исключены, как случайные задержки обусловленные влиянием операционной системы. Таким образом в таблице представлены средние оценки для 95% случаев и отклонения для них.
Замеры проводились на .Net (Windows 7) и Mono 2.10.2 (OpenSUSE 11.3).
Колонка «замедление» — это замедление Log4Net относительно NLog. Рассчитывалась с поправкой на время выполнения вызова функции (время Em_1).
Каждый последующий запуск теста может возвращать результаты выходящие из посчитанных доверительных интервалов, а в рамках одного запуска этот интервал не нарушается. Поэтому оценку производительности можно использовать только относительную. И поэтому замеры для обеих систем логирования проводятся в одном запуске.
Результаты замеров
Тестирование под .Net (Windows 7)
| Log4Net | NLog | ||
| функция | среднее время (нс) | среднее время (нс) | замедление |
| N0_1 | 31,4 (-0,3 +0,4) | 6,83 (-0,05 +0,02) | 8,4 |
| N0_100 | 31,9 (-0,8 +3,8) | 6,83 (-0,06 +0,01) | 8,5 |
| N1_1 | 40,4 (-1,3 +2,9) | 7,25 (-0,13 +0,01) | 10 |
| N3_1 | 60,6 (-1,2 +8,8) | 7,93 (-0,04 +0,03) | 13 |
| P0_1 | 27,7 (-0,3 +0,3) | 4,438 (-0,004 +0,031) | 26 |
| Em_1 | 3,51 (-0,12 +0,24) | --- | --- |
Распределение времени выполнения функций с Log4Net:
Здесь: синий — N0_1, фиолетовый — N0_100, зеленый — N1_1, красный — N3_1.
Распределение NLog не привожу, т.к. это просто очень узкий выброс на 2-3 значения и формы распределения на графике все равно нет.
Тестирование под Mono 2.10.2 (OpenSUSE 11.3)
| Log4Net | NLog | ||
| функция | среднее время (нс) | среднее время (нс) | замедление |
| N0_1 | 80,0 (-36,5 +5,5) | 6,924 (-0,004 +0,016) | 21 |
| N0_100 | 78,0 (-34,6 +11,3) | 6,924 (-0,004 +0,016) | 21 |
| N1_1 | 92,4 (-34,9 +13,3) | 6,926 (-0,006 +0,054) | 24 |
| N3_1 | 141 (-52 +848) | 7,635 (-0,015 +0,005) | 32 |
| P0_1 | 69,6 (-30,2 +4,8) | 4,351 (-0,011 +0,009) | 62 |
| Em_1 | 3,285 (-0,005 +0,005) | --- | --- |
Распределение времени выполнения функций с Log4Net:
Здесь: синий — N0_1, фиолетовый — N0_100, зеленый — N1_1, красный — N3_1.
Аналогично, распределение NLog не привожу.
Если интересно, то можно самому построить графики.
Исходные коды бенчмарков лежат здесь. Отдельно сохранены бинарники, результаты тестирования, данные для гистограмм и графики. Там же примеры построения гистограмм для GnuPlot.
Анализ результатов
Замеры проводились на разных машинах, поэтому не следует сравнивать производительность Mono и .Net. Если интересно именно сравнение производительности платформ, то об этом можно более подробно прочитать в этой работе.
Из таблиц понятно, что для тривиального вызова мы получим ухудшение скорости у Log4Net более чем в 8 раз. Для более реального применения, следует смотреть пример вывода с 3-мя параметрами, т.е. 13 и 32 для DotNet и Mono соответственно.
В Log4Net странно большое время проверки уровня логирования. Настолько, что не имеет особого смысла использовать предпроверку.
Если Log4Net применяется под Mono, то мы можем наблюдать довольно причудливые распределения. Исходя из своего опыта сразу могу сказать, что это происки GC. По видимому, Mono хуже справляется с массированным боксингом параметров функций, а Log4Net все параметры приводит к типу object. Из-за этого, время выполнения еще более не предсказуемо — абсолютная погрешность превышает саму величину.
Применимость
В реальной жизни, скорее всего, не понадобится настолько подробное логирование, что скорость вызова отключенного лога окажет влияние на скорость алгоритма. Сложно представить, как поведет себя сервис, если такой лог включить. Также, следует отдавать себе отчет, что речь идет о десятках наносекунд.
Полезная нагрузка логируемого участка кода обычно бывает на три порядка больше вызова лога (десятки микросекунд), а операции связанные с вводом/выводом еще на три порядка (десятки миллисекунд). Таким образом критерий скорости, при выборе логгера, пока не существенен.
Удачной разработки!
