Начну с того, что данная оптимизация будет работать только, если вы используете значения взятые из Properties (например: NDC, MDC) и не используете UserName.
Введение
Я работаю на продуктовую компанию, где есть множество маленьких сервисов, связанных между собой. Так как компании более 10 лет, то и сервисы успели обрасти историей. Для логирования данных используется log4net. Раньше все сервисы писали свои логи в базу данных, используя буферизацию и отдельный диспетчер для записи, чтобы не утруждать рабочий поток логированием. Со временем появилась связка nxlog + elasticsearch + kibana, что сделало поддержку сервисов намного приятней. Началась постепенная миграция сервисов на новый стек. С этого момента у нас было уже две конфигурации для log4net:
- писать в базу данных
- писать в nxlog
Задача
Иногда у нас возникает ситуация, когда какой-то сервис записывает сообщение об ошибке и нам надо разобраться, что стало этому причиной. Чтобы получить полную картину и сделать привальные выводы, нам нужны все связанные с этим заказом логи со всех сервисов. Но вот проблема: у нас нет никаких меток чтобы их связать. Поэтому, мы стали генерировать уникальное значение и передавать его между нашими сервисами вместе с заказом. Перед тем, как запустить обработку заказа, мы вызываем в упрощенном варианте приведенный ниже код, чтобы он смог попасть в логи.
LogicalThreadContext.Properties["CorrelationId"] = Guid.NewGuid();
Пример нашей конфигурации log4net в 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>
Проблема
Но когда мы начали добавлять данный функционал в старые сервисы заменяя запись в базу данных на запись в nxlog. Наши изменения не прошли на code review по причине того, что данная конфигурация на 100 000 записях в лог занимала 15 секунд машинного времени, в то время, как конфигурация с записью в базу данных всего 1.2 секунды. Тогда мы попытались сохранить CorrelationId в базу данных и потерпели поражение. При буферизации не запоминались Properties, где хранилось наше значение, а только Message и Exception.
<appender name="Buffering" type="log4net.Appender.BufferingForwardingAppender" >
<bufferSize value="512" />
<fix value="Message | Exception" />
<appender-ref ref="Database" />
</appender>
И как только мы добавили к свойству Fix еще и Properties, то на 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, который в себе хранит всю информацию о записи, пытается запомнить имя пользователя в Properties, хотя мы его об этом точно не просили, так как для этого в этом же классе есть соответствующее не используемое нами свойство.
Краткосрочное решение
В результате появился на свет 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" }));
}
}
}
}
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 |
По результатам видно, что прирост довольно солидный в 359456.73 / 9485.56 = 37.9 раз. Такое большое значение обусловлено тем, что в тесте логи никуда не сохраняются. На наших сервисах логи пересылаются в nxlog и поэтому для нас реальный прирост получился в 10 раз, 15 секунд машинного времени превратились в 1.5 секунды.
Долгосрочное решение
Воодушевленный таким результатом и я сделал pull request для log4net, где предложил удалить дублирующий код, и получил ожидаемый ответ:
bodewig: and break existing code and patterns that need those properties, doesn't it?
С одной стороны автор прав: любое изменение может быть критичным для кого-то, но с другой стороны обидно, что тратится столько времени впустую. Хотелось бы узнать ваше мнение.
Автор: kolbasik