log4net проблема производительности BufferingForwardingAppender

Question

РЕДАКТИРОВАТЬ 2: Я решил проблему (см. Ответ ниже). Обратите внимание, что эта проблема потенциально затрагивает все аппендеры, украшенные BufferingForwardingAppender, а также все аппендеры, наследуемые от BufferingAppenderSkeleton (соответственно: AdoNetAppender, RemotingAppender, SmtpAppender и SmtpPickupDirAppender) *

Я делал несколько базовых тестов log4net и пытался украсить RollingFileAppender с помощью BufferingForwardingAppender.

Я испытываю ужасную производительность при использовании BufferingForwardingAppender, а не непосредственно через RollingFileAppender, и я действительно не понимаю причину.

Вот моя конфигурация:

<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
  <file value="c:\" />
  <appendToFile value="false" />
  <rollingStyle value="Composite" />
  <datePattern value="'.'MMdd-HH'.log'" />
  <maxSizeRollBackups value="168" />
  <staticLogFileName value="false" />
  <layout type="log4net.Layout.PatternLayout">      
    <conversionPattern value="%date [%thread] %-5level %logger - %message%newline" />
  </layout>
</appender>

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
</appender>

<root>
  <level value="DEBUG" />
  <appender-ref ref="BufferingForwardingAppender" />    
</root>

А вот эталонный тест (очень простой код):

var stopWatch = new Stopwatch();
stopWatch.Start();            
for (int i = 0; i < 100000; i++)            
{
   Log.Debug("Hello");
}
stopWatch.Stop();
Console.WriteLine("Done in {0} ms", stopWatch.ElapsedMilliseconds);

Пройдя напрямую через RollingFileAppender, вы получите:

Совершено за 511 мс

Принимая во внимание, что через BufferingForwardingAppender, украшающий RollingFileAppender:

Совершено в 14261 мс

Это примерно в 30 раз медленнее.

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

Мне кажется, что конфигурация в порядке, так что это действительно странно.

Кто-нибудь понял?

Спасибо!

РЕДАКТИРОВАТЬ 1:

Поведение является точно таким же, если обернуть / декорировать FileAppender или даже ConsoleAppender (все еще есть пример базового BufferingForwardingAppender обертывания / декорирования ConsoleAppender в образцах официальной конфигурации log4net... и ничего конкретного не упоминалось о производительности).

После некоторого исследования / профилирования я вижу, что большая часть времени портится в BufferingForwardingAppender более конкретно при вызове WindowsIdentity.GetCurrent() ... вызывается КАЖДЫЙ раз, когда мы делаем вызов Log.Debug().. в предыдущем примере (100K раз в примере источника выше).

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

Частичный стек вызовов:

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get_UserName ()

Вызов get_LocationInformation() это также делается в FixVolatileData, что влечет за собой высокую стоимость перфорирования (каждый раз перехватывает трассировку стека).

Теперь я пытаюсь понять, почему этот чрезвычайно дорогой вызов FixVolatileData (по крайней мере, для запрашиваемого исправления) происходит для каждого события журнала в этом контексте, тогда как прохождение напрямую через завернутый appender (напрямую через ConsoleAppender/FileAppender ..) не выполняет этот вид операция.

Предстоящее обновление, чтобы следовать, если кто-то не получил ответ на все это;)

Спасибо!

Answer 1

Я выяснил проблему.

BufferingForwardingAppender наследуется от BufferingAppenderSkeleton (как и другие приложения, использующие буферизацию событий журнала, такую ​​как AdoNetAppender, RemotingAppender, SmtpAppender..).

BufferingAppenderSkeleton на самом деле буферизует события регистрации перед фактической доставкой целевому приложению, когда определенное условие выполнено (например, заполнен буфер).

Согласно документации LoggingEvent класс (представляющий событие регистрации и содержащий все значения (message, threadid...) события):

Некоторые свойства событий журналирования считаются "изменчивыми", то есть значения являются правильными во время доставки события аппендерам, но впоследствии они не будут согласованными. Если событие должно быть сохранено и обработано позднее, эти изменчивые значения должны быть исправлены вызовом FixVolatileData. Вызывает FixVolatileData снижение производительности, но это важно для поддержания согласованности данных

Эти "летучие" свойства представлены FixFlags перечисление, содержащее флаги, такие как Message, ThreadName, UserName, Identity ... так что все переменные свойства. Он также содержит флаги "Нет" (не исправить свойства), "Все" (исправить все свойства) и "Частично" (исправить только определенный заранее определенный набор свойств).

Где BufferingAppenderSkeleton Например, по умолчанию DEFAULT устанавливает фиксирование "Все", что означает, что все "изменчивые" свойства должны быть фиксированы.

В этом контексте для каждого LoggingEvent, добавляемого в BufferingAppenderSkeleton, ВСЕ "изменчивые" свойства будут зафиксированы до того, как событие будет вставлено в буфер. Это включает в себя свойства Identity (имя пользователя) и LocationInformation (трассировка стека), даже если эти свойства не включены в макет (но я полагаю, что имеет какой-то смысл, если макет будет изменен для включения этих свойств в более позднее время в то время как буфер уже был заполнен LoggingEvents).

Тем не менее, в моем случае это действительно больно. Я не включаю Identity и LocationInformation в свой макет и не планирую (в основном из-за проблем с производительностью)

Теперь для решения...

Есть два свойства в BufferingAppenderSkeleton который может быть использован для управления FixFlags значение флага BufferingAppenderSkeleton (еще раз по умолчанию он установлен на "ВСЕ", что не очень приятно!). Эти два свойства Fix (Тип FixFlags) и OnlyFixPartialEventData (тип bool).

Для точной настройки значения флага или отключения всех исправлений Fix свойство должно быть использовано. Для определенной частичной предопределенной комбинации флагов (не включая Identity или LocationInfo), OnlyFixPartialEventData вместо этого можно установить значение true.

Если я повторно использую образец конфигурации выше (в моем вопросе), единственное изменение, внесенное в конфигурацию для повышения производительности, указано ниже:

<appender name="BufferingForwardingAppender" type="log4net.Appender.BufferingForwardingAppender">
  <bufferSize value="512" />
  <appender-ref ref="RollingLogFileAppender" />
  <Fix value="0"/> <!-- Set Fix flag to NONE -->
</appender>

При использовании этой модифицированной конфигурации выполнение кода теста, представленное в моем вопросе выше, снижается с приблизительно 14000 мс до 230 мс (в 60 раз быстрее)! И если я использую <OnlyFixPartialEventData value="true"/> вместо отключения всех исправлений требуется около 350 мс.

К сожалению, этот флаг не очень хорошо задокументирован (за исключением немного документации SDK) ... поэтому мне пришлось углубиться в источники log4net, чтобы найти проблему.

Это особенно проблематично, особенно в "эталонных" примерах конфигурации, этот флаг нигде не отображается (http://logging.apache.org/log4net/release/config-examples.html). Таким образом, примеры, предоставленные для BufferingForwardingAppender и AdoNetAppender (и других приложений, унаследованных от BufferingAppenderSkeleton), дадут УЖАСНУЮ производительность пользователям, даже если используемый ими макет довольно минимален.

Answer 2

Возможно, это потому, что вы не указываете шаблон макета в BufferingForwardingAppender но ты в RollingLogFileAppender Следовательно BufferingForwardingAppender включает в себя все в своем выводе, включая имя пользователя (%username)

Ниже приведена интересная статья в блоге, в которой есть список параметров макетов шаблонов, и похоже, что некоторые из них помечены как медленные.

http://www.beefycode.com/post/Log4Net-Tutorial-pt-4-Layouts-and-Patterns.aspx