c# - 秒表多任务ElapsedMilliseconds计算

Question

我有一个非常基本的函数来跟踪每个函数调用所花费的时间。 UnitWorkAsync 中的秒表返回预期值，但 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

Answer 1

Hans Passant 的评论绝对正确

首先

当你启动一个任务时，不能保证它会启动自己的线程

其次

当您调用 Thread.Sleep 时，它将使该线程休眠并完全停止，没有 pass-go。

第三

通过正确使用 await，它允许线程返回到池中直到它需要，这反过来又让任务调度程序有机会重用该线程并允许资源分配更高效

解决

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

问题

这里的问题是调度程序不会同时给你所有的线程，它只会根据一组规则、一些启发式方法(和秘方)认为你应该拥有的东西， 只是在开玩笑)。在这种使用 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