Логирование — производительность молчания

[@powerman]

Честно говоря, меня сильно смущают ваши цифры. Есть подозрение, что где-то закралась небольшая ошибочка… порядка на три примерно — т.е. не 'нс' (10^-9) а µs (10^-6). Дело в том, что если это действительно числа в 'нс', то получается что NLog выводит примерно 150 миллионов сообщений в секунду. При размере сообщения байт в 16, это 2.4GB/sec… не знаю, на каком железе Вы запускали тесты, но в реальность этих цифр верится слабо.

[@exmachine]

Так задача не вывести поток сообщений, а доблестно их игнорировать! ;)
И вывод как раз в том, что столько все равно не обработаешь.

[@powerman]

Я разрабатывал скоростной логгер для Perl (была реальная необходимость отлаживать движок, который выкачивал тысячи url-ек в секунду; в процессе выкачки одной url в отладочном режиме в лог писались десятки записей; а поскольку отлаживалась в том числе и производительность, то вывод в лог не должен был заметно тормозить всю систему; и уж тем более вызов лога при отключенном отладочном режиме не должен был вообще сказываться на производительности — чтобы не требовалось удалять отладочные вызовы лога при релизе модуля).

На Core2Duo E6600 @ 2.4GHz (используя одно ядро) мой модуль выводит (по шаблону «Test message: %d») одно сообщение за 3µs, а игнорирует сообщения за 400нс (в 7.5 раз быстрее). Разница в скорости между оптимизированным перлом и C где-то в 2 раза. Современный разогнанный на 5GHz проц даст ещё два раза. Итого максимальная теоретическая скорость доблестного игнорирования сообщений в лог (используя одно ядро CPU) порядка 100нс. А у Вас — 7нс (а .NET точно не быстрее C). Чтобы получить 7нс надо запускать тест многопоточно ядрах на 16-ти. Минимум.

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

[@exmachine]

Спасибо! Появился повод все еще раз перепроверить. Но ошибки не обнаружил.
Вот такой код на моей машине выполняется примерно 10 секунд (визуально и по системным часам).
Код замера интервала времени выполнения эквивалентен опубликованному.
Код логирования будет работать чуть быстрее чем в NLog за счет статических членов.

using System;
using System.Diagnostics;
namespace LogBenchmark
{
    class Program
    {
        private static volatile bool _showLog = true;
        static void Main(string[] args)
        {
            _showLog = false;
            Console.WriteLine("Frequency:{0}", Stopwatch.Frequency);
            int R = 1000000000;
            DateTime begin = DateTime.UtcNow;
            long none = Measure(None, R);
            long p3 = Measure(NCh_P3, R);
            Console.WriteLine("Elapsed: {0}", DateTime.UtcNow - begin);
 
            Console.WriteLine("None total:{0} ticks", none);
            Console.WriteLine("N3_1 total:{0}  ticks", p3);
 
            Console.WriteLine("None total:{0} s", (double)none / Stopwatch.Frequency);
            Console.WriteLine("N3_1 total:{0} s", (double)p3 / Stopwatch.Frequency);
 
            Console.WriteLine("None operation:{0} s", (double)none / Stopwatch.Frequency / R);
            Console.WriteLine("N3_1 operation:{0} s", (double)p3 / Stopwatch.Frequency / R);
        }
 
        static void None(int a1)
        {
        }
 
        public static long Measure(Action<int> action, int repeats)
        {
            action(0);
 
            long start = Stopwatch.GetTimestamp();
            for (int j = 0; j < repeats; j++)
                action(j);
            return Stopwatch.GetTimestamp() - start;
        }
 
        internal static void NCh_P3(int a1)
        {
            Debug("Test message: {0} {1} {2}", a1, a1, a1);
        }
 
        internal static void Debug(string frm, int a1, int a2, int a3)
        {
            if(_showLog)
                Console.WriteLine(frm, a1, a2, a3);
        }
    }
}

[@powerman]

Любопытно. Я погонял этот тест у себя, и сравнил с аналогичным кодом на Perl.

Mono быстрее Perl в ~70 раз на вызове пустой функции (вызов функции с одним «if(False)...» по скорости сравним с вызовом пустой функции и в Mono и в Perl), и медленнее Perl в ~2.25 раза на выводе в STDOUT (перенаправленном в /dev/null).

Скорее всего C тоже быстрее Perl на вызове пустой функции в те же 70-100 раз. Когда я говорил, что оптимизированный Perl медленнее C всего в два раза я имел в виду код, который делает что-то полезное, цифры чисто из опыта, сравнивал за последние годы не один раз и на разных задачах. Но на вызове пустой функции вполне логично что разница в скорости увеличивается капитально.

Так что Ваши цифры меня уже не смущают — вызов (практически) пустой функции действительно может работать в .NET/Mono с такой скоростью.

[@outcoldman]

Не обижайтесь, но ваш тест похож на что-то типа «а сломается ли велосипед, если на нем гнать 300 км/ч?». Все догадываются, что сломается, но так же все знают, что только у одаренных получиться как-то разогнаться до 300км/ч. :-)

[@exmachine]

Спасибо, но не обижаюсь.
Продолжу, аналогию с велосипедом. Прежде чем разгоняться до любой скорости, следует подумать: успеваем ли рулить, как будем останавливаться.

[@catlion]

У вас во второй таблице колонки NLog и Log4Net не перепутаны?

[@catlion]

И да, я уже не вспомню, почему я когда-то остановился на NLog, но с тех пор у меня не возникло ни одной причины рассматривать что-то другое.

[@exmachine]

Перепутаны. Благодарю. Поправил. 8-)

[@LexL]

Портировать код тоже надо уметь — переименовать файлы log4j в cs и исправить синтаксические ошибки — это только полдела. Надо еще знать сильные и слабые места платформы. А если еще файлы конфигурации облагородить — тогда…

Ну тогда получится что-то типо NLog ;)

[@victorI]

у нас используется log4net, в разных бизнес-процессах по-разному, но есть такие, которые генерируют порядка 1Гб логов за 5мин работы, так что отключения логгирования — одно из основных требований по тестировании производительности. Даже специальные задачи на подмодули заводятся, чтоб они могли переключать режимы логгирования без рестарта сервисов.
Потом есть еще такой микро нюанс, что даже если у вас в коде log4net пишет в дебаг, то ToString() у параметров вызовется в любом случае, и иногда в продакшене там оказываются десятки и сотни мегабайт. Лог вроде и не пишется, но OutOfMemory тут как тут )))

[@victorI]

а по статье выводы очень интересные получаются, действительно, для систем, которые сделаны, как у нас говорят, через Log Driven Development, с очень большим кол-вом лог вызовов, переход на NLog может иметь вполне определенные бенефиты.