Секундомер многозадачного расчета 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

Ганс Пассант абсолютно прав в своих комментариях

Во-первых

Когда вы запускаете задачу, нет никаких гарантий, что она запустит еесобственный поток

Во-вторых

Когда вы вызываете Thread.Sleep, он будет спать в этом потоке с полной остановкой, без прохода.

В-третьих

При правильном использовании await он позволяет потоку возвращаться в пул до тех пор, пока он не понадобится, что, в свою очередь, дает планировщику задач возможность повторно использовать этот поток и позволяет ресурсураспределение будет более эффективным

Решение

Если вы замените 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 означают родителя и работника
• 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

Answer 2

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