Добавление одиночного Console.WriteLine() вне цикла изменяет тайм-ауты цикла - почему?

Рассмотрим следующий код:

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

Когда я компилирую и запускаю сборку RELEASE x86 этого в Windows 7 x64 с помощью Visual Studio 2010, я получаю следующие тайминги (работает на 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

Это само по себе нечетно - почему loop3() будет намного медленнее, чем другие циклы? В любом случае, я раскомментирую указанную строку (Console.WriteLine()), и мои тайминги становятся:

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

Теперь loop2() намного медленнее, а loop3() намного быстрее. Я нахожу это самым любопытным...

У меня есть два вопроса:

  • Может ли кто-нибудь еще воспроизвести это, и
  • Если да, может ли кто-нибудь объяснить это?

[EDIT] Я должен добавить, что я могу проверить эти тайминги с секундомером, и я запускаю тестовую программу из командной строки (поэтому мы можем исключить вмешательство Visual Studio в нее).

ДОПОЛНЕНИЕ:

Я изменил программу следующим образом, чтобы исключить возможность того, что JITTER оптимизирует циклы:

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

Теперь мои результаты таковы:

builder.AppendLine() закомментировал:

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() не закомментирован:

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

Обратите внимание на разницу в времени цикла2(), когда я это делаю. Не вычисляется!

Ответы

Ответ 1

Я могу воспроизвести это точно. Кроме того, я могу сделать отклонение таким образом:

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

Когда я запускаю с MemoryBarriers, я получаю второй шаблон независимо от того, каким способом я запускаю тест:

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

Определение MemoryBarrier:

Синхронизирует доступ к памяти следующим образом: процессор, выполняющий текущий поток, не может переупорядочить инструкции таким образом, чтобы доступ к памяти до вызова MemoryBarrier выполнялся после обращения к памяти, следующего за вызовом MemoryBarrier.

Поскольку IL для циклов идентичен между двумя версиями, а MemoryBarrier заставляет дисперсию исчезать, я думаю, что мы можем заключить, что дисперсия определенно является результатом оптимизации на первом шаблоне... может быть, JITer. возможно, CPU... не уверен там.

Моя среда такая же, за исключением того, что я использую VS2012 и .NET 4.5 RTM.