Log Timmer

One common challenge in developing software is tuning performance. The application is running slow but you are not sure what is causing the problem. An approach to the debugging the problem is to use logging. This works, but you end up doing a lot of time arithmetic to determine how long it took some action to complete. Logging also adds many lines of code to the application muddling up the implementation and making it harder to read and understand. The solution is a class designed to time and log an event. I give credit to Scott Plichta for designing the architecture for the Log Timer.

Creating a log in C++ is easy. The constructor starts the timer and the destructor calculates the elapsed time and logs the results. This is a problem in Java. In Java, destructors are may not be called until the garbage collector runs. C# also uses garbage collection, but provides the IDisposable interface. IDisposable tells the garbage collector to dispose of the object as soon as possible. That means the timings provided by a log timer class in C# are not quite as accurate as the timing in a C++ log timer class.

How do you use the log timer class work in C#? The simplest method is just to place a "using" statement creating the log timer around the code you want to time:

using (new LogTimer.LogTimer())
{
    // code you want to time
}

Call that is a little more complicated allows passing in the custom message:

using (new LogTimer.LogTimer("Deserialize time: "))
{
    // code you want to time
}

The code above will always log. The LogTimer class has constructors that allow passing in the number of milliseconds for logging for each of the Log4Net levels. Below is an example passing in all the level thresholds:

using (new LogTimer.LogTimer("DownloadImage GetReponse time: ", 5000, 3000, 2000, 100, 0))
{
    // code you want to time
}

There are several other constructors taking different number of thresholds.  Below is the implementation of the LogTimer class in C#.

using System;
using System.Collections.Generic;
using System.Text;

using log4net.Core;
using System.Diagnostics;

namespace LogTimer
{
    // based on:
    // http://www.eggheadcafe.com/articles/20050625.asp
    // http://www.codeproject.com/KB/cs/idispose.aspx

    public class LogTimer : IDisposable
    {
        /// <summary>
        /// Create a logger for use in this class
        /// </summary>
        private static readonly log4net.ILog log = log4net.LogManager.GetLogger(typeof(LogTimer));

        /// <summary>
        /// Used by the destructor to avoid disposing twice
        /// </summary>
        private bool disposed = false;

        /// <summary>
        /// Default message
        /// </summary>
        private string msg = "LogTimer: ";

        /// <summary>
        /// Threashold in milliseconds before issuing a debug log
        /// </summary>
        private readonly long debugCount = 0;

        /// <summary>
        /// Threashold in milliseconds before issuing a info log
        /// </summary>
        private readonly long infoCount = 0;

        /// <summary>
        /// Threashold in milliseconds before issuing a warn log
        /// </summary>
        private readonly long warnCount = 0;

        /// <summary>
        /// Threashold in milliseconds before issuing a error log
        /// </summary>
        private readonly long errorCount = 0;

        /// <summary>
        /// Threashold in milliseconds before issuing a fatal log
        /// </summary>
        private readonly long fatalCount = 0;

        /// <summary>
        /// Stopwatch to determine how long between starting and stopping
        /// </summary>
        private Stopwatch sw = new Stopwatch();


        /// <summary>
        /// Simple constructor that generates a default message for the current log level
        /// </summary>
        public LogTimer()
        {
            sw.Start();
        }

        /// <summary>
        /// Simple constructor that generates the messages for the current log level
        /// </summary>
        /// <param name="message">The message to log</param>
        public LogTimer(string message) : base()
        {
            msg = message;
        }

        /// <summary>
        /// Most comprehensive constructor. Allows setting all the properties.
        /// </summary>
        /// <param name="message">Message to log</param>
        /// <param name="fatal">Threshold for fatal logs</param>
        /// <param name="error">Threashold for error logs</param>
        /// <param name="warn">Threashold for warn logs</param>
        /// <param name="info">Threashold for info logs</param>
        /// <param name="debug">Threadhold for debug logs</param>
        public LogTimer(string message, long fatal, long error, long warn, long info, long debug) : base()
        {
            msg = message;
            fatalCount = fatal;
            errorCount = error;
            warnCount = warn;
            infoCount = info;
            debugCount = debug;
        }

        /// <summary>
        /// Construct allowing setting the message and threasholds for fatal, error, warn, and info.
        /// </summary>
        /// <param name="message">Message to log</param>
        /// <param name="fatal">Threshold for fatal logs</param>
        /// <param name="error">Threashold for error logs</param>
        /// <param name="warn">Threashold for warn logs</param>
        /// <param name="info">Threashold for info and debug logs</param>
        public LogTimer(string message, long fatal, long error, long warn, long info) : base()
        {
            msg = message;
            fatalCount = fatal;
            errorCount = error;
            warnCount = warn;
            infoCount = info;
            debugCount = info;
        }

        /// <summary>
        /// Construct allowing setting the message and threasholds for
        /// fatal, error, and warn.
        /// </summary>
        /// <param name="message">Message to log</param>
        /// <param name="fatal">Threshold for fatal logs</param>
        /// <param name="error">Threashold for error logs</param>
        /// <param name="warn">Threashold for warn, info and debug logs</param>
        public LogTimer(string message, long fatal, long error, long warn) : base()
        {
            msg = message;
            fatalCount = fatal;
            errorCount = error;
            warnCount = warn;
            infoCount = warn;
            debugCount = warn;
        }

        /// <summary>
        /// Construct allowing setting the message and threasholds for
        /// fatal and error
        /// </summary>
        /// <param name="message">Message to log</param>
        /// <param name="fatal">Threshold for fatal logs</param>
        /// <param name="error">Threashold for error, warn, info and debug logs</param>
        public LogTimer(string message, long fatal, long error) : base()
        {
            msg = message;
            fatalCount = fatal;
            errorCount = error;
            warnCount = error;
            infoCount = error;
            debugCount = error;
        }

        /// <summary>
        /// Construct allowing setting the message and threashold
        /// </summary>
        /// <param name="message">Message to log</param>
        /// <param name="fatal">Threshold for fatal, error, warn, info,
        /// and debug logs</param>
        public LogTimer(string message, long fatal) : base()
        {
            msg = message;
            fatalCount = fatal;
            errorCount = fatal;
            warnCount = fatal;
            infoCount = fatal;
            debugCount = fatal;
        }

        /// <summary>
        /// Actual destructor
        /// </summary>
        ~LogTimer()
        {
            Dispose(false);
        }

        /// <summary>
        /// Dispose method
        /// </summary>
        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }

        /// <summary>
        /// Dispos method
        /// </summary>
        /// <param name="disposing">currently disposing</param>
        protected virtual void Dispose(bool disposing)
        {
            if (!this.disposed)
            {
                if (disposing)
                {
                    sw.Stop();
                    long duration = sw.ElapsedMilliseconds;

                    // log with the highest enabled log level
                    // a log level is enable when IsLevelEnable and leveCount > 0
                    if (log.IsFatalEnabled && duration >= fatalCount)
                    {
                        log.Fatal(msg + duration.ToString());
                    }
                    else if (log.IsErrorEnabled && duration >= errorCount)
                    {
                        log.Error(msg + duration.ToString());
                    }
                    else if (log.IsWarnEnabled && duration >= warnCount)
                    {
                        log.Warn(msg + duration.ToString());
                    }
                    else if (log.IsInfoEnabled && duration >= infoCount)
                    {
                        log.Info(msg + duration.ToString());
                    }
                    else if (log.IsDebugEnabled && duration >= debugCount)
                    {
                        log.Debug(msg + duration.ToString());
                    }
                }
            }
            disposed = true;
        }

    }
}