Библиотека 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 (таймер высокого разрешения до тактов).
В log4net для записи логов в файл есть FileAppender. В нём реализована возможность эксклюзивной блокировки (используется по умолчанию) и, так называемой, MinimalLock. ExclusiveLock при инициализации log4net открывает файл для записи с возможностью чтения для остальных процессов. MinimalLock выполняет открытие/закрытие файла на каждую запись в файл. Соответственно, ExclusiveLock нам не подходит совсем (поскольку файл для всех процессов, кроме первого, который захватил блокировку над файлом, будет недоступен), а у MinimalLock есть ряд серьёзных недостатков:
В поиске достойной замены я набрёл на статью 2008 года на Code Project — Logging into single file from multi-process. В статье описывается реализация ConcurrentMinimalLock, в которой производится буферизация сообщений, а также выполняется открытие файла в цикле (пока блокировка-таки не будет установлена). Вроде бы всё хорошо, однако время вызова метода логирования 1:04 из 1:20. Т.е. по-прежнему долго. И это ещё с учётом того, что это частично асинхронное логирование (при жёстком закрытии приложения всё из очередей будет потеряно).
В моих изысканиях я был очень удивлён, что никто не хочет использовать банальные мьютексы (Mutex), ведь их основное назначение — кросс-процессная синхронизация. Поэтому я решил написать собственный Appender, который бы выполнял синхронизацию между процессами с помощью мьютекса. Для создания Appender'а необходимо следующее:
В момент инициализации мы открываем FileStream в режиме записи, но при этом указываем FileShare read-write. Т.е. остальные процессы смогут читать-писать в этот файл параллельно. Жаль нет способа сделать файл только чтения для всех, кто не ConcurrentFileAppender, чтобы тех. поддержка не могла править файлы (случайно, конечно же) онлайн. То, что мы держим файл открытым даёт нам возможность не тратить лишнее время на открытие, как это делается в предыдущих реализациях.
Метод банально в цикле проверяет очередь на непустоту. Если очередь непуста — копируем её содержимое, очищаем и сбрасываем на диск.
Накопленные в очереди сообщения сначала записываются в буфер, а потом уже этот буфер целиком вымещается на диск, чтобы не делать последовательные вызовы Write. Ещё важный момент — выполнять Seek перед записью, поскольку текущее положение курсора файла кешируется.
В конце концов был написан базовый класс ConcurrentAppenderSkeleton:
И наследники: 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.
Как видно из таблицы, при использовании блокировки мьютексом только на время ввода-вывода, очередь сообщений меньше, что несколько повышает надёжность. При необходимости использовать функциональность RollingFileAppender имеет смысл пользоваться ConcurrentForwardingAppender в связке с ConcurrentMinimalLock, хотя лучше написать свой вариант Lock, который не будет двойную буферизацию делать.
Два главных преимущества Concurrent*Appender'ов: многопроцессовость и практическое отсутствие замедления в работе основного приложения при включённом логировании.
В процессе оформления статьи заметил ошибку в подсчете общего времени и вызова метода logger.Debug. С не моими appender'ами всё оказалось ещё хуже, а с моими ещё лучше :) Но обновлять исходную таблицу результатов уже не стал, т.к. долго очень, извините (ошибка в том, что в log4net.Extensions.Console доступ к экземпляру Stopwatch был несинхронизированным + надо было делить значение на 8).
Ссылки:
Сразу оговорюсь про тестовое окружение, поскольку в своих доводах я буду опираться на результаты тестов. Процессор 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);
- Конфликт блокировок, когда несколько процессов пытаются получить поток для записи (а это обозначает не запись в лог).
<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).
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).
Ссылки:
- Официальная страница log4net
- System.Threading.Mutex — класс, реализующий функциональность мьютекса в .NET Framework
- Logging into single file from multi-process (логирование в один файл из нескольких процессов)
