Log the Elapsed Time Between Log Entries using NLog

I often want to know how long a certain operation takes to run, so I write a log message before and after the operation. Because each log entry contains a timestamp, I can mentally subtract the timestamps to determine how long the operation took.

But if I'm doing a lot of these performance tests, it can get a bit tiring to constantly have to do these mental calculations. It would be much easier if the log entry itself contained the elapsed time since the last log entry. I'll show you how to do that using NLog. (For an intro to NLog, see my blog post Log Software Events and User Actions with NLog.)

The key feature of NLog that allows you to add a new kind of data to the log entry is the custom layout renderer. You may be familiar with some of the build-in layout renderers, such as "${longdate}" for the timestamp, "${level}" for the log level, and "${message}" for the log message. Here you'll add "${elapsed-time}" as a custom layout renderer.

First, specify the custom layout renderer you want to use for each log entry. You do this in NLog's layout configuration, which you should already have in App.config (or however you set it up). Here's an example, specifying that the elapsed time should be shown after the timestamp:

<layout xsi:type="CsvLayout" delimiter="Tab" withHeader="false">
    <column layout="${longdate}" />
    <column layout="${elapsed-time}" />
    <column layout="${machinename}" />
    <column layout="${windows-identity}" />
    <column layout="${processid}" />
    <column layout="${uppercase:${level}}" />
    <column layout="${message}" />
    <column layout="${exception:format=toString}" />
</layout>

Now write the actual renderer:

[LayoutRenderer("elapsed-time")]
public class ElapsedTimeLayoutRenderer : LayoutRenderer
{
    private DateTime? _lastTimeStamp;

    protected override void Append(StringBuilder builder, LogEventInfo logEvent)
    {
        var lastTimeStamp = _lastTimeStamp ?? logEvent.TimeStamp;
        var elapsedTime = logEvent.TimeStamp - lastTimeStamp;
        var elapsedTimeString = $"{elapsedTime.TotalSeconds:f4}".PadLeft(10);
        builder.Append($"{elapsedTimeString} s");
        _lastTimeStamp = logEvent.TimeStamp;
    }
}

First, specify the name of the renderer ("elapsed-time") using a class attribute. Then, create a class that derives from LayoutRenderer and implement its Append method. In the Append method, we calculate the time elapsed since the last log entry, format this elapsed time, and finally append the result to the provided StringBuilder.

The last log entry's timestamp is saved each time the Append method is called, which happens each time a log entry is about to be written to the log. Notice that the first time this method is run the saved timestamp is null, in which case we simply use the current timestamp. The provided LogEventInfo contains (among other things) the current log entry's timestamp.

Finally, you need to register this layout renderer with NLog. This should be done before any log entries are written. Since I normally use a wrapper class for NLog, I register any custom layout renderers in the wrapper's constructor:

public class Logger : ILogger
{
    private readonly global::NLog.Logger _logger;

    public Logger(string name)
    {
        LayoutRenderer.Register<ElapsedTimeLayoutRenderer>("elapsed-time");
        _logger = LogManager.GetLogger(name);
    }

    // Logging methods (Trace, Debug, Info, etc.)
}

For the implementation of the logging methods, see my blog post Log Software Events and User Actions with NLog.

For a recent application, my log output looks something like this:

2019-06-12 17:32:31.1410            0.0000 s        CITRX        DOMAIN\smithj        13876        DEBUG        Initialized logger        
2019-06-12 17:32:31.2150            0.0740 s        CITRX        DOMAIN\smithj        13876        DEBUG        Initializing IOC container        
2019-06-12 17:32:32.0870            0.8720 s        CITRX        DOMAIN\smithj        13876        DEBUG        Initialized IOC container        
2019-06-12 17:32:32.2520            0.1650 s        CITRX        DOMAIN\smithj        13876        DEBUG        Started request router        
2019-06-12 17:32:32.2710            0.0190 s        CITRX        DOMAIN\smithj        13876        DEBUG        Received StartApplicationRequest        
2019-06-12 17:32:32.2710            0.0000 s        CITRX        DOMAIN\smithj        13876        DEBUG        Handling StartApplicationRequest        
2019-06-12 17:32:32.3710            0.1000 s        CITRX        DOMAIN\smithj        13876        DEBUG        Logging in to ESAPI        
2019-06-12 17:32:35.6100            3.2390 s        CITRX        DOMAIN\smithj        13876        DEBUG        Logged in to ESAPI        
2019-06-12 17:32:35.8620            0.2520 s        CITRX        DOMAIN\smithj        13876        INFO        Starting application (v. 1.1.0.0)

Now it's easy to tell how long certain operations took to run. For example, you can quickly see that "Logging in to ESAPI" took about 3 seconds, and that it's the slowest operation so far.

The elapsed time could also be useful in determining certain usability patterns. For example, if a user took a long time interacting with a dialog box, perhaps the interface was not easy to understand. Or he or she took a coffee break.