c# - 在循环外添加一个 Console.WriteLine() 会改变循环的计时 - 为什么？

Question

考虑以下代码:

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

当我使用 Visual Studio 2010 在 Windows 7 x64 上编译并运行此版本的 RELEASE x86 版本时，我得到以下计时(在 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() 快得多。我觉得这很好奇......

所以我有两个问题:

1. 其他人能否重现此内容，并且
2. 如果是这样，谁能解释一下？

[编辑] 我应该补充一点，我可以用秒表验证这些计时，并且我正在从命令行运行测试程序(因此我们可以排除 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

请注意我这样做时 loop2() 计时的差异。不计算!

Answer 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 定义:

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.

由于循环的 IL 在两个版本之间是相同的，并且 MemoryBarrier 使方差消失，我认为我们可以得出结论，方差肯定是第一个模式优化的结果......也许是 JITer.. .也许是 CPU 的问题……不确定。

除了我使用的是 VS2012 和 .NET 4.5 RTM，我的环境是一样的。