Performance profiling in .NET

Question

I wrote a class which uses Stopwatch to profile methods and for/foreach loops. With for and foreach loops it tests a standard loop against a Parallel.For or Parallel.ForEach implementation.

You would write performance tests like so:

Method:

PerformanceResult result = Profiler.Execute(() => { FooBar(); });

For loop:

SerialParallelPerformanceResult result = Profiler.For(0, 100, x => { FooBar(x); });

ForEach loop:

SerialParallelPerformanceResult result = Profiler.ForEach(list, item => { FooBar(item); });

Whenever I run the tests (one of .Execute, .For or .ForEach) I put them in a loop so I can see how the performance changes over time.

Example of performance might be:

Method execution 1 = 200ms
Method execution 2 = 12ms
Method execution 3 = 0ms

For execution 1 = 300ms (Serial), 100ms (Parallel)
For execution 2 = 20ms (Serial), 75ms (Parallel)
For execution 3 = 2ms (Serial), 50ms (Parallel)

ForEach execution 1 = 350ms (Serial), 300ms (Parallel)
ForEach execution 2 = 24ms (Serial), 89ms (Parallel)
ForEach execution 3 = 1ms (Serial), 21ms (Parallel)

My questions are:

1. Why does performance change over time, what is .NET doing in the background to facilitate this?

2. How/why is a serial operation faster than a parallel one? I have made sure that I make the operations complex to see the difference properly...in most cases serial operations seem faster!?

NOTE: For parallel processing I am testing on an 8 core machine.

Answer 1

After some more exploration into performance profiling, I have discovered that using a Stopwatch is not an accurate way to measure the performance of a particular task

(Thanks hatchet and Loren for your comments on this!)

Reasons a stopwatch are not accurate:

1. Measurements are calculated in elapsed time in milliseconds, not CPU time.
2. Measurements can be influenced by background "noise" and thread intensive processes.
3. Measurements do not take into account JIT compilation and overhead.

That being said, using a stopwatch is OK for casual exploration of performance. With that in mind, I have improved my profiling algorithm somewhat.

Where before it simply executed the expression that was passed to it, it now has the facility to iterate over the expression several times, building an average execution time. The first run can be omitted since this is where JIT kicks in, and some major overhead may occur. Understandably, this will never be as sophisticated as using a professional profiling tool like Redgate's ANTS profiler, but it's OK for simpler tasks!

Answer 2

As per my comment above: I did some simple tests on my own and found no difference over time. Can you share your code? I'll put mine in an answer as it doesn't fit here.

This is my sample code. (I also tried with both static and instance methods with no difference)

class Program
{
    static void Main(string[] args)
    {
        int to = 50000000;
        OtherStuff os = new OtherStuff();

        Console.WriteLine(Profile(() => os.CountTo(to)));
        Console.WriteLine(Profile(() => os.CountTo(to)));
        Console.WriteLine(Profile(() => os.CountTo(to)));
    }

    static long Profile(Action method)
    {
        Stopwatch st = Stopwatch.StartNew();
        method();
        st.Stop();
        return st.ElapsedMilliseconds;
    }
}

class OtherStuff
{
    public void CountTo(int to)
    {
        for (int i = 0; i < to; i++)
        {
            // some work...
            i++;
            i--;
        }
    }
}

A sample output would be:

331
331
334

Consider executing this method instead:

class OtherStuff
    {
        public string CountTo(Guid id)
        {
            using(SHA256 sha = SHA256.Create())
            {
                int x = default(int);
                for (int index = 0; index < 16; index++)
                {
                    x = id.ToByteArray()[index] >> 32 << 16;
                }
                RNGCryptoServiceProvider rng = new RNGCryptoServiceProvider();
                byte[] y = new byte[1024];
                rng.GetBytes(y);
                y = y.Concat(BitConverter.GetBytes(x)).ToArray();
                return BitConverter.ToString(sha.ComputeHash(BitConverter.GetBytes(x).Where(o => o >> 2 < 0).ToArray()));
            }
        }
    }

Sample output:

11 
0 
0