multi-threading on multicore process weird results

Question

I am trying to test the thread execution of a multi-threaded program on multi-cores virtual machine. I wrote C# code for it:

class Program
{
    public static int fib(int n)
    {
        if (n < 2)
            return n;

        return fib(n-1)+fib(n-2);
    }

    public static void execution(object n)
    {
        int STEP = 40;
        var start = DateTime.Now;
        int value = fib(STEP);
        var end = DateTime.Now;

        Console.WriteLine(string.Format("threads: {0}, time : {1}, start: {2}, end: {3}", n, end.Subtract(start).TotalSeconds,
            start, end));
    }

    static void Main(string[] args)
    {
        int[] threads = {1, 2, 4, 8, 16};

        for(int j=0; j<5; ++j)
        {
            for (int i = 0; i < threads[j]; ++i)
            {
                var thread = new Thread(Program.execution);
                thread.Start(threads[j]);
            }
            Thread.Sleep(60000);
        }
    }

and this is the result I got

threads: 1, time : 4.2177734, start: 2/8/2014 7:30:13 PM, end: 2/8/2014 7:30:18 PM

threads: 2, time : 4.1015625, start: 2/8/2014 7:31:13 PM, end: 2/8/2014 7:31:17 PM

threads: 2, time : 4.2441407, start: 2/8/2014 7:31:13 PM, end: 2/8/2014 7:31:18 PM

threads: 4, time : 2.0351562, start: 2/8/2014 7:32:13 PM, end: 2/8/2014 7:32:15 PM

threads: 4, time : 2.0527343, start: 2/8/2014 7:32:13 PM, end: 2/8/2014 7:32:15 PM

threads: 4, time : 2.0869141, start: 2/8/2014 7:32:13 PM, end: 2/8/2014 7:32:15 PM

threads: 4, time : 2.0898437, start: 2/8/2014 7:32:13 PM, end: 2/8/2014 7:32:15 PM

threads: 8, time : 3.34375, start: 2/8/2014 7:33:13 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.381836, start: 2/8/2014 7:33:13 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.3066406, start: 2/8/2014 7:33:14 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.2451172, start: 2/8/2014 7:33:14 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.4560547, start: 2/8/2014 7:33:13 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.5029296, start: 2/8/2014 7:33:13 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.2841796, start: 2/8/2014 7:33:14 PM, end: 2/8/2014 7:33:17 PM

threads: 8, time : 3.4160157, start: 2/8/2014 7:33:14 PM, end: 2/8/2014 7:33:17 PM

threads: 16, time : 5.9921875, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.4404297, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 5.3896484, start: 2/8/2014 7:34:15 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 5.9658203, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 5.9873047, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.2226563, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.1552735, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.5576172, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.5273437, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.2529297, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.2958984, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 5.8544922, start: 2/8/2014 7:34:15 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.3886719, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 5.7089844, start: 2/8/2014 7:34:15 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.7207031, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:20 PM

threads: 16, time : 6.0742188, start: 2/8/2014 7:34:14 PM, end: 2/8/2014 7:34:21 PM

notice that I am running the program on a 4-cores Windows 7 virtual machine.

what doesn't make sense to me is that when I have 4 threads running at the same time, each thread takes less time for calculation than when I have 1 or 2 threads running simultaneously.

can someone explain here?

Answer 1

Operating System gives each of your thread a quantum of CPU run time. Each thread has to wait in a queue in order to get executed, this waiting time gets longer as number of threads increases. On the other hand each thread will get a less quantum time to execute. This will be more apparent on a virtual multi-core environment because there is not enough physical core to execute your threads simultaneously.

Also, you should consider context switching between threads has a cost that will be increased as number of threads increases. So avoid running many threads on your application without usage

Answer 2

This is a complex analysis. Like mentioned before, CPU's give time slices to each processor, AND you are subject to the JIT doing optimizations, but more likely at 4 threads the CPU is able to balance both time slices and thread context switching at an optimum rate for your program. I'm sure that these results would vary wildly per machine due to a lot of things out of your control.

Answer 3

It is probably because of the optimizer not really hitting it's stride until you get there. Try adding some calls to warp it up first to the beginning of the program to get more consistent results. I only have a dual core so I get very different results from what you are showing so I can't be more precise.

for (int r = 0; r < 20; r++)
        fib(40);