История одного исследования в log4net и ускорение его более чем в 10 раз

Начну с того, что данная оптимизация будет работать только, если вы используете значения взятые из 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 авторизация, например.

AccelerateForwardingAppender.cs

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 библиотеку, чтобы сравнить производительность.

Benchmark.cs

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?

С одной стороны автор прав: любое изменение может быть критичным для кого-то, но с другой стороны обидно, что тратится столько времени впустую. Хотелось бы узнать ваше мнение.