26

編集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 ..を直接通過する)ことがこの種の実行を行わない理由を理解しようとしています。手術。

誰かがこのすべてに対する答えを得ない限り、フォローする今後のアップデート;)

ありがとう!

4

2 に答える 2

45

私はその問題を見つけました。

BufferingForwardingAppenderから継承してBufferingAppenderSkeletonいます(、、、などのロギングイベントバッファリングを利用する他のアペンダーとAdoNetAppender同様RemotingAppenderSmtpAppender

BufferingAppenderSkeleton、特定の条件が満たされると(たとえば、バッファがいっぱいになると)、実際にログイベントをターゲットアペンダーに配信する前に、実際にバッファリングします。

クラスのドキュメントによるとLoggingEvent(ロギングイベントを表し、イベントのすべての値(message、threadid ...)が含まれています):

一部のロギングイベントプロパティは「揮発性」と見なされます。つまり、イベントがアペンダーに配信された時点では値は正しいですが、その後はいつでも一貫性がなくなります。イベントを保存して後で処理する場合は、FixVolatileDataを呼び出してこれらの揮発性の値を修正する必要があります。FixVolatileDataを呼び出すとパフォーマンスが低下しますが、データの一貫性を維持するために不可欠です

FixFlagsこれらの「揮発性」プロパティは、Message、ThreadName、UserName、Identityなどのフラグを含む列挙によって表されます。したがってすべての揮発性プロパティ。また、フラグ「None」(プロパティなしを修正)、「All」(すべてのプロパティを修正)、および「Partial」(特定の事前定義されたプロパティのセットのみを修正)も含まれています。

インスタンス化BufferingAppenderSkeletonされている場合、デフォルトでは、修正を「すべて」に設定します。これは、すべての「揮発性」プロパティを修正する必要があることを意味します。

そのコンテキストでは、BufferingAppenderSkeletonに追加された各LoggingEventについて、イベントがバッファーに挿入される前に、すべての「揮発性」プロパティが修正されます。これには、プロパティIdentity(ユーザー名)とLocationInformation(スタックトレース)がレイアウトに含まれていない場合でも含まれます(ただし、後でこれらのプロパティがバッファに含まれるようにレイアウトが変更された場合は、何らかの意味があります。すでにLoggingEventsで埋められています)。

しかし、私の場合、これは本当にパフォーマンスを損ないます。IdentityとLocationInformationをレイアウトに含めておらず、(主にパフォーマンスの問題のために)含める予定はありません。

今解決のために...

(のフラグ値BufferingAppenderSkeletonを制御するために使用できる2つのプロパティがあります(もう一度デフォルトで「ALL」に設定されていますが、これはあまり良くありません!)。これらの2つのプロパティは、(FixFlagsタイプ)と(boolタイプ)です。FixFlagsBufferingAppenderSkeletonFixOnlyFixPartialEventData

フラグ値を微調整したり、すべての修正を無効にしたりするには、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から継承する他のアペンダー)に提供されるサンプルは、使用しているレイアウトが非常に小さい場合でも、ユーザーにひどいパフォーマンスを提供します。

于 2012-07-05T19:40:00.080 に答える
1

でレイアウトパターンを指定してBufferingForwardingAppenderいないが、そのRollingLogFileAppenderためにBufferingForwardingAppenderユーザー名(%username)を含むすべてが出力に含まれていることが原因である可能性はありますか?

以下は興味深いブログ記事で、パターンレイアウトのオプションのリストがあり、そのうちのいくつかが低速としてマークされているようです。

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

于 2012-07-05T15:02:45.070 に答える