Stopwatch giving different results depending on where code resides

Question

I'm getting some confusing Stopwatch results in my C# project. Consider the following code:

static void Main(string[] args)
{
    byte[] myEventArray = GetEventByteArrayFromDatabase();
    byte[] myEventItemsArray = GetEventItemByteArrayFromDatabase();
    uint numEvents = 1000;
    uint numEventItems = 1000;

    Stopwatch sw1 = Stopwatch.StartNew();
    TestFunction(ref myEventArray, numEvents, ref myEventItemsArray, numEventItems);
    sw1.Stop();

    float timeTakenInSeconds = (float)sw2.ElapsedTicks / Stopwatch.Frequency;
    Console.WriteLine("Total time: " + timeTakenInSeconds + " seconds. ");
}

static void TestFunction(ref byte[] EventArray, uint numEvents, ref byte[] EventItemArray, uint numEventItems)
{
        Calculator calc = new Calculator();
        calc.Test(EventArray, numEvents, EventItemArray, numEventItems);
}

I run this, and get a time of around 0.2 seconds. Now consider this:

static void Main(string[] args)
{
    byte[] myEventArray = GetEventByteArrayFromDatabase();
    byte[] myEventItemsArray = GetEventItemByteArrayFromDatabase();
    uint numEvents = 1000;
    uint numEventItems = 1000;

    Stopwatch sw1 = Stopwatch.StartNew();
    Calculator calc = new Calculator();
    calc.Test(myEventArray , numEvents, myEventItemsArray , numEventItems);
    sw1.Stop();

    float timeTakenInSeconds = (float)sw1.ElapsedTicks / Stopwatch.Frequency;
    Console.WriteLine("Total time: " + timeTakenInSeconds + " seconds. ");
}

I run that, and get a similar result, as one would expect. Finally, check this out:

static void Main(string[] args)
{
    byte[] myEventArray = GetEventByteArrayFromDatabase();
    byte[] myEventItemsArray = GetEventItemByteArrayFromDatabase();
    uint numEvents = 1000;
    uint numEventItems = 1000;

    TestFunction(ref myEventArray, numEvents, ref myEventItemsArray, numEventItems);
}

static void TestFunction(ref byte[] EventArray, uint numEvents, ref byte[] EventItemArray, uint numEventItems)
{
    Stopwatch sw1 = Stopwatch.StartNew();
    Calculator calc = new Calculator();
    calc.Test(EventArray, numEvents, EventItemArray, numEventItems);
    sw1.Stop();

    float timeTakenInSeconds = (float)sw1.ElapsedTicks / Stopwatch.Frequency;
    Console.WriteLine("Total time: " + timeTakenInSeconds + " seconds. ");
}

When I run that, the timing result is consistently ten times faster for some reason. Any ideas why that could be the case?

A bit more info: The Calculator class is defined in C++/CLI. I'm using it as a wrapper for native C++ code that eventually works with the byte arrays. I'm also compiling with the "unsafe" compiler flag. Not sure if that could be having any effect. All code is compiled in release mode.

Answer 1

I've discovered the reason for this. It happens because in the first case, the creation of my Calculator object was included in the timing result, and in the 3rd case it was not.

If I understand this correctly, Stack variables are not actually created on the line you type "new()", the compiler moves the memory allocation to the method "prolog".

See this page: https://msdn.microsoft.com/en-us/library/tawsa7cb.aspx

"The prolog saves argument registers in their home addresses if required, pushes nonvolatile registers on the stack, allocates the fixed part of the stack for locals and temporaries, and optionally establishes a frame pointer."

So my "case 1" included the "new" (because it happened in the prolog of TestFunction) and "case 3" excluded it, because the "new" had already happened.