MetricsLoggingInterceptor.cs

gistfile1.txt

using System;
using System.Collections;
using System.Collections.Concurrent;
using System.Diagnostics;
using System.Linq;
using System.Text;
using Castle.DynamicProxy;
using Microsoft.Extensions.Logging;
using Scrutor;

namespace Mugen
{
    public class MetricsLoggingInterceptor<TInterface> : AsyncTimingInterceptor where TInterface : class
    {
        // ReSharper disable once StaticMemberInGenericType
        private static readonly ProxyGenerator ProxyGenerator = new ProxyGenerator();
        private readonly ConcurrentDictionary<string, double> _averageSecondsByMethod = new ConcurrentDictionary<string, double>();
        private readonly ConcurrentDictionary<string, int> _hitCountByMethod = new ConcurrentDictionary<string, int>();

        private readonly ILogger<TInterface> _logger;

        private MetricsLoggingInterceptor(ILogger<TInterface> logger)
            => _logger = logger;

        public static TInterface Decorate(TInterface target, ILogger<TInterface> logger)
        {
            var interceptor = new MetricsLoggingInterceptor<TInterface>(logger);
            var decorated = ProxyGenerator.CreateInterfaceProxyWithTarget(target, interceptor);
            return decorated;
        }

        private bool IsPropertyMethod(string methodName)
            => methodName.StartsWith("get_") || methodName.StartsWith("set_");

        protected override void StartingTiming(IInvocation invocation)
        {
            if (!_logger.IsEnabled(LogLevel.Information))
            {
                return;
            }

            try
            {
                var methodName = invocation.MethodInvocationTarget.Name;
                if (IsPropertyMethod(methodName))
                {
                    return;
                }

                var typeName = invocation.TargetType.GetDisplayName();
                var args = FormatArgs(invocation);
                _logger.LogInformation(
                    $"{typeName}::{methodName} - starting [ args = <{args}> ]"
                );
            }
            catch (Exception exception)
            {
                _logger.LogError(
                    exception,
                    "Failed to start timing of invocation {invocation}",
                    invocation?.MethodInvocationTarget?.Name
                );
            }
        }

        protected override void CompletedTiming(IInvocation invocation, Stopwatch stopwatch)
        {
            if (!_logger.IsEnabled(LogLevel.Information))
            {
                return;
            }

            try
            {
                var methodName = invocation.MethodInvocationTarget.Name;
                if (IsPropertyMethod(methodName))
                {
                    return;
                }

                var typeName = invocation.TargetType.Name;
                var args = FormatArgs(invocation);
                var elapsedSeconds = stopwatch.Elapsed.TotalSeconds;
                UpdateStats(methodName, elapsedSeconds);
                _logger.LogInformation(
                    $"{typeName}::{methodName} - {elapsedSeconds:N} sec [ hits={_hitCountByMethod[methodName]}, avg={_averageSecondsByMethod[methodName]:N} ] [ args = <{args}> ]"
                );
            }
            catch (Exception exception)
            {
                _logger.LogError(
                    exception,
                    "Failed to end timing of invocation {invocation}",
                    invocation?.MethodInvocationTarget?.Name
                );
            }
        }

        private static string FormatArgs(IInvocation invocation)
            => invocation.Arguments.Select(arg => $"'{FormatArg(arg)}'")
                .JoinToString(", ");

        private static string FormatArg(object arg)
        {
            return arg switch
            {
                null => "null",
                string str => str,
                IDictionary dictionary => dictionary.Count <= 5
                    ? $"[{JoinToString(dictionary.Keys)}]"
                    : $"{dictionary.GetType().GetDisplayName()} of size {dictionary.Count}",
                ICollection collection => collection.Count <= 5
                    ? $"[{JoinToString(collection)}]"
                    : $"{collection.GetType().GetDisplayName()} of size {collection.Count}",
                IEnumerable enumerable => enumerable.GetType()
                    .GetDisplayName(),
                _ => arg.ToString()
            };
        }

        private void UpdateStats(string methodName, double elapsedSeconds)
        {
            _hitCountByMethod.AddOrUpdate(
                methodName,
                1,
                (_, hitCount) => hitCount + 1
            );
            _averageSecondsByMethod.AddOrUpdate(
                methodName,
                elapsedSeconds,
                (_, previousAverage) => IncrementalAverage(
                    _hitCountByMethod[methodName],
                    previousAverage,
                    elapsedSeconds
                )
            );
        }

        private static double IncrementalAverage(int total, double previousAverage, double newValue)
            => ((total - 1) * previousAverage + newValue) / total;

        private static string JoinToString(ICollection items, string separator = ",")
        {
            var stringBuilder = new StringBuilder();
            var separatorUsed = "";
            foreach (var item in items)
            {
                stringBuilder.Append(separatorUsed);
                stringBuilder.Append(item);
                separatorUsed = separator;
            }

            return stringBuilder.ToString();
        }
    }
    
    public static class DependencyInjectionExtensions
    {
            public static void DecorateWithMetricsLogging<TService>(this IServiceCollection serviceCollection)
            where TService : class
            => serviceCollection.Decorate<TService>(
                (target, svc) =>
                    MetricsLoggingInterceptor<TService>.Decorate(target, svc.GetRequiredService<ILogger<TService>>())
            );
    }
}