c# - 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) );
       */
    }
  }
}