I do performance measurements quite regularly which involves to call a piece of code several times to measure how long it did take. I am sure nearly everybody has done this already. But as a physicist I know that (nearly) every measurement has fundamental problems which never go away. Key to a successful measurement is that you exactly know what you are measuring and not what you think you measure. The easiest way to get out of this dilemma without too much knowledge is to simply ignore the fact that you don´t know enough and restrict yourself to pure differential measurements. With differential I do mean that you measure it once, change the code in a way that makes it better and measure it again. When you measure different times then you can assume that your code change was the cause for the different timing. That does work to some extent quite well but you should always be vigilant when the results change dramatically from one build to the next. There is no error I did not make with performance measurements so I think it is safe to give away my top 101:
You still want to make some quick throw away measurements? You have been warned. It is a tricky thing. To get at least the timing calculation right I did create some extension methods I want to share there. With these extensions you can create an Action delegate and call the new Profile method on it to execute it n-times. To give you full control over the string formatting you can supply a format string which expands {runs}, {time} and {frequency} in a human readable way for you.
Since we know that the first call to File.Open will involve actual disk accesses which are much slower we want to measure the first call independently to see the "cold" startup performance as well:
There are also times when you want to control the number of iterations by yourself. Nothing easier than that. Simply change the delegate type from Action to Func<int> and you are ready to go.
That was almost too easy. But what if I do not like the formatting? Well it turns out you can customize it still. The format string placeholders {0} {1} and {2} are the number of runs, elapsed time in seconds as float and call frequency (runs/s) as float. They can be used as usual to customize the output format to your specific needs.
The actual class is written in C# 3.0 with lambda expressions. The usage of this rather low level primitives gives you a rather surprising amount of flexibility and composability to build higher level functions.
using System;
using System.Globalization;
using System.Diagnostics;
namespace PerformanceTester
{
/// <summary>
/// Helper class to print out performance related data like number of runs, elapsed time and frequency
/// </summary>
public static class Extension
{
static NumberFormatInfo myNumberFormat;
static NumberFormatInfo NumberFormat
{
get
{
if (myNumberFormat == null)
{
var local = new CultureInfo("en-us", false).NumberFormat;
local.NumberGroupSeparator = " "; // set space as thousand separator
myNumberFormat = local; // make a thread safe assignment with a fully initialized variable
}
return myNumberFormat;
}
}
/// <summary>
/// Execute the given function and print the elapsed time to the console.
/// </summary>
/// <param name="func">Function that returns the number of iterations.</param>
/// <param name="format">Format string which can contain {runs} or {0},{time} or {1} and {frequency} or {2}.</param>
public static void Profile(this Func<int> func, string format)
{
Stopwatch watch = Stopwatch.StartNew();
int runs = func(); // Execute function and get number of iterations back
watch.Stop();
string replacedFormat = format.Replace("{runs}", "{3}")
.Replace("{time}", "{4}")
.Replace("{frequency}", "{5}");
// get elapsed time back
float sec = watch.ElapsedMilliseconds / 1000.0f;
float frequency = runs / sec; // calculate frequency of the operation in question
try
{
Console.WriteLine(replacedFormat,
runs, // {0} is the number of runs
sec, // {1} is the elapsed time as float
frequency, // {2} is the call frequency as float
runs.ToString("N0", NumberFormat), // Expanded token {runs} is formatted with thousand separators
sec.ToString("F2", NumberFormat), // expanded token {time} is formatted as float in seconds with two digits precision
frequency.ToString("N0", NumberFormat)); // expanded token {frequency} is formatted as float with thousands separators
}
catch (FormatException ex)
{
throw new FormatException(
String.Format("The input string format string did contain not an expected token like "+
"{{runs}}/{{0}}, {{time}}/{{1}} or {{frequency}}/{{2}} or the format string " +
"itself was invalid: \"{0}\"", format), ex);
}
}
/// <summary>
/// Execute the given function n-times and print the timing values (number of runs, elapsed time, call frequency)
/// to the console window.
/// </summary>
/// <param name="func">Function to call in a for loop.</param>
/// <param name="runs">Number of iterations.</param>
/// <param name="format">Format string which can contain {runs} or {0},{time} or {1} and {frequency} or {2}.</param>
public static void Profile(this Action func, int runs, string format)
{
Func<int> f = () =>
{
for (int i = 0; i < runs; i++)
{
func();
}
return runs;
};
f.Profile(format);
}
/// <summary>
/// Call a function in a for loop n-times. The first function call will be measured independently to measure
/// first call effects.
/// </summary>
/// <param name="func">Function to call in a loop.</param>
/// <param name="runs">Number of iterations.</param>
/// <param name="formatFirst">Format string for first function call performance.</param>
/// <param name="formatOther">Format string for subsequent function call performance.</param>
/// <remarks>
/// The format string can contain {runs} or {0},{time} or {1} and {frequency} or {2}.
/// </remarks>
public static void ProfileWithFirst(this Action func, int runs, string formatFirst, string formatOther)
{
func.Profile(1, formatFirst);
func.Profile(runs - 1, formatOther);
}
}
}