How some simple lines of code can affect execution time of next codes significantly?

Question

EDIT: The dis assembly of both cases are also attached based on given comment through Tools > Options > Debugging > 'Suppress JIT optimization on module load' > uncheck (clear this option, to do JIT Optimization even in debug mode). It can be seen that the generated machine code is not good when pseudo codes are available! in fast version, the code use CPU Registers directly but in other version, it load p1.x and p1.y from memory in every iteration! i don't know how could we control such behavior!

When i was trying to measure execution time of a block of code for performance testing, i found some irregularities that confused me: if i add some block of (pseudo) code before the actual measuring loop, the total elapsed time is increased by a large factor (from 120 msec to 220 msec i.e. about 1.8 times slower! in my 2 GHz PC). Note that in real case, these pseudo codes are some different codes required for initialization or similar purposes.

NOTE: I build the app in Release Mode and run it by Start Without Debug (Ctrl+F5) to ensure all optimizations are applied to get best results.

I show a simplified scenario here as sample:

void test()
{
    Point p1 = new Point(1, 2);
    Point p = p1;
    //*** !!! Comment & UnComment the following 2 lines to see difference: ***
    p.Offset(p1); p.Offset(p1); p.Offset(p1); p.Offset(p1);
    p.Offset(p1); p.Offset(p1); p.Offset(p1); p.Offset(p1);

    Stopwatch timer = new Stopwatch();
    double dt = -1;

    for (int repeat = 1; repeat <= 5; repeat++)
    {
        p = p1; //here we reset the initial p

        timer.Restart();
        for (int i = 0; i < 50000000; i++)
        {
            p.Offset(p1);
        }
        timer.Stop();
        dt = timer.ElapsedMilliseconds;

        textBox1.Text += repeat + "] " + dt + ", p: " + p + "\r\n";
        Application.DoEvents(); if (this.IsDisposed) break;
    }
}

private void button1_Click(object sender, EventArgs e)
{
    test();
}

This issue prevents me from comparison of results i need for optimization. By the way, this may relates to struct types(?).

Do you know what is the reason and how to solve it?

EDIT (4 Apr.): i checked and found that this behavior is only happen for struct types not class types. and as we know, structs are usually value types in Stack rather than heap. this may have a role here but i don't know..

Another Note: i also found that if i uncheck the 'Optimize Code' option in project Properties > Build tab, then the code actually runs faster!

The screenshot of two cases are shown below:

The dis-assembly:

Answer 1

Interesting question.

In these cases, assembler always tells you the truth (not the CIL, that will be exactly the same!). It might be that your thing triggered a boundary condition that changes the assembler of the inner-most loop.

I changed the code into a console application, made the necessary adjustments (suppress optimization flag etc), release mode, put a breakpoint, F5 and hit ctrl-alt-d.

Note: I noticed I also had to increase the test case by a factor 10 to get these timings. The timings are exactly the same, as I expected.

Still, there could be an issue with f.ex. register allocation, so let's check that. Assembler never lies.

Case 1 assembler.

                for (int i = 0; i < 500000000; i++)
00007FFE23C74526  xor         ecx,ecx  
                {
                    p.Offset(p1);
00007FFE23C74528  inc         r14d  
00007FFE23C7452B  add         r15d,2  
                for (int i = 0; i < 500000000; i++)
00007FFE23C7452F  inc         ecx  
00007FFE23C74531  cmp         ecx,1DCD6500h  
00007FFE23C74537  jl          00007FFE23C74528  
                }

Case 2 assembler

                for (int i = 0; i < 500000000; i++)
00007FFE23C84526  xor         ecx,ecx  
                {
                    p.Offset(p1);
00007FFE23C84528  inc         r14d  
00007FFE23C8452B  add         r15d,2  
                for (int i = 0; i < 500000000; i++)
00007FFE23C8452F  inc         ecx  
00007FFE23C84531  cmp         ecx,1DCD6500h  
00007FFE23C84537  jl          00007FFE23C84528  
                }

Conclusion

The assembler output is exactly the same, and so is the data -- In other words: the performance of the inner loop is also exactly the same.

Still, do check the assembler output for yourself as I've explained. If you have another version of the .NET JIT, it should explain the behavior.

---

Apparently there's a bit of confusion on how you should test emitted assembler code. Here's the correct way to do it:

• Tools -> Options -> Debugging -> Suppress JIT optimization on module load -> uncheck (If you clear this option, you can debug optimized JIT code, but your ability to debug may be limited)
• Disable "Just my code" as well in the same settings pane.
• Set the build type to "release" mode. Also check configuration manager.
• Right click project -> "Properties" -> Build tab. Check "Optimize code".
• Optional, same tab: ensure that "Prefer 32-bit code" is unchecked. (NOTE: The 32-bit JIT and the 64-bit JIT are two different things.)

Set breakpoint, F5, ctrl-alt-d, pray your breakpoint is hit, otherwise set it somewhere else and try again.

---

I'm a bit surprised by some of the comments, so let me go over them:

• @Douglas notes that longer methods result in less efficient code. Yes, I've actually made a bug report about this to the Microsoft CoreCLR team. This is true, but with the remark that the JIT optimizer will only be disabled when compiling very large methods. Very large in this context is 60.000 lines of IL code. The exact limits can be found here: https://github.com/dotnet/coreclr/blob/01a5e9b4580cf6ea21de672f627402c30658ef22/src/jit/compiler.h#L7131 . In this case, it's totally irrelevant.
• @Noldorin notes that the OP should look at the IL code. I would like to point out that the emitted IL code is exactly the same in both scenario's.