まず、プロパティから取得した値（NDC、MDCなど）を使用し、UserNameを使用しない場合にのみ、この最適化が機能します。
はじめに
私は、関連する小さなサービスがたくさんある食品会社で働いています。 同社は10年以上前のものであるため、サービスはなんとか歴史になりました。 データのロギングには、log4netが使用されます。 以前は、すべてのサービスがログをデータベースに書き込み、バッファリングと書き込み用の別のマネージャーを使用して、ログにワークフローを煩わさないようにしました。 時間が経つにつれて、nxlog + elasticsearch + kibanaが大量に出現し、サービスサポートがより快適になりました。 新しいスタックへのサービスの段階的な移行が開始されました。 これ以降、log4netには2つの構成が既にありました。
- データベースに書き込む
- nxlogに書き込みます
挑戦する
サービスによってはエラーメッセージが書き込まれ、その原因を特定する必要がある場合があります。 全体像を把握して正しい結論を引き出すには、すべてのサービスのこの注文に関連するすべてのログが必要です。 しかし、ここに問題があります：それらをリンクするタグがありません。 そのため、独自の値を生成し、注文とともにサービス間で転送し始めました。 注文処理を開始する前に、単純化されたバージョンで以下のコードを呼び出して、ログに記録できるようにします。
LogicalThreadContext.Properties["CorrelationId"] = Guid.NewGuid();
web.configのlog4net設定の例：
<log4net> <appender name="nxlog" type="log4net.Appender.RemoteSyslogAppender"> <threshold value="DEBUG" /> <layout type="log4net.Layout.SerializedLayout, log4net.Ext.Json"> <decorator type="log4net.Layout.Decorators.StandardTypesDecorator, log4net.Ext.Json" /> <default value='nxlog' /> <member value="CorrelationId|%property{CorrelationId}" /> </layout> </appender> <root> <appender-ref ref="nxlog" /> </root> </log4net>
問題
ただし、この機能を古いサービスに追加し始め、データベースのレコードをnxlogのレコードに置き換えました。 ログの100,000エントリのこの構成には15秒のマシン時間がかかり、データベースへの書き込みの構成はわずか1.2秒であったため、変更はコードレビューを通過しませんでした。 その後、CorrelationIdをデータベースに保存しようとしましたが、敗北しました。 バッファリングするとき、プロパティは記憶されておらず、値が保存されていた場所ではなく、メッセージと例外のみが記憶されていました。
<appender name="Buffering" type="log4net.Appender.BufferingForwardingAppender" > <bufferSize value="512" /> <fix value="Message | Exception" /> <appender-ref ref="Database" /> </appender>
そして、プロパティをFixプロパティに追加するとすぐに、ログの100,000エントリに12秒強のマシン時間がかかり始めました。 そして、これはバックグラウンドでデータベースに保存することは言うまでもなく、バッファリングのためだけです。 正直なところ、私たちはこれに非常に驚き、さらにプロファイラーの結果に驚きました。
namespace log4net.Core { public class LoggingEvent : ISerializable { private void CreateCompositeProperties() { this.m_compositeProperties = new CompositeProperties(); this.m_compositeProperties.Add(this.m_eventProperties); this.m_compositeProperties.Add(LogicalThreadContext.Properties.GetProperties(false)); this.m_compositeProperties.Add(ThreadContext.Properties.GetProperties(false)); PropertiesDictionary propertiesDictionary = new PropertiesDictionary(); propertiesDictionary["log4net:UserName"] = (object) this.UserName; // <- 70% propertiesDictionary["log4net:Identity"] = (object) this.Identity; this.m_compositeProperties.Add(propertiesDictionary); this.m_compositeProperties.Add(GlobalContext.Properties.GetReadOnlyProperties()); } } }
何らかの理由で、レコードに関するすべての情報を保存するLoggingEventクラスは、プロパティにユーザー名を記憶しようとしますが、このクラスには対応するプロパティが使用されていないため、要求しませんでした。
短期的な解決策
その結果、AccelerateForwardingAppenderが誕生しました。作成されると、毎回計算する時間を無駄にすることなく、UserNameとIdentityの値が記憶され、すべてのLoggingEventオブジェクトにコピーされます。 私たちのサービスはIIS_IUSRSの下で実行されており、変更されていないことを警告したいと思います。 ただし、たとえばWindowsの承認がある場合は機能しない場合があります。
using System; using System.Linq.Expressions; using System.Runtime.CompilerServices; using System.Security.Principal; using System.Threading; using log4net.Appender; using log4net.Core; namespace log4net.ext.boost { public sealed class AccelerateForwardingAppender : ForwardingAppender { private static readonly FieldAccessor<LoggingEvent, LoggingEventData> LoggingEventDataAccessor; static AccelerateForwardingAppender() { LoggingEventDataAccessor = new FieldAccessor<LoggingEvent, LoggingEventData>(@"m_data"); } public AccelerateForwardingAppender() { CacheUsername = true; CacheIdentity = true; Username = WindowsIdentity.GetCurrent().Name ?? string.Empty; Identity = Thread.CurrentPrincipal.Identity?.Name ?? string.Empty; } public bool CacheUsername { get; set; } public bool CacheIdentity { get; set; } public string Username { get; set; } public string Identity { get; set; } protected override void Append(LoggingEvent loggingEvent) { Accelerate(loggingEvent); base.Append(loggingEvent); } protected override void Append(LoggingEvent[] loggingEvents) { for (var i = 0; i < loggingEvents.Length; i++) { Accelerate(loggingEvents[i]); } base.Append(loggingEvents); } [MethodImpl(MethodImplOptions.AggressiveInlining)] private void Accelerate(LoggingEvent loggingEvent) { if (CacheUsername || CacheIdentity) { var loggingEventData = LoggingEventDataAccessor.Get(loggingEvent); if (CacheUsername) { loggingEventData.UserName = Username; } if (CacheIdentity) { loggingEventData.Identity = Identity; } LoggingEventDataAccessor.Set(loggingEvent, loggingEventData); } } private sealed class FieldAccessor<TSubject, TField> { public readonly Func<TSubject, TField> Get; public readonly Action<TSubject, TField> Set; public FieldAccessor(string fieldName) { Get = FieldReflection.CreateGetDelegate<TSubject, TField>(fieldName); Set = FieldReflection.CreateSetDelegate<TSubject, TField>(fieldName); } } private static class FieldReflection { public static Func<TSubject, TField> CreateGetDelegate<TSubject, TField>(string fieldName) { var owner = Expression.Parameter(typeof(TSubject), @"owner"); var field = Expression.Field(owner, fieldName); var lambda = Expression.Lambda<Func<TSubject, TField>>(field, owner); return lambda.Compile(); } public static Action<TS, TF> CreateSetDelegate<TS, TF>(string fieldName) { var owner = Expression.Parameter(typeof(TS), @"owner"); var value = Expression.Parameter(typeof(TF), @"value"); var field = Expression.Field(owner, fieldName); var assign = Expression.Assign(field, value); var lambda = Expression.Lambda<Action<TS, TF>>(assign, owner, value); return lambda.Compile(); } } } }
ソースコードとテストをgithubにアップロードし、 BenchmarkDotNetライブラリを使用してパフォーマンスを比較しました。
using System; using System.Diagnostics; using BenchmarkDotNet.Attributes; using BenchmarkDotNet.Columns; using BenchmarkDotNet.Configs; using BenchmarkDotNet.Jobs; using BenchmarkDotNet.Running; using log4net.Appender; using log4net.Core; using log4net.Layout; namespace log4net.ext.boost.benchmark { public static class Program { private static void Main(string[] args) { var config = ManualConfig.Create(DefaultConfig.Instance) .With(PlaceColumn.ArabicNumber) .With(StatisticColumn.AllStatistics) .With(Job.Default); BenchmarkRunner.Run<BoostBenchmark>(config); Console.WriteLine("Press any key to exit..."); Console.ReadKey(true); } public class BoostBenchmark { public BoostBenchmark() { Trace.AutoFlush = Trace.UseGlobalLock = false; Trace.Listeners.Clear(); TraceAppender = new TraceAppender { Layout = new PatternLayout("%timestamp [%thread] %ndc - %message%newline") }; AccelerateForwardingAppender = new AccelerateForwardingAppender(); AccelerateForwardingAppender.AddAppender(TraceAppender); } private TraceAppender TraceAppender { get; } private AccelerateForwardingAppender AccelerateForwardingAppender { get; } [Benchmark] public void TraceAppenderBenchmark() { Perform(TraceAppender); } [Benchmark] public void AcceleratedTraceAppenderBenchmark() { Perform(AccelerateForwardingAppender); } private static void Perform(IAppender appender) { appender.DoAppend(new LoggingEvent(new LoggingEventData { TimeStamp = DateTime.UtcNow, Message = "TEST" })); } } } }
ホストプロセス環境情報： BenchmarkDotNet.Core = v0.9.9.0 OS = Microsoft Windows NT 6.2.9200.0 プロセッサー= Intel（R）Core（TM）i7-6700HQ CPU 2.60GHz、ProcessorCount = 8 周波数= 2531255ティック、解像度= 395.0609 ns、タイマー= TSC CLR = MS.NET 4.0.30319.42000、Arch = 32ビットリリース GC =同時ワークステーション JitModules = clrjit-v4.6.1586.0 タイプ= BoostBenchmarkモード=スループット
| 方法 | 中央値 | Stddev | 平均 | Stderror | Stddev | Op / s | 分 | Q1 | 中央値 | Q3 | マックス | 場所 |
|---|---|---|---|---|---|---|---|---|---|---|---|---|
| TraceAppenderBenchmark | 104.5323 us | 4.5553 us | 105.4234 us | 0.8934 us | 4.5553 us | 9485.56 | 98.7720 us | 102.2095 us | 104.5323 us | 107.0166 us | 116.3275 us | 2 |
| AcceleratedTraceAppenderBenchmark | 2.6890 us | 0.1433 us | 2.7820 us | 0.0236 us | 0.1433 us | 359456.73 | 2.6134 us | 2.6629 us | 2.6890 us | 2.9425 us | 3.0275 us | 1 |
結果によると、成長は359456.73 / 9485.56 = 37.9倍と非常に安定していることがわかります。 このような大きな価値は、ログがテストのどこにも保存されないという事実によるものです。 サービスでは、ログはnxlogに送信されるため、実際の増加は10倍で、15秒のマシン時間が1.5秒になりました。
長期的なソリューション
この結果に触発されて、私はlog4netのプルリクエストを行いました。そこで重複コードを削除することを提案し、期待されるレスポンスを得ました：
bodewig：そして、それらのプロパティを必要とする既存のコードとパターンを壊しませんか？
一方で、著者は正しいです。変更は誰かにとって重要な場合がありますが、一方で、多くの時間が無駄になるのは残念です。 ご意見をお聞かせください。