Расширяем log4net. Конкурентное логирование

    Библиотека log4net известна и в представлении не нуждается. В ней есть практически всё, что нужно, «из коробки». Однако, есть специфические ситуации, в которых необходимо добавлять/расширять функциональность библиотеки. Конкретная ситуация: есть некоторая библиотека, которая выполняет логирование через log4net в некоторый логер (или несколько — не суть). Эта библиотека используется в N службах. Как сделать так, чтобы логирование происходило в единственный файл? Под катом объяснение, почему FileAppender+MinimalLock не подходит, и реализация Appender'а, который решает задачу. Отдельно хочу сказать, что вопрос о логировании в БД, по сети и т.п. в статье не рассматривается, т.к. это гораздо более серьёзная задача, которая (особенно для больших систем) требует длительного обдумывания и внедрения.



    Сразу оговорюсь про тестовое окружение, поскольку в своих доводах я буду опираться на результаты тестов. Процессор i7 (4 ядра, 8 с учётом hyper-threading), приложение log4net.Extensions.Console выполняет в 8 потоках запись в лог с произвольным Sleep после записи. Количество записей в лог — 10000. Приложение BulkStarter запускает 10 экземпляров log4net.Extensions.Console и дожидается их выполнения. Таким образом, 10 процессов, по 8 потоков в каждом выполняют запись в единственный файл. Все временные характеристики были получены в таком тесте с помощью Stopwatch (таймер высокого разрешения до тактов).

    FileAppender+MinimalLock


    В log4net для записи логов в файл есть FileAppender. В нём реализована возможность эксклюзивной блокировки (используется по умолчанию) и, так называемой, MinimalLock. ExclusiveLock при инициализации log4net открывает файл для записи с возможностью чтения для остальных процессов. MinimalLock выполняет открытие/закрытие файла на каждую запись в файл. Соответственно, ExclusiveLock нам не подходит совсем (поскольку файл для всех процессов, кроме первого, который захватил блокировку над файлом, будет недоступен), а у MinimalLock есть ряд серьёзных недостатков:
    • Очень медленный (из 1:56 теста, непосредственно вызовы метода логирования заняли 1:40);
    • Конфликт блокировок, когда несколько процессов пытаются получить поток для записи (а это обозначает не запись в лог).
    Пример конфигурации FileAppender'а с MinimalLock:
    <appender name="FileAppender" type="log4net.Appender.FileAppender">
    	<file value="D:\1\test-minlock.log"/>
    	<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
    	<layout type="log4net.Layout.PatternLayout">
    		<conversionPattern value="%message%n"/>
    	</layout>
    </appender>
    

    ConcurrentMinimalLock


    В поиске достойной замены я набрёл на статью 2008 года на Code Project — Logging into single file from multi-process. В статье описывается реализация ConcurrentMinimalLock, в которой производится буферизация сообщений, а также выполняется открытие файла в цикле (пока блокировка-таки не будет установлена). Вроде бы всё хорошо, однако время вызова метода логирования 1:04 из 1:20. Т.е. по-прежнему долго. И это ещё с учётом того, что это частично асинхронное логирование (при жёстком закрытии приложения всё из очередей будет потеряно).

    ConcurrentFileAppender


    В моих изысканиях я был очень удивлён, что никто не хочет использовать банальные мьютексы (Mutex), ведь их основное назначение — кросс-процессная синхронизация. Поэтому я решил написать собственный Appender, который бы выполнял синхронизацию между процессами с помощью мьютекса. Для создания Appender'а необходимо следующее:
    • Унаследоваться от абстрактного класса log4net.Appender.AppenderSkeleton;
    • Реализовать метод ActivateOptions, в котором выполняется инициализация Appender'а;
    • Реализовать методы Append, принимающие один LoggingEvent и массив LoggingEvent.
    • Реализовать метод OnClose, который очищает ресурсы (аналог Dispose в log4net).
    Основная идея — сообщения добавлять в синхронизированную очередь (с помощью Monitor), а в отдельном потоке выполнять запись в файл, используя для синхронизации доступа к файлу именованый мьютекс (по полному пути к файлу).

    ActivateOptions


    В момент инициализации мы открываем FileStream в режиме записи, но при этом указываем FileShare read-write. Т.е. остальные процессы смогут читать-писать в этот файл параллельно. Жаль нет способа сделать файл только чтения для всех, кто не ConcurrentFileAppender, чтобы тех. поддержка не могла править файлы (случайно, конечно же) онлайн. То, что мы держим файл открытым даёт нам возможность не тратить лишнее время на открытие, как это делается в предыдущих реализациях.
    public override void ActivateOptions()
      Dispose(true); // flush на случай повторной инициализации
      
      base.ActivateOptions();
    
      // проверки на корректность опущены для компактности  
      var path = SystemInfo.ConvertToFullPath(Path);
      var dir = System.IO.Path.GetDirectoryName(path);
      if (!Directory.Exists(dir))
          Directory.CreateDirectory(dir);
    
      _loggingEvents = new Queue<LoggingEvent>(QueueInitialCapacity);
      
      FileStream stream = null;
      Mutex mutex = null;
      try
      {
          stream = File.Open(path, FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
          mutex = CreateMutex(path);
      
          _thread = new Thread(ThreadProc)
          {
              Name = "ConcurrentFileAppenderListener",
              IsBackground = true // logging thread should not prevent an application exit
          };
          _thread.Start();
      
          _stream = stream;
          stream = null;
      
          _mutex = mutex;
          mutex = null;
      
          if (FlushOnProcessExit)
              AppDomain.CurrentDomain.ProcessExit += delegate { OnProcessExit(path); };
      }
      finally
      {
          if (stream != null)
              stream.Dispose();
          if (mutex != null)
              mutex.Close();
      }
    }
    


    ThreadProc


    Метод банально в цикле проверяет очередь на непустоту. Если очередь непуста — копируем её содержимое, очищаем и сбрасываем на диск.
    private void ThreadProc()
    {
        var culture = CultureInfo.InvariantCulture;
    
        while (true)
        {
            if (!_nonEmptyQueue) // несинхронизированный доступ к полю типа bool не сулит ничего страшного
            {
                Thread.Sleep(QueueEmptyCheckTimeoutInMilliseconds);
                continue;
            }
    
            lock (QueueSyncRoot)
            {
                _currentProcessingEvents = _loggingEvents.ToArray();
                _loggingEvents.Clear();
                _nonEmptyQueue = false;
            }
    
            Flush(_mutex, _stream, culture, _currentProcessingEvents);
            _currentProcessingEvents = null;
        }
    }
    


    Flush


    Накопленные в очереди сообщения сначала записываются в буфер, а потом уже этот буфер целиком вымещается на диск, чтобы не делать последовательные вызовы Write. Ещё важный момент — выполнять Seek перед записью, поскольку текущее положение курсора файла кешируется.
    private void Flush(Mutex mutex, FileStream stream, CultureInfo culture, ICollection<LoggingEvent> events)
    {
        if (events.Count <= 0)
            return;
    
        byte[] buffer;
        using (var sw = new StringWriter(culture))
        {
            foreach (var e in events)
                RenderLoggingEvent(sw, e);
            buffer = Encoding.GetBytes(sw.ToString());
        }
    
        try
        {
            mutex.WaitOne();
    
            stream.Seek(0, SeekOrigin.End);
            stream.Write(buffer, 0, buffer.Length);
            stream.Flush();
        }
        finally
        {
            mutex.ReleaseMutex();
        }
    }
    


    Окончательная реализация


    В конце концов был написан базовый класс ConcurrentAppenderSkeleton:
    public abstract class ConcurrentAppenderSkeleton : AppenderSkeleton, IDisposable
    {
    	/// <summary>
    	/// Gets a name for a <see cref="Mutex"/>.
    	/// </summary>
    	protected abstract string UniqueMutexName { get; }
    	
    	/// <summary>
    	/// Performs initialization of an appender. Should throw exception if cannot be initialized.
    	/// </summary>
    	protected abstract void ActivateOptionsInternal();
    	
    	/// <summary>
    	/// Prepares data to a flushing.
    	/// </summary>
    	/// <remarks>
    	/// <para>This method executes in a thread safe context (under <see cref="Monitor"/> lock).</para>
    	/// </remarks>
    	/// <param name="events">Logging events.</param>
    	/// <returns>A prepared data.</returns>
    	protected abstract object PrepareData(LoggingEvent[] events);
    	
    	/// <summary>
    	/// Flushes prepared data.
    	/// </summary>
    	/// <remarks>
    	/// <para>This method executes in a thread-safe context (under mutex).</para>
    	/// </remarks>
    	/// <param name="data">A prepared data to a flushing.</param>
    	protected abstract void Flush(object data);
    }
    

    И наследники: ConcurrentFileAppender и ConcurrentForwardingAppender (по аналогии с BufferingForwardingAppender). Последний позволяет выполнять запись (Flush) в набор других Appender'ов. Важно, чтобы эти другие Appender'ы не делали эксклюзивных блокировок (т.е. FileAppender+ExclusiveLock использовать нельзя), а так они будут синхронизированы мьютексом.

    В тестовых целях я добавил настройку — в каком месте синхронизироваться по мьютексу: либо сразу перед получением сообщений из очереди, либо только для записи в файл. В первом случае происходит увеличение количества очереди (за счёт более длительных блокировок, т.к. они включают форматирование и запись), но некоторое сокращение затрат на ввод-вывод (поскольку 10 записей по 10Кб быстрее делаются, чем 100 по 1Кб). Во втором случае очередь растёт не очень сильно, нахождение в блокировке минимально (только время на сам ввод-вывод), что более масштабируемо.

    Испытания


    Напомню, что тест — это запись в лог 500 Мб из 10 процессов по 8 потоков в каждом. В таблице ниже результаты для различных тестов. ConcurrentFileAppender будет отображаться сокращённо как File, ConcurrentForwardingAppender (запись ведеётся в FileAppender+MinimalLock) как Fwd+Min, а также экзотический вариант — ConcurrentForwardingAppender, где запись ведётся в FileAppender с ConcurrentMinimalLock, будет обозначаться как Fwd+Con. Время Sleep для опроса очереди — 10мс. Mutex.WaitOne только для записи будет обозначен как IO, для форматирования и записи — Whole.

    Время (с) \ Тест MinLock Concurrent MinLock File IO File Whole Fwd+Min IO Fwd+Min Whole Fwd+Con IO Fwd+Con Whole
    Общее время 116,6 79,7 11,27 11,6 11,96 11,61 11,7 11,61
    logger.Debug 100,36 64,68 0,08 0,07 0,07 0,07 0,08 0,07
    Ср. длина очереди - - 9 40 185 169 17 25

    Как видно из таблицы, при использовании блокировки мьютексом только на время ввода-вывода, очередь сообщений меньше, что несколько повышает надёжность. При необходимости использовать функциональность RollingFileAppender имеет смысл пользоваться ConcurrentForwardingAppender в связке с ConcurrentMinimalLock, хотя лучше написать свой вариант Lock, который не будет двойную буферизацию делать.

    Два главных преимущества Concurrent*Appender'ов: многопроцессовость и практическое отсутствие замедления в работе основного приложения при включённом логировании.

    P.S.


    В процессе оформления статьи заметил ошибку в подсчете общего времени и вызова метода logger.Debug. С не моими appender'ами всё оказалось ещё хуже, а с моими ещё лучше :) Но обновлять исходную таблицу результатов уже не стал, т.к. долго очень, извините (ошибка в том, что в log4net.Extensions.Console доступ к экземпляру Stopwatch был несинхронизированным + надо было делить значение на 8).

    Ссылки:
    Файлы:

    Похожие публикации

    AdBlock похитил этот баннер, но баннеры не зубы — отрастут

    Подробнее
    Реклама

    Комментарии 16

      +2
      А поправьте меня, если я ошибаюсь — разве проект log4net не был заброшен 5 лет назад (по крайней мере этой датой датируются последние багфиксы на официальном сайте)? Я неоднократно встречал людей, отдающих предпочтение NLog на основании того, что последний активно развивается, в отличии от log4net.
        0
        В SVN последняя ревизия 4 сделана 4 месяца назад, так что видать не совсем еще заброшен
          0
          4 месяца назад — фикс одного плагина в пару строк кода. Последний фикс ядра — 20 месяцев назад (тоже пару строк), до этого — 3 года назад. Последний стабильный билд — 4 года назад.
          +3
          В принципе, да, log4net не развивается.

          Вот тут — stackoverflow.com/questions/710863/log4net-vs-nlog коллективный разум их сравнивает, Nlog'у отдаётся предпочтение.
            0
            Кстати, в NLog есть реализация блокировки файла мьютексом (свойство ConcurrentWrites у FileTarget). Надо бы поглубже изучить библиотеку.
            0
            Неплохо, но при такой постановки задачи я бы исспользовал Message Queue.
              0
              Да, я сразу оговорился, что менять схему логирования — задача иного уровня. По-хорошему необходимо более чётко продумывать логирование/мониторинг (БД, типы сообщений и т.п.).
              0
              хорошо так. но есть пара замечаний:
              1. методы помещения в очередь [как он у вас называется?] и ThreadProc лучше сделать на Monitor.Pulse() | Monitor.Wait(), чтобы не засыпать в цикле на длинную константу[?] QueueEmptyCheckTimeoutInMilliseconds
              2. log4net, конечно, мощь. но уж очень монструозная. и как говорили коментаторы выше – подзаброшенная.
                0
                1. Да, Вы абслоютно правы, с Monitor Pulse/Wait лучше должно быть. Сейчас просто в lock (syncObject) делается Enqueue у Queue, а QueueEmptyCheckTimeoutInMilliseconds по умолчанию 10мс.
                2. Да уж. Странно, что Apache Foundation не занимается развитием библиотеки.
                  0
                  Проверил, logger.Debug несколько дольше дольше вызывается (раза в полтора), зато средняя длина очереди сократилась до 1,25-1,5, т.е. более надёжно.
                  +1
                  Хмм, а я использую log4net… везде… и ColoredConsoleAppender, который вообще рулит :)
                  Ну и что что никто ничего к библиотеке не дописыват? Значит она уже идеальна!
                    0
                    простите, а вы смотрели исходники «идеальной» библиотеки?
                      0
                      нет
                        0
                        посмотрите. возможно, это одна из причин, по которой никто к ней ничего не дописывает.
                          0
                          так а не надо ничего дописывать… лично меня все устраивает
                            0
                            Главное пользоваться чем-нибудь типа Common.Logging (wrapper над популярным логирующими системами), чтобы не было мучительно больно при переходе с «теперь уже неустрающего» фрейморка на другой. Всё меняется, понадобится подобная функционально, как я описал, а окажется, что без переписывания библиотеки не выйдет…

                  Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                  Самое читаемое