none
How to measure code using StopWatch? My results are not useful

    Question

  • Hi,

    Please consider this code:

    var somestring = "blab;la;blab;blabla;";
    var iterations = 100000;
    Stopwatch watch = new Stopwatch();
    while (true)
    {
        watch.Reset();
        watch.Start();
        for (int i = 0; i < iterations; i++)
        {
            var split = somestring.Split(';');
        }
        watch.Stop();
        Console.WriteLine(watch.Elapsed);
    
        watch.Reset();
        watch.Start();
        for (int i = 0; i < iterations; i++)
        {
            var split = somestring.Split(';');
        }
        watch.Stop();
        Console.WriteLine(watch.Elapsed);
    
        Console.ReadKey();
    }

    Why is the first run always slower than the other? And how should I construct this test in order to effectivly compare their speed?

    --
    Werner



    Wednesday, September 12, 2012 2:05 PM

Answers

  • "However I finally found out why. It is the "Console.ReadKey();" that is fired after each loop. Somehow this messes up the runtime cache as if the loop ran for the first time - each time."

    Your CPU frequency probably varies depending on workload. On idle it switches to a lower frequency, perhaps half of the normal one and when it has work to do it speeds up again. But it's possible that it doesn't speed up fast enough and so the first result after a idle period is always slower.

    • Marked as answer by Werner Clausen Friday, September 14, 2012 12:33 PM
    Friday, September 14, 2012 6:36 AM

All replies

  • "Why is the first run always slower than the other?"

    How much slower? 1ms, 10ms, 100ms? On my computer I don't see any significant difference.

    Just yesterday I replied to a very similar question: http://social.msdn.microsoft.com/Forums/en-US/csharplanguage/thread/275aa422-39ac-4ae8-ae2c-3978faae940d. It's a bit different because in your case there's no lazy initialization that needs to be done for String.Split. Still, the first run of a particular piece of code may always give false results due to data/instruction caching.

    To what I said in the other thread I'll add that trying to measure the speed of code that may trigger a GC is unlikely to give precise results. If a GC occurs in a run but not in the other you'll get different results. And which one is correct? Both!

    Wednesday, September 12, 2012 2:22 PM
  • "Why is the first run always slower than the other?"

    Initialization and caching.

    For example; timing the time to read a file will typical result in the first reading being orders of magnitude longer than subsequent readings.

    Wednesday, September 12, 2012 2:23 PM
  • Significantly slower. Enough to conclude (wrongly) that the one is faster than the other. Wehn code must run in recursive methods in a scenario where it must perform to the best - any difference is important.

    However I finally found out why. It is the "Console.ReadKey();" that is fired after each loop. Somehow this messes up the runtime cache as if the loop ran for the first time - each time. If I put it ouside the loop I get correct values (same values in the above example).

    --
    Werner

    Friday, September 14, 2012 6:21 AM
  • "However I finally found out why. It is the "Console.ReadKey();" that is fired after each loop. Somehow this messes up the runtime cache as if the loop ran for the first time - each time."

    Your CPU frequency probably varies depending on workload. On idle it switches to a lower frequency, perhaps half of the normal one and when it has work to do it speeds up again. But it's possible that it doesn't speed up fast enough and so the first result after a idle period is always slower.

    • Marked as answer by Werner Clausen Friday, September 14, 2012 12:33 PM
    Friday, September 14, 2012 6:36 AM
  • "However I finally found out why. It is the "Console.ReadKey();" that is fired after each loop. Somehow this messes up the runtime cache as if the loop ran for the first time - each time."

    Your CPU frequency probably varies depending on workload. On idle it switches to a lower frequency, perhaps half of the normal one and when it has work to do it speeds up again. But it's possible that it doesn't speed up fast enough and so the first result after a idle period is always slower.

    Yes, that would explain this behaviour better than my (and I see now that this is also what John suggests) assumption on runtime optimizations. Also the fact that the very first run (right after entering void Main()) is a great deal slower than the first run after looping. Suggesting that the slowness isn't due to the same at all.

    --
    Werner


    Friday, September 14, 2012 12:30 PM
  • The very first execution of any method is always slower than the following because that's when the method is compiled from IL into native code.
    Monday, September 17, 2012 9:23 AM
  • That's certainly a good observation except it doesn't apply in this particular case, all involved methods are from mscorlib/System and those are supposed to be ngened.
    Monday, September 17, 2012 9:43 AM
  • mscorlib is supposed to be ngened? Sorry for not taking your word for it; do you have any link to support this? How come I can examine it with ildasm?

    • Edited by Louis.fr Monday, September 17, 2012 3:34 PM
    Monday, September 17, 2012 3:32 PM
  • "mscorlib is supposed to be ngened? Sorry for not taking your word for it; do you have any link to support this?"

    None that comes to mind right now but you can check the native assembly dir, see what you have in C:\Windows\Assembly\NativeImages_v4.0.30319_32

    "How come I can examine it with ildasm?"

    What that has to do with ngen?!!

    Monday, September 17, 2012 4:15 PM
  • "mscorlib is supposed to be ngened? Sorry for not taking your word for it; do you have any link to support this?"

    Okay, it makes sense too. But that means you should reinstall the Framework when you make changes to your architecture.

    None that comes to mind right now but you can check the native assembly dir, see what you have in C:\Windows\Assembly\NativeImages_v4.0.30319_32

    "How come I can examine it with ildasm?"

    What that has to do with ngen?!!

    Ildasm can only examine non-ngen'd assemblies. I thought you were saying that the assemblies in the Microsoft.Net\Framework\... were ngen'd assemblies.

    Tuesday, September 18, 2012 12:02 PM
  • "But that means you should reinstall the Framework when you make changes to your architecture."

    Sort of. First you need to reinstall the OS so...

    Tuesday, September 18, 2012 1:07 PM
  • Not all changes of architecture need reinstalling the OS.

    I don't know if those changes could alter how the code is compiled to native.

    Tuesday, September 18, 2012 3:35 PM
  • At least in the context of .NET 'architecture' means something like x86,x64,IA64,ARM. You cannot change between those architecture without reinstalling everything. x86->x64 is an exception but it doesn't count because you don't really use x64 if you don't reinstall.

    What you're probably thinking is downgrading a x86 CPU to one that doesn't support particular instruction sets like SSE2. But NGEN supposedly doesn't use such instructions, only the JIT compiler does.

    Anyway the NGEN service takes care of recompiling assemblies when needed, like when you install a .NET update.

    Wednesday, September 19, 2012 5:51 AM