log4netの拡張。 競合ロギング

log4netライブラリはよく知られており、紹介する必要はありません。 必要なものはほとんどすべて、すぐに使用できます。 ただし、ライブラリの機能を追加/拡張する必要がある特定の状況があります。 特定の状況：log4netからロガーへのロギングを実行するライブラリがあります（またはいくつかは重要ではありません）。 このライブラリはNサービスで使用されます。 単一のファイルにログを記録する方法は？ 猫の下には、FileAppender + MinimalLockが適切でない理由の説明と、問題を解決するAppenderの実装があります。 データベース、ネットワークなどへのログインの問題について個別に言いたいと思います。 記事は考慮されません、なぜなら これははるかに深刻な作業であり、（特に大規模システムの場合）多くの考えと実装が必要です。



私の議論ではテスト結果に依存するため、テスト環境についてすぐに予約してください。 i7プロセッサ（4コア、8ハイパースレッディングを考慮に入れた8）、log4net.Extensions.Consoleアプリケーションは、記録後に任意のスリープで8スレッドでログに書き込みます。 ログエントリの数は10000です。BulkStarterアプリケーションは、log4net.Extensions.Consoleの10個のインスタンスを起動し、その完了を待ちます。 したがって、10個のプロセス（それぞれ8つのスレッド）が単一のファイルに書き込みます。 すべての時間特性は、 ストップウォッチ （測定までの高解像度タイマー）を使用したこのようなテストで取得されました。

FileAppender + MinimalLock

log4netには、ファイルにログを書き込むためのFileAppenderがあります。 排他ロック（デフォルトで使用）といわゆるMinimalLockの可能性を実装します。 log4netを初期化するとき、ExclusiveLockは他のプロセスの読み取り専用ファイルを開きます。 MinimalLockは、ファイル内のエントリごとにファイルを開いたり閉じたりします。 したがって、ExclusiveLockは私たちにはまったく適していません（ファイルのロックをキャプチャした最初のプロセスを除くすべてのプロセスでファイルを使用できないため）、MinimalLockにはいくつかの重大な欠点があります。

• 非常に遅い（テストの1:56から、ロギングメソッドへの直接呼び出しには1:40かかりました）。
• 複数のプロセスが書き込み用のスレッドを取得しようとするとロックが競合します（つまり、ログに書き込みを行いません）。

MinimalLockを使用したFileAppenderの構成例：

<appender name="FileAppender" type="log4net.Appender.FileAppender"> <file value="D:\1\test-minlock.log"/> <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%message%n"/> </layout> </appender> 

ConcurrentMinimalLock

価値のある代替品を探して、コードプロジェクト- マルチプロセスから単一ファイルへのログインに関する2008年の記事に出会いました。 この記事では、ConcurrentMinimalLockの実装について説明します。この実装では、メッセージがバッファリングされ、ファイルがループで開かれます（ロックが確立されるまで）。 すべて問題ないようですが、ロギングメソッドを呼び出す時間は1:20のうち1:04です。 つまり まだ長い。 これは、これが部分的に非同期のロギングであるという事実を考慮しています（アプリケーションがハードクローズされている場合、すべてのキューが失われます）。

ConcurrentFileAppender

私の研究では、平凡なミューテックスの主な目的はプロセス間同期であるため、誰もミューテックスを使用したくないことに非常に驚きました。 したがって、ミューテックスを使用してプロセス間で同期する独自のAppenderを作成することにしました。 アペンダーを作成するには、次のものが必要です。

• 抽象クラスlog4net.Appender.AppenderSkeletonから継承。
• ActivateOptionsメソッドを実装します。このメソッドでは、Appenderの初期化が実行されます。
• 単一のLoggingEventとLoggingEventの配列を受け入れるAppendメソッドを実装します。
• リソースを消去するOnCloseメソッドを実装します（log4netのDisposeと同様）。

主なアイデアは、（Monitorを使用して）同期キューにメッセージを追加し、別のスレッドでファイルに書き込み、名前付きミューテックスを使用してファイルへのアクセスを（ファイルへのフルパスに沿って）同期することです。

ActivateOptions

初期化時に、FileStreamを書き込みモードで開きますが、FileShareの読み取り/書き込みを指定します。 つまり 他のプロセスは、このファイルに対して並行して読み書きできます。 残念なことに、ConcurrentFileAppender以外のユーザーに読み取り専用ファイルを作成する方法はありません。 サポートはオンラインで（もちろん、偶然に）ファイルを編集できませんでした。 ファイルを開いたままにしておくという事実は、以前の実装で行われていたように、開くのにあまり時間をかけない機会を与えてくれます。

 public override void ActivateOptions() Dispose(true); // flush     base.ActivateOptions(); //       var path = SystemInfo.ConvertToFullPath(Path); var dir = System.IO.Path.GetDirectoryName(path); if (!Directory.Exists(dir)) Directory.CreateDirectory(dir); _loggingEvents = new Queue<LoggingEvent>(QueueInitialCapacity); FileStream stream = null; Mutex mutex = null; try { stream = File.Open(path, FileMode.Append, FileAccess.Write, FileShare.ReadWrite); mutex = CreateMutex(path); _thread = new Thread(ThreadProc) { Name = "ConcurrentFileAppenderListener", IsBackground = true // logging thread should not prevent an application exit }; _thread.Start(); _stream = stream; stream = null; _mutex = mutex; mutex = null; if (FlushOnProcessExit) AppDomain.CurrentDomain.ProcessExit += delegate { OnProcessExit(path); }; } finally { if (stream != null) stream.Dispose(); if (mutex != null) mutex.Close(); } } 

Threadproc

ループ内のメソッドtriteは、空でないかどうかキューをチェックします。 キューが空でない場合は、その内容をコピーしてクリアし、ディスクにダンプします。

 private void ThreadProc() { var culture = CultureInfo.InvariantCulture; while (true) { if (!_nonEmptyQueue) //      bool     { Thread.Sleep(QueueEmptyCheckTimeoutInMilliseconds); continue; } lock (QueueSyncRoot) { _currentProcessingEvents = _loggingEvents.ToArray(); _loggingEvents.Clear(); _nonEmptyQueue = false; } Flush(_mutex, _stream, culture, _currentProcessingEvents); _currentProcessingEvents = null; } } 

フラッシュ

キューに蓄積されたメッセージは最初にバッファに書き込まれ、次にこのバッファはディスクに完全に割り当てられ、連続した書き込み呼び出しが行われないようにします。 もう1つの重要なポイントは、ファイルカーソルの現在の位置がキャッシュされるため、記録の前にSeekを実行することです。

 private void Flush(Mutex mutex, FileStream stream, CultureInfo culture, ICollection<LoggingEvent> events) { if (events.Count <= 0) return; byte[] buffer; using (var sw = new StringWriter(culture)) { foreach (var e in events) RenderLoggingEvent(sw, e); buffer = Encoding.GetBytes(sw.ToString()); } try { mutex.WaitOne(); stream.Seek(0, SeekOrigin.End); stream.Write(buffer, 0, buffer.Length); stream.Flush(); } finally { mutex.ReleaseMutex(); } } 

最終実装

最後に、基本クラスConcurrentAppenderSkeletonが記述されました。

 public abstract class ConcurrentAppenderSkeleton : AppenderSkeleton, IDisposable { /// <summary> /// Gets a name for a <see cref="Mutex"/>. /// </summary> protected abstract string UniqueMutexName { get; } /// <summary> /// Performs initialization of an appender. Should throw exception if cannot be initialized. /// </summary> protected abstract void ActivateOptionsInternal(); /// <summary> /// Prepares data to a flushing. /// </summary> /// <remarks> /// <para>This method executes in a thread safe context (under <see cref="Monitor"/> lock).</para> /// </remarks> /// <param name="events">Logging events.</param> /// <returns>A prepared data.</returns> protected abstract object PrepareData(LoggingEvent[] events); /// <summary> /// Flushes prepared data. /// </summary> /// <remarks> /// <para>This method executes in a thread-safe context (under mutex).</para> /// </remarks> /// <param name="data">A prepared data to a flushing.</param> protected abstract void Flush(object data); } 

継承者：ConcurrentFileAppenderおよびConcurrentForwardingAppender（ BufferingForwardingAppenderに似ています）。 後者では、他のアペンダーのセットに書き込み（フラッシュ）できます。 これらの他のアペンダーが排他ロックを行わないことが重要です（つまり、FileAppender + ExclusiveLockは使用できません）。したがって、それらはミューテックスによって同期されます。

テストの目的で、ミューテックスを使用して同期する場所を設定しました。キューからメッセージを受信する直前、またはファイルへの書き込み専用です。 最初のケースでは、キューの数は増加します（フォーマットと記録を含むためロックが長くなるため）が、入力/出力コストはいくらか減少します（10Kbの10レコードが100から1Kbより速いため）。 2番目の場合、キューはあまり大きくならず、ロック状態にあることは最小限で（I / O自体の時間のみ）、よりスケーラブルです。

テスト

テストは、それぞれ8スレッドの10プロセスの500 MBログエントリであることを思い出させてください。 次の表は、さまざまなテストの結果を示しています。 ConcurrentFileAppenderはFileとして省略形で表示され、ConcurrentForwardingAppender（記録はFileAppender + MinimalLockで実行されます）としてFwd + Minとして、エキゾチックなバージョン-ConcurrentMiniwardLockでFileAppenderで記録が実行されるConcurrentForwardingAppenderはFwd + Conとして指定されます。 キューポーリングのスリープ時間は10ミリ秒です。 Mutex.WaitOneは、記録専用のIO、フォーマットおよび記録用のWholeとして指定されます。

時間（s）\テスト	ミンロック	同時ミンロック	ファイルio	ファイル全体	Fwd + min io	Fwd +最小全体	Fwd + con io	Fwd + con全体
総時間	116.6	79.7	11.27	11.6	11.96	11.61	11.7	11.61
logger.Debug	100.36	64.68	0.08	0,07	0,07	0,07	0.08	0,07
水 キューの長さ	-	-	9	40	185	169	17	25

表からわかるように、入出力の時間だけミューテックスロックを使用すると、メッセージキューが小さくなり、信頼性がわずかに向上します。 RollingFileAppender機能を使用する必要がある場合、ConcurrentMinimalLockと組み合わせてConcurrentForwardingAppenderを使用することは理にかなっていますが、ダブルバッファリングを行わない独自のバージョンのLockを記述する方が適切です。

コンカレントの2つの主な利点*アペンダー：マルチプロセッシングと、ロギングが有効な場合のメインアプリケーションでのスローダウンの実質的な欠如。

PS

記事を書く過程で、合計時間の計算とlogger.Debugメソッドの呼び出しでエラーに気付きました。 私のアペンダーではなく、すべてがさらに悪くなりましたが、私のアペンダーではさらに良くなりました:)しかし、私は元の結果テーブルをもう更新しませんでした。 非常に長い時間、申し訳ありません（エラーは、log4net.Extensions.ConsoleでStopwatchインスタンスへのアクセスが同期されていなかったため、値を8で割る必要がありました）。

参照：

• Log4net公式ページ
• System.Threading.Mutex-.NET Frameworkでミューテックス機能を実装するクラス
• マルチプロセスから単一ファイルへのログイン

ファイル：

• アペンダーの実装とテストアプリケーション
• 起動結果+拡張結果テーブル付きODSファイル