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:
- Can anyone else reproduce this, and
- 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!