Have you ever wanted to know how much time a process takes in your code?  I was recently working on a project where I wanted to compare different techniques of file access and wast trying to remove bottlenecks in the process.  Now of course you have to be very careful with any type of observer in your code as the observer can have adverse effects and wind up reporting back inaccurate information.  As I was just trying to get a relative feel for how long things were taking, I didn't worry too much.  Now on with the class.

What I decided to do was to create a timing class which would initialize on creation and record the system time.  The idea is that I want to profile a particular portion of code, then log the results.  Here is the class and we can talk about each part and why.

public class ProcessTimer : IDisposable
    public string Name { get; set; }
    public Guid Id { get; set; }

    private DateTime _startTime;
    private static readonly ILog log = LogManager.GetLogger(typeof(ProcessTimer));

    public ProcessTimer(string name)
        Name = name;
        Id = Guid.NewGuid();
        _startTime = DateTime.Now;

    public void Dispose()
        // Here, we are done, let's get the total time string.
        var _ts = DateTime.Now - _startTime;

        double leftoverms = _ts.TotalMilliseconds;
        int hours = (int)(leftoverms/(360000));
        leftoverms -= hours * 360000;
        int mins = (int)(leftoverms / (60000));
        leftoverms -= mins * 60000;
        int secs = (int)(leftoverms / (1000));
        leftoverms -= secs * 1000;
        int msecs = (int)leftoverms;
        log.Info(Name + " : " + hours + " Hrs, " + mins + " Mins, " + secs + " Secs, " + msecs + " Msecs.");

At the top of the class, you have two methods for identifying the instance.  You can set the name of the instance so that when the results are logged, you will know what it is you are profiling.  I have also included an optional Guid for further identification but haven't used it in this instance.  Moving on, you have two private fields called _startTime and log.  _startTime records when the class is instantiated and the log is the instance of log4net we are using.  Of course, you can change the code to use your own logging mechanism.  Taking a look at the constructor, we see that it sets the name of the instance, generates a new Guid and then captures the system date and time through DateTime.Now.  So far, we have setup the class, now let's get into the meat of it which happens in the Dispose method.  You may have noticed that the ProcessTimer class implements the IDisposable interface.  This allows us to participate in a using block and have the Dispose method called upon leaving the using block.  I will demonstrate this later.  The first thing we do in the Dispose method is to capture a timespan between the current datetime and the datetime that we captured earlier.  I could use the TimeSpan.TotalMilliseconds method, log that and be done but I wanted to get a little more fancy.  The math that follows breaks the millisecond count up into Hours, Minutes, Seconds and Milliseconds.  For Example, if the result is 23,568 milliseconds, wouldn't it be nicer if it read 23 secs, 568 MSecs.  That is not that big of an issue but what happens when we get into longer processes that take perhaps minutes or even hours.  For example, how long is 4,567,213 milliseconds.  It is not obvious right at first but when you break it down, you get   12 Hours, 4 Minutes, 7 seconds and 213 milliseconds.  That to me seems more useful.  So the way that this is calculated is to make a determination as to first how many hours are represented by the milliseconds by doing integer division by 360,000.  Take the number of hours, * 360,000 and subtract that from the original milliseconds.  YOu can then do the same with minutes (using 60000) and then seconds (using 1000) and you should get a nice breakdown.  Step through the code to see this in action.  Now, on to how you would use this in code.  It's very simple.

using (var m = new ProcessTimer("Testing my Functionality"))
    while (!done)
	done = myObject.Do();

As you can see, anything that needs to be timed, can simply be wrapped with a using statement.  The constructor will get called at the top and the Dispose is called automatically when you leave the block.  Anything you want to time, just wrap it in the process timer and it will be called and logged.  Finally, let's see what the log looks like.  This is the sample line from the log4net file.


INFO 9 ConsoleApplication2.ProcessTimer - Testing my Functionality: 0 Hrs, 0 Mins, 18 Secs, 957 Msecs.

Please take this base and move it around to suit your needs.