編集2:問題を解決しました(以下の回答を参照)この問題は、BufferingForwardingAppenderで装飾されたすべてのアペンダーと、BufferingAppenderSkeletonから継承したすべてのアペンダー(それぞれ:AdoNetAppender、RemotingAppender、SmtpAppender、SmtpPickupDirAppender)に影響を与える可能性があることに注意してください*
私はlog4netの非常に基本的なベンチをいくつか実行していて、RollingFileAppenderをBufferingForwardingAppenderで装飾しようとしました。
RollingFileAppenderを直接経由するのではなく、BufferingForwardingAppenderを経由すると、ひどいパフォーマンスが発生しますが、その理由はわかりません。
これが私の設定です:
<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ミリ秒で完了
RollingFileAppenderを飾るBufferingForwardingAppenderを通過するのに対して:
14261ミリ秒で完了
これは約30倍遅くなります。
ファイルに書き込む前に一定量のログをバッファリングすることである程度の速度が得られると思いましたが、何らかの理由で事態はさらに悪化します。
設定はOKのように思えるので、これは本当に奇妙です。
誰かが手がかりを得ましたか?
ありがとう!
編集1:
FileAppenderまたはConsoleAppenderをラップ/装飾することで動作は厳密に同じです(log4netの公式構成サンプルにConsoleAppenderをラップ/装飾する基本的なBufferingForwardingAppenderの例がありますが、パフォーマンスに関する具体的な言及はありません)。
Log.Debug()
調査/プロファイリングを行った後、ほとんどの時間はBufferingForwardingAppender内で台無しになっていることがわかります。具体的には、WindowsIdentity.GetCurrent()の呼び出しで...前のサンプルで..を呼び出すたびに呼び出されます(上記のサンプルソースで100K回)。
このメソッドの呼び出しは非常にコストがかかることが知られており、回避または最小化する必要があります。ログイベントごとに呼び出される理由がわかりません。私は本当に何かを完全に誤って構成しているのですか/何か明らかなものが見られないのですか、それともどこかにバグがあるのですか、これは私が今理解しようとしていることです...
部分的な呼び出しスタックは次のとおりです。
- AppenderSkeleton.DoAppend
- BufferingAppenderSkeleton.Append
- LoggingEvent.FixVolatileData
- LoggingEvent.get_UserName()
の呼び出しget_LocationInformation()
もFixVolatileDataで行われ、パフォーマンスコストも高くなります(毎回スタックトレースをキャプチャします)。
私は今、この非常にコストのかかるFixVolatileData呼び出し(少なくとも要求された修正に対して)がこのコンテキストの各ログイベントで発生するのに対し、ラップされたアペンダーを直接通過する(ConsoleAppender / FileAppender ..を直接通過する)ことがこの種の実行を行わない理由を理解しようとしています。手術。
誰かがこのすべてに対する答えを得ない限り、フォローする今後のアップデート;)
ありがとう!