2

I want to test the execution time of different C# implementations of an algorithm. Since the test environment (my computer) has several environmental variables outside of my control (like OS time-slicing) I'd like to get lots of data points and then look at the distribution. Basically, I'd like to run the algorithm a bunch of times, measure the time for each, and then aggregate the results in some way.

The code looks something like this:

    public void TestSpeed()
    {
        var sw = new System.Diagnostics.Stopwatch();
        MyTestAlgorightm(); // "warm up" system

        for (var i = 0; i < 10000; i++)
        {
            sw.Reset();

            sw.Start();
            MyTestAlgorightm();
            sw.Stop();

            AddExecutionDuration(sw.ElapsedTicks);
        }

        AggregateResults();
    }

However, when I look at the results, they seem a bit deceptive... I get times like this:

84, 23, 19, 22, 19, 18, 17, 17, ...

I always see this pattern where the first call (actually second, after the "warm up") takes a "long" time, then subsequent calls are all relatively fast and all take a similar duration to run.

My guess is that what I'm seeing is something similar to Branch Prediction (I know there is no branching in this code, but maybe something similar...), as shown in this excellent question.

If this is the case, then is there a way to "turn it off" so that I can see how long it would normally take to call MyTestAlgorithm() every once in a while from production code, but while still being able to call it several times in a row within this time test so I can gather metrics?

If it's not something similar to branch prediction, then what is causing the first timed call to take longer? Or asked differently, why do subsequent calls run faster?

Since it was stated that without knowing what MyTestAlgorithm() consists of its hard to answer this question (fair point), here is a simplified example of what I'm testing:

    private AlgorithmTest _test;
    private PropertyInfo _pi;
    private int MyTestAlgorithm()
    {
        if (_pi == null)
        {
            _pi = typeof (AlgorithmTest).GetProperty("Prop1");
            _test = new AlgorithmTest() {Prop1 = 42};
        }
        return (int)_pi.GetValue(_test);
    }

    public class AlgorithmTest
    {
        public int Prop1 { get; set; }
    }

And here are my test numbers:

5, 2, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, ...

Note that the body of the if is not being timed, since it is only executed the first time during the "warm up", and then the results are cached.

Community
  • 1
  • 1
Matt Klein
  • 7,856
  • 6
  • 45
  • 46
  • 3
    Rolling your own benchmarking framework isn't ideal... I suggest you look at https://github.com/PerfDotNet/BenchmarkDotNet – Jon Skeet Sep 09 '16 at 14:14
  • This heavily depends on what `MyTestAlgorightm()` does, we can´t guess. Does it create some caches on the first call? Thus this question will soon get closed as unclear. – MakePeaceGreatAgain Sep 09 '16 at 14:14
  • 1
    Are you saying after the first execution it is faster? I believe that is because of the JIT compiler. – Tyler Nichols Sep 09 '16 at 14:16
  • 1
    The JIT compiler is why I call `MyTestAlgorithm()` once as a "warm up" prior to timing it. Is the first call _after that_ which is slow... – Matt Klein Sep 09 '16 at 14:19
  • A good point @HimBromBeere I've added a simplified example of what I'm testing that still shows the behavior. – Matt Klein Sep 09 '16 at 14:32
  • *Compilation* (JIT has to *compile* the routine), *loads* (some libraries - dlls -have to be *loaded*), *initialization* (static constructors should be called etc.) – Dmitry Bychenko Sep 09 '16 at 14:50
  • Are you running this in Debug or Release? – itsme86 Sep 09 '16 at 15:08
  • Does your warmup call execute every code path in `MyTestAlgorithm` including *all* of the methods that it can call? If not you may be hitting JIT on later calls also. – Ian Mercer Sep 09 '16 at 15:12
  • @itsme86 A good question. I'm running in Release, and just for fun I checked Debug and it shows the same results. – Matt Klein Sep 09 '16 at 15:17
  • @IanMercer It does. The first call ("warm up") of `MyTestAlgorithm()` executes the if block, and then executes the `_pi.GetValue` statement. Then, subsequent calls to `MyTestAlgorithm()` only execute `return (int)_pi.GetValue(_test);` – Matt Klein Sep 09 '16 at 15:19
  • Could it be that multiple invocations in a short time cause a rerun of the JIT with a higher optimization level? To avoid this, the warmup should contain multiple runs of the test procedure. – Lutz Lehmann Sep 09 '16 at 16:04

0 Answers0