Adding logging to an old .NET 4.0 project via Castle Windsor to measure performance

Recently I've been working with a reasonably old codebase, one that's using Castle / Castle.Windsor 3.1.0 which dates back to late 2012, targeting plain .NET Framework 4.0. This has been 'interesting'.

The work I've been doing has been around improving the performance of a process that imports data from a rather large Excel spreadsheet (c. 14,000 records) by reading the file, processing it, comparing it against the target database and then loading it. The short version of the story is that the process used to take 5+ minutes to execute and now does so in around 10 seconds. The exact nuts and bolts of how I achieved this aren't that relevant, but the key part of the process was adding logging.

Adding NLog to Castle.Windsor (3.x)

This required the addition of three packages:

Castle.Facilities.Logging
Castle.Services.Logging.NLogIntegration
NLog

I also updated the project to use the latest 3.x version of Castle (3.3.0) and Castle.Windsor (3.4.0) as part of the process.

In order to integrate NLog with Castle Windsor, I added the following to the applications startup code:

Container.AddFacility<LoggingFacility>(f => f.LogUsing(LoggerImplementation.NLog).WithConfig("NLog.config"));

The rest of the container configuration is provided via a config file section so isn't really interesting here. The NLog.config file is a fairly standard set of NLog configuration, pared back to the minimum required to get it working:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" internalLogFile="c:\temp\nlog-internal.log">
  <targets>
    <target xsi:type="File" name="f" fileName="C:/logs/${shortdate}.log"
            layout="${longdate} ${uppercase:${level}} ${message}" />
  </targets>
  <rules>
    <logger name="*" minlevel="Debug" writeTo="f" />
  </rules>
</nlog>

With that in place, the first thing to do was to add a property to each of the classes that would be generating logging so that Castle could inject a logging instance:

public ILogger Logger { get; set; }

This ILogger interface comes from Castle.Core.Logging and provides an abstraction over NLog, I guess I could theoretically swap NLog out for a different logging solution at any point in the future if I wanted to.

Wrapping ILogger to allow for rough 'n ready performance measurement

There's many different ways to measure code performance, but because I knew tha this code consisted of ten or twenty "main" chunks that were each taking a good while, the easiest way to get a view of what was happening was to measure how long each chunk was taking. I could've added code at the start and end of every method that looks like this:

Logger.Info($"START {nameof(MethodName)}");
...
...
Logger.Info($"END {nameof(MethodName)}");

This would allow me to see the start and end times and extrapolate the time taken. Instead I opted to write a wrapper around Logger, as an extension method, to also write out the duration and reduce the duplication of START/END calls and naming of things (and allow me to customise the message logged more easily). This looks like:

public sealed class LoggerStopStartLogger : IDisposable
{
    private ILogger Logger { get; set; }
    private string Message { get; set; }
    private Stopwatch watch;

    public LoggerStopStartLogger(ILogger logger, string message)
    {
        Logger = logger;
        Message = message;
        watch = new Stopwatch();
        watch.Start();
        Logger.Info($"START {Message}");
    }
    void IDisposable.Dispose()
    {
        Logger.Info($"END {Message} - Duration [{watch.ElapsedMilliseconds}]");
    }
}

With this class comes the extension method:

public static class ILoggerHelpers
{
    public static LoggerStopStartLogger WrapEvent(this ILogger logger, LogLevel logLevel, string message)
    {
        return new LoggerStopStartLogger(logger, logLevel, message);
    }
}

Now that I've got the extension method and the associated class, I can wrap the content of entire methods (or calls to entire methods) with this:

using (var _ = Logger.WrapEvent(LogLevel.Info, "Populating users with changes"))
{
    //
    // The body of the method goes here
    //
}

That re-purposing of using and IDisposable gives me three things, firstly it means that I don't end up making mistakes with the text I use to describe each method (such as it being different between the start and end calls), second it gives me a tidy way to see both the elapsed duration and finally it lets me see from the logging how method calls are nested inside each other. The latter proved particularly useful as I discovered that there was one method being called (incorrectly and with no purpose other than using up execution time) from inside another method that it called.

The final log file (once I'd used the data to improve performance) looked a little like this:

2019-02-16 00:12:37.9494 INFO START Loading user data
2019-02-16 00:12:37.9914 INFO   START Clearing all grids
2019-02-16 00:12:38.0034 INFO   END Clearing all grids - Duration [12]
2019-02-16 00:12:38.0034 INFO   START Populating all users data grid
2019-02-16 00:12:39.7064 INFO   END Populating all users data grid - Duration [1697]
2019-02-16 00:12:39.7204 INFO   START Getting as import user
2019-02-16 00:12:39.7664 INFO   END Getting as import user - Duration [45]
2019-02-16 00:12:39.7664 INFO   START Populating users with issues
2019-02-16 00:12:40.4600 INFO   END Populating users with issues - Duration [688]
2019-02-16 00:12:40.4789 INFO   START Populating valid and issue users grids
2019-02-16 00:12:41.6015 INFO   END Populating valid and issue users grids - Duration [1123]
2019-02-16 00:12:41.6175 INFO   START Check users worker
2019-02-16 00:12:41.6325 INFO     START CheckUsersForValidManager
2019-02-16 00:12:46.2185 INFO     END CheckUsersForValidManager - Duration [4586]
2019-02-16 00:12:46.2185 INFO   END Check users worker - Duration [4606]
2019-02-16 00:12:46.2575 INFO   START Populating users with changes
2019-02-16 00:12:47.4361 INFO   END Populating users with changes - Duration [1177]
2019-02-16 00:12:47.4521 INFO   START Populating different email addresses
2019-02-16 00:12:48.1403 INFO   END Populating different email addresses - Duration [687]
2019-02-16 00:12:48.1543 INFO   START Populating deletable users
2019-02-16 00:12:49.6463 INFO     START Populate deletable users update grid
2019-02-16 00:12:49.6543 INFO     END Populate deletable users update grid - Duration [7]
2019-02-16 00:12:49.6743 INFO   END Populating deletable users - Duration [1520]
2019-02-16 00:12:49.6923 INFO END Loading user data - Duration [11744]

I've added some indenting so that you can see where there's nested method calls - there's much less indentation now than there was before, and one method left that's taking about 40% of the time for the entire process; guess what's getting looked at next!