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

РЕДАКТИРОВАТЬ 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, вывод будет:

Done in 511 ms

Принимая во внимание, что прохождение BufferingForwardingAppender украшает RollingFileAppender:

Done in 14261 ms

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

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

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

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

Спасибо!

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

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

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

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

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

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get _Имя пользователя()

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

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

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

Спасибо!