Is my method of measuring running time flawed?

Question

Sorry, it's a long one, but I'm just explaining my train of thought as I analyze this. Questions at the end.

I have an understanding of what goes into measuring running times of code. It's run multiple times to get an average running time to account for differences per run and also to get times when the cache was utilized better.

In an attempt to measure running times for someone, I came up with this code after multiple revisions.

In the end I ended up with this code which yielded the results I intended to capture without giving misleading numbers:

// implementation C
static void Test<T>(string testName, Func<T> test, int iterations = 1000000)
{
    Console.WriteLine(testName);
    Console.WriteLine("Iterations: {0}", iterations);
    var results = Enumerable.Repeat(0, iterations).Select(i => new System.Diagnostics.Stopwatch()).ToList();
    var timer = System.Diagnostics.Stopwatch.StartNew();
    for (int i = 0; i < results.Count; i++)
    {
        results[i].Start();
        test();
        results[i].Stop();
    }
    timer.Stop();
    Console.WriteLine("Time(ms): {0,3}/{1,10}/{2,8} ({3,10})", results.Min(t => t.ElapsedMilliseconds), results.Average(t => t.ElapsedMilliseconds), results.Max(t => t.ElapsedMilliseconds), timer.ElapsedMilliseconds);
    Console.WriteLine("Ticks:    {0,3}/{1,10}/{2,8} ({3,10})", results.Min(t => t.ElapsedTicks), results.Average(t => t.ElapsedTicks), results.Max(t => t.ElapsedTicks), timer.ElapsedTicks);
    Console.WriteLine();
}

---

Of all the code I've seen that measures running times, they were usually in the form:

// approach 1 pseudocode
start timer;
loop N times:
    run testing code (directly or via function);
stop timer;
report results;

This was good in my mind since with the numbers, I have the total running time and can easily work out the average running time and would have good cache locality.

But one set of values that I thought were important to have were minimum and maximum iteration running time. This could not be calculated using the above form. So when I wrote my testing code, I wrote them in this form:

// approach 2 pseudocode
loop N times:
    start timer;
    run testing code (directly or via function);
    stop timer;
    store results;
report results;

This is good because I could then find the minimum, maximum as well as average times, the numbers I was interested in. Until now I realized that this could potentially skew results since the cache could potentially be affected since the loop wasn't very tight giving me less than optimal results.

---

The way I wrote the test code (using LINQ) added additional overheads which I knew about but ignored since I was just measuring the running code, not the overheads. Here was my first version:

// implementation A
static void Test<T>(string testName, Func<T> test, int iterations = 1000000)
{
    Console.WriteLine(testName);
    var results = Enumerable.Repeat(0, iterations).Select(i =>
    {
        var timer = System.Diagnostics.Stopwatch.StartNew();
        test();
        timer.Stop();
        return timer;
    }).ToList();
    Console.WriteLine("Time(ms): {0,3}/{1,10}/{2,8}", results.Min(t => t.ElapsedMilliseconds), results.Average(t => t.ElapsedMilliseconds), results.Max(t => t.ElapsedMilliseconds));
    Console.WriteLine("Ticks:    {0,3}/{1,10}/{2,8}", results.Min(t => t.ElapsedTicks), results.Average(t => t.ElapsedTicks), results.Max(t => t.ElapsedTicks));
    Console.WriteLine();
}

Here I thought this was fine since I'm only measuring the times it took to run the test function. The overheads associated with LINQ are not included in the running times. To reduce the overhead of creating timer objects within the loop, I made the modification.

// implementation B
static void Test<T>(string testName, Func<T> test, int iterations = 1000000)
{
    Console.WriteLine(testName);
    Console.WriteLine("Iterations: {0}", iterations);
    var results = Enumerable.Repeat(0, iterations).Select(i => new System.Diagnostics.Stopwatch()).ToList();
    results.ForEach(t =>
    {
        t.Start();
        test();
        t.Stop();
    });
    Console.WriteLine("Time(ms): {0,3}/{1,10}/{2,8} ({3,10})", results.Min(t => t.ElapsedMilliseconds), results.Average(t => t.ElapsedMilliseconds), results.Max(t => t.ElapsedMilliseconds), results.Sum(t => t.ElapsedMilliseconds));
    Console.WriteLine("Ticks:    {0,3}/{1,10}/{2,8} ({3,10})", results.Min(t => t.ElapsedTicks), results.Average(t => t.ElapsedTicks), results.Max(t => t.ElapsedTicks), results.Sum(t => t.ElapsedTicks));
    Console.WriteLine();
}

This improved overall times but caused a minor problem. I added the total running time in the report by adding each iteration's times but gave misleading numbers since the times were short and didn't reflect the actual running time (which was usually much longer). I needed to measure the time of the entire loop now so I moved away from LINQ and ended up with the code I have now at the top. This hybrid gets the the times I think are important with minimal overhead AFAIK. (starting and stopping the timer just queries the high resolution timer) Also any context switching occurring is unimportant to me as it's part of normal execution anyway.

At one point, I forced the thread to yield within the loop to make sure that it is given the chance at some point at a convenient time (if the test code is CPU bound and doesn't block at all). I'm not too concerned about the processes running which might change the cache for the worse since I would be running these tests alone anyway. However, I came to the conclusion that for this particular case, it was unnecessary to have. Though I might incorporate it in THE final final version if it proves beneficial in general. Perhaps as an alternate algorithm for certain code.

---

Now my questions:

• Did I make some right choices? Some wrong ones?
• Did I make wrong assumptions about the goals in my thought process?
• Would the minimum or maximum running times really be useful information to have or is it a lost cause?
• If so, which approach would be better in general? The time running in a loop (approach 1)? Or the time running just the code in question (approach 2)?
• Would my hybrid approach be ok to use in general?
• Should I yield (for reasons explained in the last paragraph) or is that more harm to the times than necessary?
• Is there a more preferred way to do this that I did not mention?

Just to be clear, I'm not looking for an all-purpose, use anywhere, accurate timer. I just want to know of an algorithm that I should use when I want a quick to implement, reasonably accurate timer to measure code when a library or other 3rd party tools is not available.

I'm inclined to write all my test code in this form should there be no objections:

// final implementation
static void Test<T>(string testName, Func<T> test, int iterations = 1000000)
{
    // print header
    var results = Enumerable.Repeat(0, iterations).Select(i => new System.Diagnostics.Stopwatch()).ToList();
    for (int i = 0; i < 100; i++) // warm up the cache
    {
        test();
    }
    var timer = System.Diagnostics.Stopwatch.StartNew(); // time whole process
    for (int i = 0; i < results.Count; i++)
    {
        results[i].Start(); // time individual process
        test();
        results[i].Stop();
    }
    timer.Stop();
    // report results
}

---

For the bounty, I would ideally like to have all the above questions answered. I'm hoping for a good explanation on whether my thoughts which influenced the code here well justified (and possibly thoughts on how to improve it if suboptimal) or if I was wrong with a point, explain why it's wrong and/or unnecessary and if applicable, offer a better alternative.

To summarize the important questions and my thoughts for the decisions made:

1. Is getting the running time of each individual iteration generally a good thing to have?
   With the times for each individual iteration, I can calculate additional statistical information like the minimum and maximum running times as well as standard deviation. So I can see if there are factors such as caching or other unknowns may be skewing the results. This lead to my "hybrid" version.
2. Is having a small loop of runs before the actual timing starts good too?
   From my response to Sam Saffron's thought on the loop, this is to increase the likelihood that constantly accessed memory will be cached. That way I'm measuring the times only for when everything is cached, rather than some of the cases where memory access isn't cached.
3. Would a forced Thread.Yield() within the loop help or hurt the timings of CPU bound test cases?
   If the process was CPU bound, the OS scheduler would lower the priority of this task potentially increasing times due to lack of time on the CPU. If it is not CPU bound, I would omit the yielding.

---

Based on the answers here, I'll be writing my test functions using the final implementation without the individual timings for the general case. If I would like to have other statistical data, I would reintroduce it back into the test function as well as apply the other things mentioned here.

Answer 1

My first thought is that a loop as simple as

for (int i = 0; i < x; i++)
{
    timer.Start();
    test();
    timer.Stop();
}

is kinda silly compared to:

timer.Start();
for (int i = 0; i < x; i++)
    test();
timer.Stop();

the reason is that (1) this kind of "for" loop has a very tiny overhead, so small that it's not worth worrying about even if test() only takes a microsecond, and (2) timer.Start() and timer.Stop() have their own overhead, which is likely to affect the results more than the for loop. That said, I took a peek at Stopwatch in Reflector and noticed that Start() and Stop() are fairly cheap (calling Elapsed* properties is likely more expensive, considering the math involved.)

Make sure the IsHighResolution property of Stopwatch is true. If it's false, Stopwatch uses DateTime.UtcNow, which I believe is only updated every 15-16 ms.

1. Is getting the running time of each individual iteration generally a good thing to have?

It is not usually necessary to measure the runtime of each individual iteration, but it is useful to find out how much the performance varies between different iterations. To this end, you can compute the min/max (or k outliers) and standard deviation. Only the "median" statistic requires you to record every iteration.

If you find that the standard deviation is large, you might then have reason to reason to record every iteration, in order to explore why the time keeps changing.

Some people have written small frameworks to help you do performance benchmarks. For example, CodeTimers. If you are testing something that is so tiny and simple that the overhead of the benchmark library matters, consider running the operation in a for-loop inside the lambda that the benchmark library calls. If the operation is so tiny that the overhead of a for-loop matters (e.g. measuring the speed of multiplication), then use manual loop unrolling. But if you use loop unrolling, remember that most real-world apps don't use manual loop unrolling, so your benchmark results may overstate the real-world performance.

For myself I wrote a little class for gathering min, max, mean, and standard deviation, which could be used for benchmarks or other statistics:

// A lightweight class to help you compute the minimum, maximum, average
// and standard deviation of a set of values. Call Clear(), then Add(each
// value); you can compute the average and standard deviation at any time by 
// calling Avg() and StdDeviation().
class Statistic
{
    public double Min;
    public double Max;
    public double Count;
    public double SumTotal;
    public double SumOfSquares;

    public void Clear()
    {
        SumOfSquares = Min = Max = Count = SumTotal = 0;
    }
    public void Add(double nextValue)
    {
        Debug.Assert(!double.IsNaN(nextValue));
        if (Count > 0)
        {
            if (Min > nextValue)
                Min = nextValue;
            if (Max < nextValue)
                Max = nextValue;
            SumTotal += nextValue;
            SumOfSquares += nextValue * nextValue;
            Count++;
        }
        else
        {
            Min = Max = SumTotal = nextValue;
            SumOfSquares = nextValue * nextValue;
            Count = 1;
        }
    }
    public double Avg()
    {
        return SumTotal / Count;
    }
    public double Variance()
    {
        return (SumOfSquares * Count - SumTotal * SumTotal) / (Count * (Count - 1));
    }
    public double StdDeviation()
    {
        return Math.Sqrt(Variance());
    }
    public Statistic Clone()
    {
        return (Statistic)MemberwiseClone();
    }
};

2. Is having a small loop of runs before the actual timing starts good too?

Which iterations you measure depends on whether you care most about startup time, steady-state time or total runtime. In general, it may be useful to record one or more runs separately as "startup" runs. You can expect the first iteration (and sometimes more than one) to run more slowly. As an extreme example, my GoInterfaces library consistently takes about 140 milliseconds to produce its first output, then it does 9 more in about 15 ms.

Depending on what the benchmark measures, you may find that if you run the benchmark right after rebooting, the first iteration (or first few iterations) will run very slowly. Then, if you run the benchmark a second time, the first iteration will be faster.

3. Would a forced Thread.Yield() within the loop help or hurt the timings of CPU bound test cases?

I'm not sure. It may clear the processor caches (L1, L2, TLB), which would not only slow down your benchmark overall but lower the measured speeds. Your results will be more "artificial", not reflecting as well what you would get in the real world. Perhaps a better approach is to avoid running other tasks at the same time as your benchmark.

Answer 2

Regardless of the mechanism for timing your function (and the answers here seems fine) there is a very simple trick to eradicate the overhead of the benchmarking-code itself, i.e. the overhead of the loop, timer-readings, and method-call:

Simply call your benchmarking code with an empty Func<T> first, i.e.

void EmptyFunc<T>() {}

This will give you a baseline of the timing-overhead, which you can essentially subtract from the latter measurements of your actual benchmarked function.

By "essentially" I mean that there are always room for variations when timing some code, due to garbage collection and thread and process scheduling. A pragmatic approach would e.g. be to benchmark the empty function, find the average overhead (total time divided by iterations) and then subtract that number from each timing-result of the real benchmarked function, but don't let it go below 0 which wouldn't make sense.

You will, of course, have to re-arrange your benchmarking code a bit. Ideally you'll want to use the exact same code to benchmark the empty function and real benchmarked function, so I suggest you move the timing-loop into another function or at least keep the two loops completely alike. In summary

1. benchmark the empty function
2. calculate the average overhead from the result
3. benchmark the real test-function
4. subtract the average overhead from those test results
5. you're done

By doing this the actual timing mechanism suddenly becomes a lot less important.

Answer 3

I think your first code sample seems like the best approach.

Your first code sample is small, clean and simple and doesn't use any major abstractions during the test loop which may introduce hidden overhead.

Use of the Stopwatch class is a good thing as it simplifies the code one normally has to write to get high-resolution timings.

One thing you might consider is providing the option to iterate the test for a smaller number of times untimed before entering the timing loop to warm up any caches, buffers, connections, handles, sockets, threadpool threads etc. that the test routine may exercise.

HTH.