log4net BufferingForwardingAppenderパフォーマンスの問題

Question

EDIT 2：私はこの問題を解決しました（下記の回答を参照してください）問題は、BufferingForwardingAppenderとBufferingAppenderSkeletonを継承しているすべてのアペンダーに影響する可能性があることに注意してください（それぞれAdoNetAppender、RemotingAppender、SmtpAppender、 SmtpPickupDirAppender）*

私はlog4netの非常に基本的なベンチをやっていました。私は、BufferingForwardingAppenderでRollingFileAppenderを装飾しようとしました。

私は、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から直接出力を行くされています

に完了

511ms

RollingFileAppenderを飾るBufferingForwardingAppenderを経一方

：約30倍遅くだ14261ミリ秒

に完了

。

私は、ファイルに書き込む前に特定の量のログをバッファリングすることでスピードを上げることができたと思っていましたが、なんらかの理由でそれがさらに悪化しました。

私は設定がOKであるように見えます、これは本当に変です。

誰かが手掛かりを得ましたか？

ありがとうございます！

EDIT 1：

行動は（まだlog4netの公式設定サンプル中の基本BufferingForwardingAppenderラッピング/飾るConsoleAppenderの例があり、厳密ConsoleAppenderを/ラップさえFileAppenderかを飾ることにより、同じ..ですし、何もパフォーマンスに特有の言及）。

調査/プロファイリングを行った後、私は、WindowsIdentity.GetCurrent（）の呼び出しでBufferingForwardingAppender内部で大部分の時間が損なわれていることがわかります。毎回Log.Debug()を呼び出しています。前のサンプル（上記のサンプルソースでは100K回）に表示されます。

このメソッドを呼び出すと、非常にコストがかかるので、避けるか、最小限に抑える必要があります。なぜ、各ログイベントに対して呼び出されるのか、実際にはわかりません。 私は本当に完全に何かを間違って設定していますか、何かが明白でないか、どこかにバグがありましたが、これは私が現在考えようとしていることです...

部分コールスタックは、次のとおりget_LocationInformation()に

• AppenderSkeleton.DoAppend
• BufferingAppenderSkeleton.Append
• LoggingEvent.FixVolatileData
• LoggingEvent.get_UserName（）

コールされますまた、FixVolatileDataで実行され、高いパーフォーマンスも発生します（s毎回タックトレース）。

私は今、このコンテキストで各ログイベントに対して（FixPolder ...を直接経由して）ラップされたアペンダを経由するのに対して、この非常に高価なFixVolatileData呼び出しが発生する理由を理解しようとしています。この種の操作を実行します。誰かがこのすべてに答えを得た場合を除き、フォローする

今後のアップデート;）

ありがとう！

Answer 1

私はこの問題を発見しました。 （例えばAdoNetAppender、RemotingAppender、SmtpAppenderような緩衝ロギングイベントを利用する他のアペンダであるように..）

BufferingForwardingAppenderがBufferingAppenderSkeletonから継承されています。

BufferingAppenderSkeletonは実際に特定の条件が満たされると（たとえば、バッファがいっぱい）、ターゲットアペンダに実際に配信する前にロギングイベントをバッファしています。 LoggingEventクラスのドキュメントによると

（ロギングイベントを表し、イベントのすべての値を（メッセージ、スレッドID ...）を含む）：

プロパティは、「揮発性」と考えられているいくつかのログイベント、つまり、 の値は、イベントがアペンダーに配信された時点では正確であり、 ですが、後でいつでも一致しません。イベントが に保存され、後で処理される場合、これらの揮発性値 はFixVolatileDataを呼び出すことで修正する必要があります。パフォーマンスがあり ペナルティFixVolatileDataを呼び出すことによって被ったが、あるはこれらの「揮発性」の性質は、このようなメッセージ、のthreadName、ユーザー名、アイデンティティとしてフラグを含むFixFlags列挙で表現されているデータの一貫性に

を維持 に不可欠です...すべての揮発性のプロパティ。 フラグ "None"（プロパティを修正しない）、 "すべて"（すべてのプロパティを修正する）、 "Partial"（事前定義されたプロパティのdsetのみを修正する）も含まれます。

Whehem BufferingAppenderSkeletonがDEFAULTによって固定され、すべての "揮発性"プロパティを固定する必要があることを意味する "All"に固定を設定します。

この状況では、BufferingAppenderSkeletonに追加されたLoggingEventごとに、イベントがバッファに挿入される前にすべての「volatile」プロパティが修正されます。これらのプロパティがレイアウトに含まれていなくても、これにはプロパティIdentity（username）とLocationInformation（スタックトレース）が含まれています（ただし、バッファが後でこれらのプロパティを含むようにレイアウトが変更された場合、 LoggingEventsで既に満たされています）。

私の場合、これは実際にはパフォーマンスが悪いです。私は私のレイアウトでアイデンティティおよびLocationInformation含めていないですし、解決のための今すぐ

（主にパフォーマンスの問題のため）に予定していない...

使用することができますBufferingAppenderSkeletonに2つのプロパティがあります。 BufferingAppenderSkeletonのフラグ値をFixFlagsに設定してください（デフォルトでは、これは "ALL"に設定されていますが、あまりうれしくありません）。 これらの2つのプロパティは、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> 

この変更された構成を使用して、ベンチマークのコードの実行がで提示私上記の質問は、約14000msから230ms（60倍速く）に低下しています。 すべての修正を無効にする代わりに<OnlyFixPartialEventData value="true"/>を使用すると、約350msかかることになります。

悲しいことに、このフラグはあまり詳しくは書かれていません（SDKのドキュメントを除いて少しです）。問題を見つけるためにlog4netソースを詳細に調べなければなりませんでした。

これは、特に "リファレンス"構成サンプルで特に問題があります。このフラグはどこにも表示されません（http://logging.apache.org/log4net/release/config-examples.html）。 したがって、BufferingForwardingAppenderとAdoNetAppender（およびBufferingAppenderSkeletonを継承する他のアペンダー）に提供されたサンプルは、使用するレイアウトがごくわずかであっても、ユーザーに驚異的なパフォーマンスをもたらします。

Answer 2

は、ユーザ名（％のユーザー名）の下

含めて出力されているのIT可能あなたがBufferingForwardingAppenderにレイアウトパターンを指定していないので、それはだが、あなたはRollingLogFileAppenderにしたがって、BufferingForwardingAppenderはそれのすべてを含めているされていることです興味深いブログ記事で、パターンレイアウトのオプションのリストがあり、彼には遅いとマークされたものがいくつかあるようです。

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