To begin with, this optimization will only work if you use values ​​taken from Properties (for example: NDC, MDC) and do not use UserName.

Introduction

I work for a grocery company, where there are many small services related to each other. Since companies are over 10 years old, services have had a history. Log4net is used for logging data. Previously, all services wrote their logs to the database, using buffering and a separate dispatcher for writing, in order not to bother the workflow with logging. Over time, a bunch of nxlog + elasticsearch + kibana appeared, which made service support much more pleasant. A gradual migration of services to a new stack has begun. From this point on, we already had two configurations for log4net:

• write to the database
• write in nxlog

Task

Sometimes we have a situation when a service writes an error message and we need to figure out what caused this. To get the full picture and make the right conclusions, we need all the logs associated with this order from all services. But here’s the problem: we don’t have any tags to link them. Therefore, we began to generate a unique value and transfer it between our services along with the order. Before you start processing an order, we call the following code in a simplified form so that it can get into the logs.

LogicalThreadContext.Properties["CorrelationId"] = Guid.NewGuid(); 

An example of our log4net configuration in web.config:

 <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> 

Problem

But when we started adding this functionality to the old services, replacing the record in the database with the record in nxlog. Our changes did not go through to code review due to the fact that this configuration on 100,000 entries in the log took 15 seconds of computer time, while the configuration with writing to the database is only 1.2 seconds. Then we tried to save the CorrelationId to the database and were defeated. When buffering, Properties were not remembered where our value was stored, but only Message and Exception.

 <appender name="Buffering" type="log4net.Appender.BufferingForwardingAppender" > <bufferSize value="512" /> <fix value="Message | Exception" /> <appender-ref ref="Database" /> </appender> 

And as soon as we added the Properties to the Fix property, then a little more than 12 seconds of computer time per 100,000 records went to the log. And this is only for buffering, not to mention saving to the database in the background. To be honest, we were greatly surprised by this and even more we were surprised by the results of the profiler:

 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()); } } } 

For some reason that is not clear to us, the LoggingEvent class, which stores all the information about the record in itself, tries to remember the name of the user in Properties, although we didn’t ask for it exactly, because for this, there is a corresponding property in the same class .

Short term solution

As a result, Accelerate ForwardingAppender was born, in which UserName and Identity values ​​are remembered during creation and copied to all LoggingEvent objects, without wasting time on the calculation each time. I want to warn you that our service is running under IIS_IUSRS and it does not change with us, so it works for us. But it may not work for you if you have Windows authentication, for example.

 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(); } } } } 

I uploaded the source code with tests on github , I also used the BenchmarkDotNet library to compare performance.

 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" })); } } } } 

 Host Process Environment Information:
 BenchmarkDotNet.Core = v0.9.9.0
 OS = Microsoft Windows NT 6.2.9200.0
 Processor = Intel (R) Core (TM) i7-6700HQ CPU 2.60GHz, ProcessorCount = 8
 Frequency = 2531255 ticks, Resolution = 395.0609 ns, Timer = TSC
 CLR = MS.NET 4.0.30319.42000, Arch = 32-bit RELEASE
 GC = Concurrent Workstation
 JitModules = clrjit-v4.6.1586.0

 Type = BoostBenchmark Mode = Throughput  

According to the results, it is clear that the increase is quite solid, 359456.73 / 9485.56 = 37.9 times. Such great importance is due to the fact that in the test logs are not saved anywhere. On our services, logs are sent to nxlog and therefore for us the real increase was 10 times, 15 seconds of computer time turned into 1.5 seconds.

Long term solution

Encouraged by this result, I made a pull request for log4net, where I offered to remove duplicate code, and received the expected answer:

 bodewig:

On the one hand, the author is right: any change can be critical for someone, but on the other hand, it’s a shame that so much time is being wasted. I would like to know your opinion.