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
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));
}
}
}
}
