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:
- DateTime.Now has a resolution of ~16ms. If you measure anything faster you must use Stopwatch which has a resolution of about 100ns.
- With Windows Vista you need to set your Power options to maximum performance to prevent the OS from change the CPU clock frequency at random times.
- Warm and cold start times are way different. Usually a factor of 2-6 is quite normal. With cold startup I mean that you have a fresh booted system which did have never run your test case. This cold startup time does mainly contribute to disk IO which you can watch with XPerf very nicely.
- Be sure that you measure the right thing. I cannot emphasize this enough. Did you really measure the right thing?
- Know your influencers. You need to get a good understanding how much e.g. number of iterations, input data size, concurrency, other applications can affect the outcome. I had more than once the case that I did execute a test in the evening and then next morning. But the results did differ by a factor two for no apparent reason.
- Debug and Release builds still differ in the managed world. Although the difference is much smaller than it was with C++.
- First time initialization effects should be measured separately. When you initialize a class and call some method 10 million times it makes not much sense to mix the ctor call time with pure function calling time.
- Do measure long enough to get reliable results. The mean value is a powerful ally to flatten sporadic effects.
- If you get strange disk IO reports check if a virus scanner does interfere.
- Other processes might be running as well. These might influence your test if they consume significant resources.
- Stupid but happens: Turn off tracing before you measure.
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.
Action func = () =>
{
using (File.OpenRead(@"C:\config.sys"))
{
}
};
func.Profile(1000, "Did open the file {runs} times in {time}s. Can do {frequency} File.Open/s");That little snippet produces on the console
Did open the file 1 000 times in 0.06s. Can do 16 667 File.Open/s
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:
func.ProfileWithFirst(1000, "First File Open did take {time}s", "Did open the file {runs} times in {time}s. Can do {frequency} File.Open/s");That will give us
First File Open did take 0.00s
Did open the file 999 times in 0.05s. Can do 20 388 File.Open/s
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.
Func<int> myFunc = () =>
{
const int Runs = 1000;
for (int i = 0; i < Runs; i++)
{
using (File.OpenRead(@"C:\config.sys")) ;
using (File.OpenRead(@"C:\autoexec.bat")) ;
}
return Runs * 2;
};myFunc.Profile(“Did open {runs} files in {time}s”);
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.
myFunc.Profile("Did open {runs} files in {1:F5}s");
Did open 2 000 files in 0,10000sThe 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.
Here is the source code for the Action and Func<int> delegate extension methods:
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);
}
}
}
}
