Adding a single Console.WriteLine() outside a loop changes a loop's timings - why?

Question

Consider the following code:

using System;
using System.Diagnostics;

namespace Demo
{
    class Program
    {
        static void Main(string[] args)
        {
            Stopwatch sw = new Stopwatch();

            for (int trial = 0; trial < 4; ++trial)
            {
                sw.Restart();
                loop1();
                Console.WriteLine("loop1() took " + sw.Elapsed);

                sw.Restart();
                loop2();
                Console.WriteLine("loop2() took " + sw.Elapsed);

                sw.Restart();
                loop3();
                Console.WriteLine("loop3() took " + sw.Elapsed);

                // Console.WriteLine(); // <-- Uncomment this and the timings change a LOT!
            }
        }

        static void loop1()
        {
            bool done = false;

            for (int i = 0; i < 100000 && !done; ++i)
            {
                for (int j = 0; j < 100000 && !done; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            done = true;
                            break;
                        }
                    }
                }
            }
        }

        static void loop2()
        {
            for (int i = 0; i < 100000; ++i)
            {
                for (int j = 0; j < 100000; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            goto exit;
                        }
                    }
                }
            }

        exit: return;
        }

        static void loop3()
        {
            for (int i = 0; i < 100000; ++i)
            {
                for (int j = 0; j < 100000; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            k = 2;
                            j = 100000;
                            i = 100000;
                        }
                    }
                }
            }
        }
    }
}

When I compile and run a RELEASE x86 build of this on Windows 7 x64 using Visual Studio 2010, I get the following timings (running on Intel Core i7)

loop1() took 00:00:01.7935267
loop2() took 00:00:01.4747297
loop3() took 00:00:05.6677592
loop1() took 00:00:01.7654008
loop2() took 00:00:01.4818888
loop3() took 00:00:05.7656440
loop1() took 00:00:01.7990239
loop2() took 00:00:01.5019258
loop3() took 00:00:05.7979425
loop1() took 00:00:01.8356245
loop2() took 00:00:01.5688070
loop3() took 00:00:05.7238753

That in itself is odd - why would loop3() be so much slower than the other loops? Anyway, I then uncomment the indicated line (the Console.WriteLine()), and my timings become:

loop1() took 00:00:01.8229538
loop2() took 00:00:07.8174210
loop3() took 00:00:01.4879274

loop1() took 00:00:01.7691919
loop2() took 00:00:07.4781999
loop3() took 00:00:01.4810248

loop1() took 00:00:01.7749845
loop2() took 00:00:07.5304738
loop3() took 00:00:01.4634904

loop1() took 00:00:01.7521282
loop2() took 00:00:07.6325186
loop3() took 00:00:01.4663219

Now loop2() is far slower, and loop3() far quicker. I find this most curious...

So I have two questions:

1. Can anyone else reproduce this, and
2. If so, can anyone explain it?

[EDIT] I should add that I can verify these timings with a stopwatch, and I am running the test program from the command-line (so we can rule out Visual Studio interfering with it).

ADDENDUM:

I modified the program as follows to exclude the possibility that the JITTER is optimizing out the loops:

using System;
using System.Diagnostics;
using System.Text;

namespace Demo
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine(test());
        }

        static string test()
        {
            Stopwatch sw = new Stopwatch();
            int total = 0;
            StringBuilder builder = new StringBuilder();

            for (int trial = 0; trial < 2; ++trial)
            {
                sw.Restart();
                total += loop1();
                builder.AppendLine("loop1() took " + sw.Elapsed);

                sw.Restart();
                total += loop2();
                builder.AppendLine("loop2() took " + sw.Elapsed);

                sw.Restart();
                total += loop3();
                builder.AppendLine("loop3() took " + sw.Elapsed);
                //builder.AppendLine(); // Uncommenting this line makes a big difference!
            }

            builder.AppendLine(total.ToString());

            return builder.ToString();
        }

        static int loop1()
        {
            bool done = false;
            int total = 0;

            for (int i = 0; i < 100000 && !done; ++i)
            {
                for (int j = 0; j < 100000 && !done; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            done = true;
                            break;
                        }

                        ++total;
                    }
                }
            }

            return total;
        }

        static int loop2()
        {
            int total = 0;

            for (int i = 0; i < 100000; ++i)
            {
                for (int j = 0; j < 100000; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            goto exit;
                        }

                        ++total;
                    }
                }
            }

        exit: return total;
        }

        static int loop3()
        {
            int total = 0;

            for (int i = 0; i < 100000; ++i)
            {
                for (int j = 0; j < 100000; ++j)
                {
                    for (int k = 0; k < 2; ++k)
                    {
                        if (i == 9900)
                        {
                            k = 2;
                            j = 100000;
                            i = 100000;
                        }
                        else
                        {
                            ++total;
                        }
                    }
                }
            }

            return total;
        }
    }
}

Now my results are as follows:

builder.AppendLine() commented out:

loop1() took 00:00:06.6509471
loop2() took 00:00:06.7322771
loop3() took 00:00:01.5361389
loop1() took 00:00:06.5746730
loop2() took 00:00:06.7051531
loop3() took 00:00:01.5027345
-1004901888

builder.AppendLine() not commented out:

loop1() took 00:00:06.9444200
loop2() took 00:00:02.8960563
loop3() took 00:00:01.4759535

loop1() took 00:00:06.9036553
loop2() took 00:00:03.1514154
loop3() took 00:00:01.4764172

-1004901888

Note the difference in the loop2() timing when I do that. Does not compute!

Answer 1

I can reproduce that exactly. In addition though, I can make the variance go away like this:

    private static void Main(string[] args)
    {
        Stopwatch sw = new Stopwatch();

        for (int trial = 0; trial < 4; ++trial)
        {
            sw.Restart();
            Interlocked.MemoryBarrier();
            loop1();
            Interlocked.MemoryBarrier();
            Console.WriteLine("loop1() took " + sw.Elapsed);

            sw.Restart();
            Interlocked.MemoryBarrier();
            loop2();
            Interlocked.MemoryBarrier();
            Console.WriteLine("loop2() took " + sw.Elapsed);

            sw.Restart();
            Interlocked.MemoryBarrier();
            loop3();
            Interlocked.MemoryBarrier();
            Console.WriteLine("loop3() took " + sw.Elapsed);

            // Console.WriteLine(); // <-- Uncomment this and the timings don't change now.
        }
    }

When I run with the MemoryBarriers, I get the second pattern no matter which way I run the test:

loop1() took ~1 sec
loop2() took ~7 secs
loop3() took ~1 sec

MemoryBarrier definition:

Synchronizes memory access as follows: The processor executing the current thread cannot reorder instructions in such a way that memory accesses prior to the call to MemoryBarrier execute after memory accesses that follow the call to MemoryBarrier.

Since the IL for the loops is identical between the 2 versions, and MemoryBarrier makes the variance disappear, I think we can conclude the variance is definitely the result of an optimization on the first pattern... maybe by the JITer... maybe by the CPU... not sure there.

My environment is the same, except I am using VS2012 & .NET 4.5 RTM.