Das Hinzufügen eines einzelnen Console.WriteLine() außerhalb einer Schleife ändert die Zeitabläufe einer Schleife - warum?

Question

Betrachten Sie den folgenden 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() dauerte " + sw.Elapsed);

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

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

                // Console.WriteLine(); // <-- Entkommentieren Sie dies und die Zeitangaben ändern sich SEHR!
            }
        }

        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;
                        }
                    }
                }
            }
        }
    }
}

Wenn ich einen RELEASE x86 Build davon auf Windows 7 x64 unter Verwendung von Visual Studio 2010 kompiliere und ausführe, erhalte ich die folgenden Zeitangaben (Ausführung auf einem Intel Core i7)

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

Das an sich ist seltsam - warum wäre loop3() so viel langsamer als die anderen Schleifen? Wie dem auch sei, dann kommentiere ich die angegebene Zeile aus (die Console.WriteLine()), und meine Zeitangaben werden zu:

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

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

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

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

Jetzt ist loop2() viel langsamer und loop3() viel schneller. Ich finde das sehr neugierig...

Also habe ich zwei Fragen:

1. Kann das jemand reproduzieren und
2. Wenn ja, kann es jemand erklären?

[EDIT] Ich sollte hinzufügen, dass ich diese Zeitangaben mit einem Stoppuhr verifizieren kann und das Testprogramm von der Kommandozeile ausführe (damit wir Visual Studio ausschließen können, das eingreift).

ZUSATZ:

Ich habe das Programm wie folgt geändert, um die Möglichkeit auszuschließen, dass der JITTER die Schleifen optimiert:

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() dauerte " + sw.Elapsed);

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

                sw.Restart();
                total += loop3();
                builder.AppendLine("loop3() dauerte " + sw.Elapsed);
                //builder.AppendLine(); // Wenn diese Zeile auskommentiert ist, macht das einen großen Unterschied!
            }

            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;
        }
    }
}

Jetzt lauten meine Ergebnisse wie folgt:

builder.AppendLine() auskommentiert:

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

builder.AppendLine() nicht auskommentiert:

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

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

-1004901888

Beachten Sie den Unterschied in der Zeitangabe für loop2(), wenn ich das mache. Nicht berechenbar!

Answer 1

Ich kann das genau reproduzieren. Darüber hinaus kann ich die Varianz wie folgt beseitigen:

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() dauerte " + sw.Elapsed);

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

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

        // Console.WriteLine(); // <-- Kommentieren Sie dies aus und die Zeitabläufe ändern sich nicht.
    }
}

Wenn ich mit den MemoryBarriers ausführe, erhalte ich unabhängig davon, wie ich den Test durchführe, das zweite Muster:

loop1() dauerte ~1 Sek.
loop2() dauerte ~7 Sek.
loop3() dauerte ~1 Sek.

MemoryBarrier Definition:

Synchronisiert den Speicherzugriff wie folgt: Der Prozessor, der den aktuellen Thread ausführt, kann Anweisungen nicht so umordnen, dass Speicherzugriffe vor dem Aufruf von MemoryBarrier nach Speicherzugriffen ausgeführt werden, die nach dem Aufruf von MemoryBarrier folgen.

Da das Intermediate Language (IL) für die Schleifen zwischen den beiden Versionen identisch ist und MemoryBarrier die Varianz verschwinden lässt, können wir schlussfolgern, dass die Varianz definitiv das Ergebnis einer Optimierung im ersten Muster ist ... vielleicht durch den JITer ... vielleicht durch die CPU... nicht ganz sicher.

Meine Umgebung ist die gleiche, außer dass ich VS2012 & .NET 4.5 RTM verwende.