Stopwatch multi-task ElapsedMilliseconds calculation

Question

I have a very basic function to track time taken by each function call. The stopwatch in UnitWorkAsync returns expected values but the timer in ParentWorkAsync keeps adding the time across tasks. What am I doing wrong with the stop watch tracking?

In the output I would assume ParentWorkAsync timer to be around the same as UnitWorkAsync timer but that is not the case as seen below

Code

class StopwatchTestHelper
{
    private static int workItemsCount = 0;

    public void Run()
    {
        List<Task> tasks = new List<Task>();

        Stopwatch stopwatch = Stopwatch.StartNew();

        for (int i = 0; i < 1000; i++)
        {
            tasks.Add(ParentWorkAsync());
        }

        Task.WaitAll(tasks.ToArray());

        Console.WriteLine("Run timer: " + stopwatch.ElapsedMilliseconds);
    }

    private async Task ParentWorkAsync()
    {
        Stopwatch stopwatch = Stopwatch.StartNew();

        await UnitWorkAsync().ConfigureAwait(false);

        Console.WriteLine("ParentWorkAsync timer: " + stopwatch.ElapsedMilliseconds);
    }

    private async Task UnitWorkAsync()
    {
        await Task.Yield();

        Stopwatch stopwatch = Stopwatch.StartNew();

        // Blocking call.
        //
        Thread.Sleep(2000);

        // Async call.
        //
        await Task.Delay(100);

        Console.WriteLine("UnitWorkAsync timer: " + stopwatch.ElapsedMilliseconds);

        Interlocked.Increment(ref workItemsCount);
        Console.WriteLine("Work items completed: " + workItemsCount);
    }
}

Output:

UnitWorkAsync timer: 2963
Work items completed: 1
ParentWorkAsync timer: 2973
UnitWorkAsync timer: 2998
Work items completed: 2
ParentWorkAsync timer: 3966
UnitWorkAsync timer: 2954
Work items completed: 3
ParentWorkAsync timer: 4956
UnitWorkAsync timer: 2993
Work items completed: 4
ParentWorkAsync timer: 5955
UnitWorkAsync timer: 2954
Work items completed: 5
ParentWorkAsync timer: 6952
UnitWorkAsync timer: 2993
Work items completed: 6
ParentWorkAsync timer: 7951

It is accurate, the code fire-hoses the threadpool. You can't have a thousand threads executing code all at the same time unless you spend a lot of money. Arbitrarily replace Thread.Sleep() with await Task.Delay to see a difference. — Hans Passant, Oct 26 '18 at 01:46

TheGeneral · Accepted Answer · 2018-10-26T02:36:38.940

Hans Passant is absolutely correct in his comments

Firstly

When you start a task, there is no guarantee it will start its own thread

Secondly

When you call Thread.Sleep it will sleep that thread with a full stop, no pass-go.

Thirdly

By using await properly, it allows the thread to go back into the pool until its needed, which in-turn gives the Task Scheduler a chance to reuse that thread and allowing the resource allocation to be more efficient

The solve

If you replace Thread.Sleep with await Task.Delay(2000) you will find this will work as expected. T

The issue

The issue here is the scheduler isn't giving you all your threads at once, it will only give what it thinks you should have based on a set of rules, some heuristics (and secret sauce, just kidding). In this case with Thread.Sleep, the scheduler is taking a dim view of what you are doing and isn't letting you have all threads you may like.

Now lets prove it

Modified code

private static async Task ParentWorkAsync()
{
   Stopwatch sw = Stopwatch.StartNew();

   var num = _rand.Next(100000);

   Console.WriteLine($"P Start : {GetInfo(num,sw)}");

   await UnitWorkAsync(num,sw).ConfigureAwait(false);

   Console.WriteLine($"P Stop : {GetInfo(num,sw)}");
}

private  static async Task UnitWorkAsync(int num, Stopwatch sw)
{
   await Task.Yield();

   Console.WriteLine($"W Start : {GetInfo(num,sw)}");

   Thread.Sleep(2000);

   Interlocked.Decrement(ref workItemsCount);

   Console.WriteLine($"W Stop : {GetInfo(num,sw)}");    
}

This is with 8 tasks,

W and P stand for parent and worker
Id = random number to keep track of events
Elapsed = the same stopwatch using elapsed time form start to finish
Threads = how many threads are being used at any one point
ThreadId = is the thread id

8 Task started

P Start : id 83868, Elapsed 0, Threads 0, ThreadId 1
W Start : id 83868, Elapsed 30, Threads 1, ThreadId 3
P Start : id 99383, Elapsed 0, Threads 1, ThreadId 1
P Start : id 53213, Elapsed 0, Threads 3, ThreadId 1
W Start : id 99383, Elapsed 0, Threads 4, ThreadId 4
P Start : id 54079, Elapsed 0, Threads 4, ThreadId 1
P Start : id 44978, Elapsed 0, Threads 5, ThreadId 1
W Start : id 53213, Elapsed 1, Threads 7, ThreadId 5
P Start : id 38396, Elapsed 0, Threads 7, ThreadId 1
P Start : id 30429, Elapsed 0, Threads 8, ThreadId 1
W Start : id 54079, Elapsed 1, Threads 8, ThreadId 8
W Start : id 44978, Elapsed 1, Threads 8, ThreadId 6
P Start : id 49184, Elapsed 0, Threads 8, ThreadId 1
W Start : id 38396, Elapsed 2, Threads 8, ThreadId 9
W Start : id 30429, Elapsed 2, Threads 8, ThreadId 10
W Start : id 49184, Elapsed 1, Threads 8, ThreadId 7
W Stop : id 83868, Elapsed 2031, Threads 8, ThreadId 3
P Stop : id 83868, Elapsed 2032, Threads 8, ThreadId 3
W Stop : id 99383, Elapsed 2001, Threads 8, ThreadId 4
P Stop : id 99383, Elapsed 2001, Threads 7, ThreadId 4
W Stop : id 53213, Elapsed 2002, Threads 6, ThreadId 5
P Stop : id 53213, Elapsed 2002, Threads 6, ThreadId 5
W Stop : id 54079, Elapsed 2002, Threads 5, ThreadId 8
P Stop : id 54079, Elapsed 2003, Threads 5, ThreadId 8
W Stop : id 44978, Elapsed 2002, Threads 5, ThreadId 6
P Stop : id 44978, Elapsed 2002, Threads 4, ThreadId 6
W Stop : id 38396, Elapsed 2002, Threads 3, ThreadId 9
P Stop : id 38396, Elapsed 2002, Threads 3, ThreadId 9
W Stop : id 49184, Elapsed 2002, Threads 2, ThreadId 7
P Stop : id 49184, Elapsed 2002, Threads 2, ThreadId 7
W Stop : id 30429, Elapsed 2003, Threads 2, ThreadId 10
P Stop : id 30429, Elapsed 2003, Threads 1, ThreadId 10

All looks good

10 Tasks started

P Start : id 63043, Elapsed 0, Threads 0, ThreadId 1
W Start : id 63043, Elapsed 15, Threads 1, ThreadId 3
P Start : id 28942, Elapsed 0, Threads 1, ThreadId 1
P Start : id 80940, Elapsed 0, Threads 3, ThreadId 1
W Start : id 28942, Elapsed 0, Threads 3, ThreadId 4
P Start : id 81431, Elapsed 0, Threads 4, ThreadId 1
P Start : id 89951, Elapsed 0, Threads 5, ThreadId 1
W Start : id 81431, Elapsed 1, Threads 8, ThreadId 6
P Start : id 29643, Elapsed 0, Threads 8, ThreadId 1
W Start : id 80940, Elapsed 1, Threads 8, ThreadId 5
P Start : id 9253, Elapsed 0, Threads 8, ThreadId 1
W Start : id 89951, Elapsed 1, Threads 8, ThreadId 8
P Start : id 53017, Elapsed 0, Threads 8, ThreadId 1
W Start : id 9253, Elapsed 22, Threads 7, ThreadId 9
P Start : id 25569, Elapsed 0, Threads 8, ThreadId 1
P Start : id 98037, Elapsed 0, Threads 8, ThreadId 1
W Start : id 53017, Elapsed 21, Threads 8, ThreadId 10
W Start : id 29643, Elapsed 22, Threads 7, ThreadId 7
// Take a look at this Elapsed this worker took 1 second to start
W Start : id 25569, Elapsed 974, Threads 9, ThreadId 11
// Take a look at this Elapsed this worker took 2 second to start
W Start : id 98037, Elapsed 1974, Threads 10, ThreadId 12
W Stop : id 28942, Elapsed 2000, Threads 10, ThreadId 4
W Stop : id 63043, Elapsed 2015, Threads 10, ThreadId 3
P Stop : id 63043, Elapsed 2016, Threads 10, ThreadId 3
P Stop : id 28942, Elapsed 2001, Threads 9, ThreadId 4
W Stop : id 81431, Elapsed 2001, Threads 8, ThreadId 6
P Stop : id 81431, Elapsed 2002, Threads 8, ThreadId 6
W Stop : id 80940, Elapsed 2002, Threads 8, ThreadId 5
P Stop : id 80940, Elapsed 2002, Threads 7, ThreadId 5
W Stop : id 89951, Elapsed 2003, Threads 6, ThreadId 8
P Stop : id 89951, Elapsed 2003, Threads 6, ThreadId 8
W Stop : id 53017, Elapsed 2022, Threads 5, ThreadId 10
P Stop : id 53017, Elapsed 2022, Threads 5, ThreadId 10
W Stop : id 9253, Elapsed 2023, Threads 5, ThreadId 9
P Stop : id 9253, Elapsed 2025, Threads 4, ThreadId 9
W Stop : id 29643, Elapsed 2024, Threads 5, ThreadId 7
P Stop : id 29643, Elapsed 2026, Threads 3, ThreadId 7
W Stop : id 25569, Elapsed 2974, Threads 2, ThreadId 11
P Stop : id 25569, Elapsed 2975, Threads 2, ThreadId 11
// eek
W Stop : id 98037, Elapsed 3975, Threads 1, ThreadId 12
// eek
P Stop : id 98037, Elapsed 4622, Threads 1, ThreadId 12

Hi there, was wondering how your GetInfo looks like. I want to do something similar for async calls to measure performance and wanted to get the same details on the Elapsed and Threads. Thanks — gdubs, Feb 25 '20 at 07:19

Leisen Chang · Answer 2 · 2018-10-26T01:37:37.220

Task.Yield() will take some time to wait for other async method in task scheduler and the time is not include in the stopwatch of UnitWorkAsync.

Code

        private async Task UnitWorkAsync()
        {
            Stopwatch stopwatch = Stopwatch.StartNew();

            await Task.Yield();
            // Blocking call.
            //
            Thread.Sleep( 2000 );

            // Async call.
            //
            await Task.Delay( 100 );

            Console.WriteLine( "UnitWorkAsync timer: " + stopwatch.ElapsedMilliseconds );

            Interlocked.Increment( ref workItemsCount );
            //Console.WriteLine( "Work items completed: " + workItemsCount );
        }

Result

UnitWorkAsync timer: 3000
ParentWorkAsync timer: 3002
UnitWorkAsync timer: 3002
ParentWorkAsync timer: 3003
UnitWorkAsync timer: 4000
ParentWorkAsync timer: 4000
UnitWorkAsync timer: 5000
ParentWorkAsync timer: 5000
UnitWorkAsync timer: 5003
ParentWorkAsync timer: 5003
UnitWorkAsync timer: 5003
ParentWorkAsync timer: 5003
UnitWorkAsync timer: 5004
ParentWorkAsync timer: 5004
UnitWorkAsync timer: 5021
ParentWorkAsync timer: 5036
UnitWorkAsync timer: 5004
ParentWorkAsync timer: 5004
UnitWorkAsync timer: 5004
ParentWorkAsync timer: 5004
UnitWorkAsync timer: 5105
ParentWorkAsync timer: 5106
UnitWorkAsync timer: 5106
ParentWorkAsync timer: 5106
UnitWorkAsync timer: 6099
ParentWorkAsync timer: 6099
UnitWorkAsync timer: 6096
ParentWorkAsync timer: 6097

Stopwatch multi-task ElapsedMilliseconds calculation

2 Answers2