The history of one study in log4net and its acceleration by more than 10 times
To begin with, this optimization will work only 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 the company is more than 10 years old, then the services managed to become history. For data logging, log4net is used. Previously, all services wrote their logs to the database, using buffering and a separate manager for writing, so as 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 now on, we already had two configurations for log4net:
- write to database
- write to nxlog
Task
Sometimes we have a situation when some service writes an error message and we need to figure out what caused this. To get the full picture and draw the right conclusions, we need all the logs related to this order from all services. But here is the problem: we do not 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 starting order processing, we call in the simplified version the code below so that it can get into the logs.
LogicalThreadContext.Properties["CorrelationId"] = Guid.NewGuid();An example of our log4net configuration in web.config:
Problem
But when we started adding this functionality to old services, replacing the record in the database with the record in nxlog. Our changes did not go through a code review due to the fact that this configuration on 100,000 log entries took 15 seconds of computer time, while the configuration with writing to the database was only 1.2 seconds. Then we tried to save CorrelationId to the database and were defeated. When buffering, Properties were not remembered, where our value was stored, but only Message and Exception.
And as soon as we added Properties to the Fix property, a little more than 12 seconds of machine time began to go to 100,000 entries in the log. And this is only for buffering, not to mention saving to the database in the background. Honestly, we were very 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 we don’t understand, the LoggingEvent class, which stores all the information about the record, tries to remember the username in Properties, although we didn’t ask for it, because there is a corresponding property that we don’t use in this class .
Short term solution
As a result, AccelerateForwardingAppender was born, in which, when created, UserName and Identity values are stored and copied to all LoggingEvent objects, without wasting time calculating each time. I want to warn you that our service is running under IIS_IUSRS and it does not change with us, so this works for us. But it may not work for you if you have Windows authorization, 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 LoggingEventDataAccessor;
static AccelerateForwardingAppender()
{
LoggingEventDataAccessor = new FieldAccessor(@"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
{
public readonly Func Get;
public readonly Action Set;
public FieldAccessor(string fieldName)
{
Get = FieldReflection.CreateGetDelegate(fieldName);
Set = FieldReflection.CreateSetDelegate(fieldName);
}
}
private static class FieldReflection
{
public static Func CreateGetDelegate(string fieldName)
{
var owner = Expression.Parameter(typeof(TSubject), @"owner");
var field = Expression.Field(owner, fieldName);
var lambda = Expression.Lambda>(field, owner);
return lambda.Compile();
}
public static Action CreateSetDelegate(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>(assign, owner, value);
return lambda.Compile();
}
}
}
} I uploaded the source code with the tests to 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(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
| Method | Median | Stddev | Mean | Stderror | Stddev | Op / s | Min | Q1 | Median | Q3 | Max | Place |
|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 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 |
According to the results, it is clear that the growth is quite solid at 359456.73 / 9485.56 = 37.9 times. Such a great value is due to the fact that the logs are not saved anywhere in the test. On our services, logs are sent to nxlog and therefore, for us, the real increase was 10 times, 15 seconds of machine time turned into 1.5 seconds.
Long term solution
Inspired by this result, I made a pull request for log4net, where I suggested deleting duplicate code, and got the expected response:
bodewig: and break existing code and patterns that need those properties, doesn't it?
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 wasted. I would like to know your opinion.