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

I tend to agree with @Sam Saffron about using one Stopwatch rather than one per iteration. In your example you performing 1000000 iterations by default. I don't know what the cost of creating a single Stopwatch is, but you are creating 1000000 of them. Conceivably, that in and of itself could affect your test results. I reworked your "final implementation" a little bit to allow the measurement of each iteration without creating 1000000 Stopwatches. Granted, since I am saving the result of each iteration, I am allocating 1000000 longs, but at first glance it seems like that would have less overall affect than allocating that many Stopwatches. I haven't compared my version to your version to see if mine would yield different results.

static void Test2<T>(string testName, Func<T> test, int iterations = 1000000)
{
  long [] results = new long [iterations];

  // print header 
  for (int i = 0; i < 100; i++) // warm up the cache 
  {
    test();
  }

  var timer = System.Diagnostics.Stopwatch.StartNew(); // time whole process 

  long start;

  for (int i = 0; i < results.Length; i++)
  {
    start = Stopwatch.GetTimestamp();
    test();
    results[i] = Stopwatch.GetTimestamp() - start;
  }

  timer.Stop();

  double ticksPerMillisecond = Stopwatch.Frequency / 1000.0;

  Console.WriteLine("Time(ms): {0,3}/{1,10}/{2,8} ({3,10})", results.Min(t => t / ticksPerMillisecond), results.Average(t => t / ticksPerMillisecond), results.Max(t => t / ticksPerMillisecond), results.Sum(t => t / ticksPerMillisecond));
  Console.WriteLine("Ticks:    {0,3}/{1,10}/{2,8} ({3,10})", results.Min(), results.Average(), results.Max(), results.Sum());

  Console.WriteLine();
}

I am using the Stopwatch's static GetTimestamp method twice in each iteration. The delta between will be the amount of time spent in the iteration. Using Stopwatch.Frequency, we can convert the delta values to milliseconds.

Using Timestamp and Frequency to calculate performance is not necessarily as clear as just using a Stopwatch instance directly. But, using a different stopwatch for each iteration is probably not as clear as using a single stopwatch to measure the whole thing.

I don't know that my idea is any better or any worse than yours, but it is slightly different ;-)

I also agree about the warmup loop. Depending on what your test is doing, there could be some fixed startup costs that you don't want to affect the overall results. The startup loop should eliminate that.

There is proabably a point at which keeping each individual timing result is counterproductive due to the cost of storage necessary to hold the whole array of values (or timers). For less memory, but more processing time, you could simply sum the deltas, computing the min and max as you go. That has the potential of throwing off your results, but if you are primarily concerned with the statistics generated based on the invidivual iteration measurements, then you can just do the min and max calculation outside of the time delta check:

static void Test2<T>(string testName, Func<T> test, int iterations = 1000000)
{
  //long [] results = new long [iterations];
  long min = long.MaxValue;
  long max = long.MinValue;

  // print header 
  for (int i = 0; i < 100; i++) // warm up the cache 
  {
    test();
  }

  var timer = System.Diagnostics.Stopwatch.StartNew(); // time whole process 

  long start;
  long delta;
  long sum = 0;

  for (int i = 0; i < iterations; i++)
  {
    start = Stopwatch.GetTimestamp();
    test();
    delta = Stopwatch.GetTimestamp() - start;
    if (delta < min) min = delta;
    if (delta > max) max = delta;
    sum += delta;
  }

  timer.Stop();

  double ticksPerMillisecond = Stopwatch.Frequency / 1000.0;

  Console.WriteLine("Time(ms): {0,3}/{1,10}/{2,8} ({3,10})", min / ticksPerMillisecond, sum / ticksPerMillisecond / iterations, max / ticksPerMillisecond, sum);
  Console.WriteLine("Ticks:    {0,3}/{1,10}/{2,8} ({3,10})", min, sum / iterations, max, sum);

  Console.WriteLine();
}

Looks pretty old school without the Linq operations, but it still gets the job done.

Answer 2

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.

Answer 3

Depending on what the running time of the code you're testing is, it's quite difficult to measure the individual runs. If the runtime of the code your testing is multiple seconds, your approach of timing the specific run will most likely not be a problem. If it's in the vicinity of milliseconds, your results will probably very too much. If you e.g. have a context switch or a read from the swap file at the wrong moment, the runtime of that run will be disproportionate to the average runtime.

Answer 4

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 5

The logic in Approach 2 feels 'righter' to me, but I'm just a CS student.

I came across this link that you might find of interest: http://www.yoda.arachsys.com/csharp/benchmark.html

Answer 6

I would lean toward the last, but I'd consider whether the overhead of starting and stopping a timer could be greater than that of looping itself.

One thing to consider though, is whether the effect of CPU cache misses is actually a fair thing to try to counter?

Taking advantage of CPU caches is something where one approach may beat another, but in real world cases there might be a cache-miss with each call so this advantage becomes inconsequential. In this case the approach that made less good use of the cache could become that which has better real-world performance.

An array-based or singly-linked-list-based queue would be an example; the former almost always having greater performance when cache-lines don't get refilled in between calls, but suffering on resize-operations more than the latter. Hence the latter can win in real-world cases (all the more so as they are easier to write in a lock-free form) even though they will almost always lose in the rapid iterations of timing tests.

For this reason it can also be worth trying some iterations with something to actually force the cache to be flushed. Can't think what the best way to do that would be right now, so I might come back and add to this if I do.