In-Code Profiling with C# and log4net

There are many tools that can be used for profiling software. These tools are a great enrichment for our job, but sometimes they are oversized. Sometimes, you need a small solution for a particular piece of code. If you find yourself at this point, I will show you a solution here.

The small piece of code, I want to show you, takes advantage of the using statement and the IDisposeable interface. The using statement can wonderful be used in order to encapsulate the code that you want to profile.

using (new ProfileRegion("RefreshContent"))
{
    #region Code you want to profile ....
}

The output is done with log4net and might look like:

2007-10-04 20:21:10,585 [5388] WARN : End Profiling: 4,986 seconds in region RefreshContent

The time will be logged as a warning when the given time span (default = 2 seconds) will be exceeded. Otherwise the profiling section will be logged as a debug message.

I think that is really a nice small class you can perfectly adopt in your project. What do you think?

Cheers
- Gerhard

kick it on DotNetKicks.com


using System;
using log4net;

namespace AdFactum.Utils
{
    /// <summary>
    /// This class describes a profiled region
    /// </summary>
    public class ProfileRegion : IDisposable
    {
        private readonly ILog log = LogManager.GetLogger(typeof(ProfileRegion));
        
        private DateTime startTime;
        private DateTime? endTime = null;
        
        private TimeSpan watermark = new TimeSpan(0, 0, 2);
        private string regionName;
        
        /// <summary>
        /// Gets the elapsed time.
        /// </summary>
        /// <value>The elapsed time.</value>
        public TimeSpan ElapsedTime
        {
            get
            {
                return (endTime == null) ?
                DateTime.Now - startTime :
                endTime.Value - startTime;
            }
        }
        
        /// <summary>
        /// Initializes a new instance of the <see cref="ProfileRegion"/> class.
        /// </summary>
        /// <param name="name">The name.</param>
        public ProfileRegion (string name)
        {
            regionName = name;
            startTime = DateTime.Now;
            
            if (log.IsDebugEnabled)
            log.Debug(string.Concat("Start Profiling: ", regionName));
        }
        
        /// <summary>
        /// Initializes a new instance of the <see cref="ProfileRegion"/> class.
        /// </summary>
        /// <param name="name">The name.</param>
        /// <param name="watermarkParam">The watermark param.</param>
        public ProfileRegion (string name, TimeSpan watermarkParam)
        :this(name)
        {
            watermark = watermarkParam;
        }
        
        /// <summary>
        /// Releases unmanaged resources and performs other cleanup operations before the
        /// <see cref="ProfileRegion"/> is reclaimed by garbage collection.
        /// </summary>
        ~ProfileRegion()
        {
            Dispose(false);
        }
        
        /// <summary>
        /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
        /// </summary>
        public void Dispose()
        {
            Dispose(true);
            GC.SuppressFinalize(this);
        }
        
        /// <summary>
        /// Releases unmanaged and - optionally - managed resources
        /// </summary>
        /// <param name="disposed"><c>true</c> to release both managed and unmanaged resources; <c>false</c> to release only unmanaged resources.</param>
        public void Dispose (bool disposed)
        {
            endTime = DateTime.Now;
            if (!disposed)
            log.Error(string.Concat("Region ", regionName, " not finalized by Dispose call!"));
            
            if (ElapsedTime < watermark)
            {
                if (log.IsDebugEnabled)
                log.Debug(string.Concat("End Profiling: ", ElapsedTime.TotalSeconds, " seconds in region ", regionName));
            }
            else
            {
                if (log.IsWarnEnabled)
                log.Warn(string.Concat("End Profiling: ", ElapsedTime.TotalSeconds, " seconds in region ", regionName));
            }
        }
    }
}

About these ads
Posted in .NET, C#. 5 Comments »

5 Responses to “In-Code Profiling with C# and log4net”

  1. Simone Busoli Says:

    That’s sweet. Only thing you may want to consider is using a Stopwatch instead of datetimes, it’s created exactly for this purpose.

  2. Tom Says:

    nice!

    you could also add some #if(DEBUG) s so that your profiling doesn’t get invoked in a production environment….

  3. Gerhard Stephan Says:

    You could add a #if(DEBUG), but I think it’s not necessary and sometimes unwanted. What, if you have performance issues in production and want to trace out the times …

    I think it’s enough to implement “if (log.IsDebugEnabled)”. That’s a bit more dynamic than using #if (DEBUG) …

  4. Bill Brown Says:

    Stopwatch is new in 2.0, so his class will work in all environments. Thanks for the heads-up about Stopwatch though—I wasn’t aware of it.

    It was very easy to change. Change the DateTimes into private Stopwatch stopwatch; and then put stopwatch = Stopwatch.StartNew(); calls into the constructors. In the Dispose(bool), call stopwatch.Stop(); and then substitute stopwatch.Elapsed for the ElapsedTime—they’re both TimeSpans.

  5. Seiti Says:

    Really nice class. Just adapted to use Stopwatch and included in my current project! Thanks!


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 106 other followers

%d bloggers like this: