秒表多任务ElapsedMilliseconds计算

Stopwatch multi-task ElapsedMilliseconds calculation

我有一个非常基本的功能来跟踪每个函数调用所花费的时间。 UnitWorkAsync 中的秒表 returns 预期值,但 ParentWorkAsync 中的计时器不断增加任务间的时间。秒表跟踪我做错了什么?

在输出中,我假设 ParentWorkAsync 计时器与 UnitWorkAsync 计时器大致相同,但情况并非如此,如下所示

代码

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);
    }
}

输出:

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

Task.Yield() 将花费一些时间等待任务调度程序中的其他异步方法,并且该时间不包括在 UnitWorkAsync 的秒表中。

代码

        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 );
        }

结果

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

Hans Passant 的评论绝对正确

首先

启动任务时,无法保证它会启动自己的线程

其次

当您调用 Thread.Sleep 时,它会休眠该线程并完全停止,不会 pass-go。

第三次

通过正确使用 await,它允许线程返回到池中直到需要,这 in-turn 使任务计划程序有机会重用该线程并允许资源分配更有效率

解决

如果将 Thread.Sleep 替换为 await Task.Delay(2000),您会发现这会按预期工作。 T

问题

这里的问题是调度程序不会一次给你所有的线程,它只会给你认为你应该基于一组规则的东西,一些启发式(和秘方,开玩笑)。在 Thread.Sleep 的这种情况下,调度程序对您正在做的事情持模糊的看法,并且不会让您拥有您可能喜欢的所有线程。

现在让我们证明一下

修改后的代码

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)}");    
}

这是 8 个任务,

  • W和P代表parent和worker
  • Id = 跟踪事件的随机数
  • Elapsed = 使用从开始到结束的经过时间的同一秒表
  • Threads = 在任一时刻使用了多少个线程
  • ThreadId = 是线程id

8 任务开始

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

看起来不错

10 个任务已开始

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