Stopwatch in a Task seems to be additive across all tasks, want to measure just task interval

Question

I'm running in a loop and kicking off tasks in the following manner:

var iResult = new List<Task>();
foreach(var i in myCollection)
{
    var task = Task.Factory.StartNew(() =>
                    DoSomething(), TaskCreationOptions.LongRunning);
    task.ContinueWith(m => myResponseHandler(m.Result));
    iResult.Add(task);
}

Within my DoSomething() method, I have a timer:

public static myMsg DoSomething()
{
    var timer = System.Diagnostics.Stopwatch.StartNew();
    DoLongRunningTask(); //If it matters this hits a REST endpoint (https)
    timer.Stop();

    return new myMsg(timer.ElaspedMilliseconds);
}

When I iterate through my list of myMsg's the ElaspedMilliseconds seems to be completely additive - the ElaspedMilliseconds on the first one might be 300, but the last one could be 50000 (50 seconds) - which is actually the approximate time the entire thing takes to run (as measured by another timer).

Answer 1

Edit:

Ooops, I was also first confused.

The problem is that it only looks aditive (accumulative) because the ElapsedTime values are always output in increasing order only.

So, if I have, as in my demo below, in the order of launching:

• 1st launched task's duration of 10 sec (10000 msec),
• the 2nd task's duration of 8 sec (8 000 ms),
• the 3d task's duration of 6 sec (6 000 ms),

then the results appear in output out of initial order - ALWAYS in order of increasing duration of tasks:

• the 1st in output: the 3d launched task's duration (of 6 sec duration)
• the 2nd in output: the 2nd launched task's duration (of 8 sec duration)
• the 3d (last) in output: the 1st launched task's duration (of 10 sec duration)

Here is the output from Console app below:

from DoSomething  6043  
from main  6043  
from DoSomething  8057  
from main  8057  
from DoSomething  10058
from main  10058

And it is obvious why - because the faster task always finishes and output before longer (more time consuming) task.

using System;
using System.Collections.Generic;
using System.Threading;
using System.Threading.Tasks;
using System.Diagnostics;

namespace ConsoleApplication1
{
  class Program
  {
    static void Main(string[] args)
    {
      var iResult = new List<Task>();
      for (int i=5; i>2; i--)
      {
        int load = i;
        var task = Task.Factory.StartNew(() =>
                        DoSomething(load), TaskCreationOptions.LongRunning);
        //following commented lines do NOT change the behavior in question
        task.ContinueWith(m => Console.WriteLine("from main  "+m.Result));
        //iResult.Add(task);
      }
      Console.ReadLine();
    }

   //public static myMsg DoSomething()
    public static long DoSomething(int load)
    {
      Stopwatch timer = System.Diagnostics.Stopwatch.StartNew();

      //usage of either prev or following 2 lines produce the same results 
      //Stopwatch timer = new Stopwatch();  //instead of prev .StartNew();
      //timer.Start();// instead of prev .StartNew();

      Console.WriteLine("***Before calling  DoLongRunningTask()   " 
               + timer.ElapsedMilliseconds);
      Console.WriteLine("GetHashCode  "+timer.GetHashCode());

      DoLongRunningTask(load); 
      timer.Stop();

      long elapsed = timer.ElapsedMilliseconds;
      Console.WriteLine("from DoSomething  "+ elapsed);

      return elapsed;//return new myMsg(timer.ElaspedMilliseconds);
    }

    public static void DoLongRunningTask(int load)
    {
      Thread.Sleep(2000*load);
      /*******************  another variant of calculation intensive loading
             load = load;
             double result = 0;
             for (int i = 1; i < load*100000; i++)
                   result += Math.Exp(Math.Log(i) );
       */
    }
  }
}

Answer 2

One thing that is most likely to happen is that DoLongRunningTask() might not be multithreaded properly, which mean one task run after the first is completed and so on. Each task has its own timer and they are all start somewhere around the same time (or as threads are allocated to the tasks), but the long running task offset them all.

You never have an unlimited thread pool and Tasks handles who get a thread and when.

About LongRunning:

"It's not a specific length per se. If you're generating a lot of tasks, LongRunning is not appropriate for them. If you're generating one or two tasks that will persist for quite some time relative to the lifetime of your application, then LongRunning is something to consider. In general, don't use it unless you find that you really need it. Under the covers, it's going to result in a higher number of threads being used, because its purpose is to allow the ThreadPool to continue to process work items even though one task is running for an extended period of time; if that task were running in a thread from the pool, that thread wouldn't be able to service other tasks. You'd typically only use LongRunning if you found through performance testing that not using it was causing long delays in the processing of other work." - Stephen Toub