ExecutionStopwatch

• Download source code - 5.53 KB

Introduction 

A common diagnostic task is to measure the performance of your code. To do that, the .NET Framework offers the System.Diagnostics.Stopwatch class. This, however, is not truly intended for code performance measured, and would return false values in your measuring (explained in the ExecutionStopwatch vs .NET Stopwatch paragraph).

The ExecutionStopwatch delivers an accurate way for measuring your code performance.

ExecutionStopwatch vs .NET Stopwatch

The .NET Framework already contains a time measuring mechanism that could be found in the Stopwatch class (under System.Diagnostics). However, the sole purpose of this class is to measure the amount of "real-world" time passed. Meaning, if you will attempt to use the Stopwatch class in order to measure the execution time of a method, you will also measure time spent by other background threads. Theoretically, you would like to call "Stop()" each time your OS performs a context switch to another thread, since you are not interested in measuring the time the CPU spent on executing unrelated work.

The ExecutionStopwatch achieves just that - the amount of time the CPU spent on executing your current thread only. Time spent on executing other system threads will not be counted.
This is done by using the Win32 function GetThreadTimes that returns time values relating to a particular thread, and not your system's global time (as the Stopwatch class does).

Demonstration

In order to demonstrate the difference in the behavior between the .NET's original Stopwatch class and between the ExecutionStopwatch class, I've come up with the following example:

class Program
{
	static void Main()
	{
		Stopwatch regularSW = new Stopwatch();
		ExecutionStopwatch executionSW = new ExecutionStopwatch();

		regularSW.Start();
		executionSW.Start();

		// the thread won't be executed for 5 seconds
		Thread.Sleep(5000);

		regularSW.Stop();
		executionSW.Stop();

		Console.WriteLine("Regular Stopwatch: {0}", regularSW.Elapsed);
		Console.WriteLine("Execution Stopwatch: {0}", executionSW.Elapsed);

		// Output:
		// 	Regular Stopwatch: 00:00:04.9900562
		// 	Execution Stopwatch: 00:00:00
	}
}

The difference can be noticed immediately. While the .NET Stopwatch measured 4.9 seconds, the ExecutionStopwatch measured ~0 seconds (Window's time accuracy stands on about 15ms).
While the Stopwatch measured the total clock time passed, the ExecutionStopwatch measured the time the CPU spent executing the code. 

Source Code

using System;
using System.Collections.Generic;
using System.Text;
using System.Runtime.InteropServices;

namespace DiagnosticsUtils
{
	public class ExecutionStopwatch
	{
		[DllImport("kernel32.dll")]
		private static extern long GetThreadTimes
			(IntPtr threadHandle, out long createionTime,
			 out long exitTime, out long kernelTime, out long userTime);

		[DllImport("kernel32.dll")]
		private static extern IntPtr GetCurrentThread();

		private long m_endTimeStamp;
		private long m_startTimeStamp;

		private bool m_isRunning;

		public void Start()
		{
			m_isRunning = true;

			long timestamp = GetThreadTimes();
			m_startTimeStamp = timestamp;
		}

		public void Stop()
		{
			m_isRunning = false;

			long timestamp = GetThreadTimes();
			m_endTimeStamp = timestamp;
		}

		public void Reset()
		{
			m_startTimeStamp = 0;
			m_endTimeStamp = 0;
		}

		public TimeSpan Elapsed
		{
			get
			{
				long elapsed = m_endTimeStamp - m_startTimeStamp;
				TimeSpan result = 
					TimeSpan.FromMilliseconds(elapsed / 10000);
				return result;
			}
		}

		public bool IsRunning
		{
			get { return m_isRunning; }
		}

		private long GetThreadTimes()
		{
			IntPtr threadHandle = GetCurrentThread();

			long notIntersting;
			long kernelTime, userTime;

			long retcode = GetThreadTimes
				(threadHandle, out notIntersting,
				out notIntersting, out kernelTime, out userTime);

			bool success = Convert.ToBoolean(retcode);
			if (!success)
				throw new Exception(string.Format
				("failed to get timestamp. error code: {0}", 
				retcode));

			long result = kernelTime + userTime;
			return result;
		}
	}
}

History

• 22^nd November, 2008: 1.0 - Original article