Performance with IDisposable, Outside the Box

Introduction

In this post, I would like to share with you a technique I used in the past, though by all means not an impressive feat. But first, a little story about IDisposable and why I chose this approach.

The IDisposable interface is mainly used as a way for the Garbage Collection to release unmanaged resources, like file handles, database connections, and generally any resource that is outside of the application.

Though one benefit of IDisposable is the fact that they can be used with the using construct, which in this case is very helpful.

Let’s look at the performance logger, dissect it and we will see how to use it.

namespace ConsoleApp1
{
    using System;
    using System.Diagnostics;
    using System.Runtime.CompilerServices;

    internal class PerfomanceLogger : IDisposable
    {
        private static int numberOfInstances = -1;

        private readonly string _message;
        private readonly string _sourceMemberName;
        private readonly string _sourceFilePath;
        private readonly int _sourceLineNumber;
        private readonly Stopwatch _stopwatch;

        private PerfomanceLogger(string message, string sourceMemberName, 
                                 string sourceFilePath, int sourceLineNumber)
        {
            numberOfInstances++;
            _message = message;
            _sourceMemberName = sourceMemberName;
            _sourceFilePath = sourceFilePath;
            _sourceLineNumber = sourceLineNumber;
            _stopwatch = new Stopwatch();
            _stopwatch.Start();

            Console.WriteLine(
                $"{new string(' ', numberOfInstances)}
                {_sourceFilePath}:{_sourceLineNumber}:{_sourceMemberName} started {_message}");
        }

        public void Dispose()
        {
            _stopwatch.Stop();

            Console.WriteLine(
                $"{new string(' ', numberOfInstances)}
                {_sourceFilePath}:{_sourceLineNumber}:{_sourceMemberName} 
                finished {_message} in {_stopwatch.Elapsed}");

            numberOfInstances--;
        }

        internal static IDisposable CreatePerfomanceLogger(
            string message,
            [CallerMemberName] string sourceMemberName = "",
            [CallerFilePath] string sourceFilePath = "",
            [CallerLineNumber] int sourceLineNumber = 0)
        {
            return new PerfomanceLogger(message, sourceMemberName, sourceFilePath, sourceLineNumber);
        }
    }
}

So let’s look at it from the top down:

• The class implements IDisposable, this allows us to call the Dispose method in a deterministic and automated way (more on that when we see the usage).
• We have a static counter that counts the number of running instances so that we can properly indent our logs for readability purposes.
• A set of private read-only fields so that we can store the information that was passed down from the caller so we can use it in the Dispose method.
• We have a private constructor, in this case, it will make it easier to build our logger with the using construct making away with remembering to use the new keyword.
• Inside the constructor, we increment the instance counter, store the incoming data, start the stopwatch and we log the start of the logger with the message prefixed by the incoming information and with the appropriate indentation (this can be changed for any logic we desire later on, like using Nlog, or a database).
• The Dispose method that needs to be implemented due to us using the IDisposable interface. In this method, we stop the stopwatch since the scope of our logging has ended, then we log the same information as in the constructor with the added elapsed time at the end so that we know how much that particular scope took.
• We have a static factory method that returns an IDisposable implementation and received 4 optional parameters, let’s look at each one and what it does:
  • message – This is nothing special but a message we want to input into our logger so that maybe we can give a custom message for logging.
  • sourceMemberName – This parameter is decorated with the [CallerMemberName] attribute and it must be optional to work properly, that attribute tells the run time that when this method is called and no value is provided to that parameter (yes, it can be overwritten when called), then the default value for that parameter will be the name of the method that called it.
  • sourceFileName – This one is decorated with the [CallerFilePath] attribute and as such, it behaves just like the one above but instead of the member name, the default value will be the file path for where this method was called from.
  • sourceLineNumber – Same as above but with the [CallerLineNumber] attribute, this will be prepopulated with the line number where this method was called from.

Now let us apply this construct in our code, and see what it outputs:

namespace ConsoleApp1
{
    using System;
    using System.Threading;

    internal static class Program
    {
        public static void Main()
        {
            using (PerfomanceLogger.CreatePerfomanceLogger())
            {
                int sum;
                using (PerfomanceLogger.CreatePerfomanceLogger("Performing Random Computation"))
                {
                    sum = SumFirstMillionNumbers();
                }

                using (PerfomanceLogger.CreatePerfomanceLogger("Perform another a longer computation"))
                {
                    for (int i = 0; i < sum / 1_000_000; i++)
                    {
                        Thread.Sleep(1);
                    }
                }
            }

            Console.ReadLine();
        }

        private static int SumFirstMillionNumbers()
        {
            int sum = 0;
            using (PerfomanceLogger.CreatePerfomanceLogger("Running Inner Sum"))
            {
                for (int i = 0; i < 1000000; i++)
                {
                    sum += i;
                }
            }

            return sum;
        }
    }
}

Notice using statements when we’re creating the loggers:

• The main one has no parameters passed into it.
• The following two loggers have a message and they are both at the same nesting level.
• There is also a logger create inside the SumFirstMillionNumbers method.

When we run this, we will have something like the following output:

As we can see, we have logged the file where the logging took place, on which line it took place and every nested logger is properly indented.

Conclusion

As we saw, by leveraging the using construct, we can take advantage of scopes declaring where the logging should start and stop. This post contains an example of what can be achieved using this technique, though not really for what IDisposable was created, it can be of help nonetheless.

We also saw the caller information attributes and how they are used.

Though there are two obvious downsides to using this approach:

1. As we saw in the Main method, the sum variable needed to be declared out of scope if we wanted to use it later. This means that if we want to use this approach in a production application, there might be times where variables need to be pulled out of scope so we can run our logging.
2. Since we are doing additional logic around our code, there will be a performance penalty associated with it depending on how often and deep we log and on what we use to log. Even if not obvious, a console application that logs on the screen still runs slower than a console that displays nothing (believe me, I tried it on console tasks that ran between 8 and 16 hours and the difference was at least 30 minutes performance that was lost due to the logging).

Otherwise, feel free to experiment with this and I’m curious what other uses you find for IDisposable.

Thank you and I’ll see you next time.

CodeProject