РЕДАКТИРОВАТЬ 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(). в предыдущем примере (100 К раз в источнике выборки выше).
Звонки на этот метод, как известно, очень дорогостоящие, их следует избегать или минимизировать, я действительно не понимаю, почему он вызван для каждого события журнала. Неужели я действительно полностью неправильно настраиваю что-то или не вижу что-то очевидное, или это что-то ошибка где-то, вот что я пытаюсь выяснить сейчас...
Стек частичного вызова:
- AppenderSkeleton.DoAppend
- BufferingAppenderSkeleton.Append
- LoggingEvent.FixVolatileDatali >
- LoggingEvent.get_UserName()
Вызов get_LocationInformation() также выполняется в FixVolatileData, что также приводит к высокой первоначальной стоимости (каждый раз отслеживать трассировку стека).
Теперь я пытаюсь понять, почему этот чрезвычайно дорогостоящий вызов FixVolatileData (по крайней мере, для исправления) возникает для каждого события журнала в этом контексте, тогда как переход непосредственно через завернутый appender (непосредственно через ConsoleAppender/FileAppender..) не выполняется этот вид операции.
Предстоящее обновление, за которым следует, если кто-то не получил ответ на все это:)
Спасибо!
