1
private void buttonLoad_Click(object sender, EventArgs e)
{
    DataTable dt = new DataTable(); //create datatable with 6000 records
    dt.Columns.Add("Name");
    dt.Columns.Add("Value");

    for (int i = 0; i < 2000; i++)
    {
        dt.Rows.Add("Tim", "955");
        dt.Rows.Add("Rob", "511");
        dt.Rows.Add("Steve", "201");
    }

    dataGridView1.DataSource = dt;
}

private async void btnSend_Click(object sender, EventArgs e)
{
    progressBar1.Minimum = 1;
    progressBar1.Maximum = dataGridView1.Rows.Count;
    progressBar1.Value = 1;
    progressBar1.Step = 1;

    List<Task> lstTasks = new List<Task>();

    DataTable dt = (DataTable)dataGridView1.DataSource;

    System.Diagnostics.Stopwatch s = new System.Diagnostics.Stopwatch();
    s.Start();
    foreach (DataRow dr in dt.Rows)
    {
        lstTasks.Add(CallAPIAsync(dr));
    }
    await Task.WhenAll(lstTasks);
    
    MessageBox.Show(s.ElapsedMilliseconds.ToString());
}

private async Task CallAPIAsync(DataRow dr)
{
    try
    {
        await Task.Delay(2000); //simulate post api request that will pass dr[name] and dr[value]

        if (new Random().Next(0,100)>95) //simulate error in the above request
        {
            throw new Exception("Test!");
        }
    }
    catch (Exception e)
    {
        Thread.Sleep(1);//similate sync processing that takes 1ms                
    }

    progressBar1.PerformStep();
}

In buttonLoad_Click I am loading sample data into datatable.

In btnSend_Click I am simulating an async task.

In the async task, if you change the value of

if (new Random().Next(0,100)>95)

to

if (new Random().Next(0,100)>5)

in order to simulate more exceptions then the code will run slowly even though the catch block takes only 1ms.

Why is async await very slow and blocking when exception handling is involved?

Peter Csala
  • 17,736
  • 16
  • 35
  • 75
variable
  • 8,262
  • 9
  • 95
  • 215

2 Answers2

4

While there are already some good hints within the comments, I found several points, that make me stumble:

You run 2000 (or as your comment 6000) tasks in parallel. Due to the fact, that we are in Winforms (WPF would be the same), each of these tasks gets the UI thread as synchronization context, which means that even if you say Task.WhenAll(), all of them have to be executed sequentially, cause they run in the UI thread.

Then in your code you have this new Random().Next(). This means a new instance of random is created and the seed is generated from the current time. This leads to the fact, that you produce the same random number multiple times. When this number is somewhere in your range 95 - 100, all these tasks will cause an Thread.Sleep(1) (and not an await Task.Delay(1)) and due to the fact, that you are within the UI thread your UI will freeze.

So here my improvements for you:

  • Break up your working horse from the ui upate code. When you use CallAPIAsync(dr).ConfigureAwait(false), the code will be performed within another thread, but you can't simply write progressBar1.PerformStep(), you have to wrap this within an progressBar1.BeginInvoke() call to dispatch this method to the UI thread.

  • When you are within the world of tasks, don't use Thread.Sleep(), cause one thread is responsible for multiple tasks. Instead use await Task.Delay() so other tasks within the same thread can do their work.

  • Be aware what using async / await means in an UI application and if your code will run on the UI thread or somewhere else. Learn how to properly use .ConfigureAwait(false) in these cases.

  • Learn the proper usage of new Random().

Also, can you tell me whether each callback runs fully before running the next callback?

This question is a little more complicated and doesn't fit into a comment. So here is my answer.

In your current implemenation your callback is bound to the UI thread due to the missing ConfigureAwait(false). So all your tasks must be processed by the UI thread. They start sequentially till reaching your first Task.Delay(2000). Here they got queued up for being processed in two seconds. Cause queueing up 2000 tasks is faster then two seconds, all your tasks getting to this point more or less in parallel. After the delay is over they have to be processed again by the one and only UI thread. So it creates a new Random instance, calls next and depending on the outcome of the whole process the (attention: UI) thread freezes for one millisecond or not. Due to your misusage of the Random class you can get a lot of exceptions, which in sum freezes your UI up for 2 seconds if all 2000 tasks run into the exception for one millisecond.

Oliver
  • 43,366
  • 8
  • 94
  • 151
  • I have used thread.sleep as placeholder for some syncronous work. – variable Aug 03 '21 at 06:51
  • Doesn't `CallAPIAsync(dr).ConfigureAwait(false)` mean that all async calls within this call must also be marked as ConfigureAwait false? Also, does this setting mean that the awaited code will run in separate thread or as you say the call itself will be run in new thread? – variable Aug 03 '21 at 07:02
  • Also, can you tell me whether each callback runs fully before running the next callback? – variable Aug 03 '21 at 07:31
  • If you apply `ConfigureAwait(false)` to a task it doesn't get a syncContext. Every await call within this method derives this syncContext. Cause there isn't anyone now, they all run on any available thread. How many threads are being used depends on the TaskScheduler. – Oliver Aug 03 '21 at 08:14
  • In the current code, I tried to make the Iprogress approach rather than using the control to update progress bar, without configure await false. Just to test. When run, the progress bar didn't update - I think as you said the tasks are blocking ui thread so Iprogress report isn't able to execute changes to progressbar – variable Aug 03 '21 at 08:33
  • 1
    I would upvote this otherwise brilliant answer, if it didn't include the `ConfigureAwait(false)` suggestion. This method is intended for library code IMHO. In application code, in most cases it's a hack. The correct way to offload work to a `ThreadPool` thread is the `Task.Run` method, and the best way to pass the result of the computation from the background thread to the UI thread is to use generic tasks `Task`, as shown [here](https://stackoverflow.com/questions/68052346/await-dispatcher-invokeasync-vs-dispatcher-invoke/68053609#68053609) for example. – Theodor Zoulias Aug 03 '21 at 09:26
  • @TheodorZoulias The `ConfigureAwait(false)` is to see in conjunction with separate the UI code from the computing code. After that, the computing code needs to be called with `ConfigureAwait(false)`. How and where this gots encapsulated is up to the programmer, but in this *simple example* it would be the way to go. For really understanding how to use it my third bullet point comes into play. ;-) – Oliver Aug 03 '21 at 09:39
  • I am assuming that the intention behind the `ConfigureAwait(false)` is to avoid running the code after the `await` on the UI thread. This is not a reliable way to achieve this goal. It depends on the awaitable being non-completed at the time it is awaited. If it is completed, the UI thread will continue running the code after the `await`. I don't know the probabilities of the awaitable being completed on the `await` point, but in any case this looks like a race condition to me. – Theodor Zoulias Aug 03 '21 at 10:05
  • 1
    Btw I just noticed that there is a `progressBar1.PerformStep();` after the `await`. Adding `ConfigureAwait(false)` will cause this line to run on a non-UI thread (in most cases), resulting quite likely in a *"The calling thread cannot access this object because a different thread owns it"* exception. – Theodor Zoulias Aug 03 '21 at 10:24
  • @TheodorZoulias That's my first bullet point about. ;-) – Oliver Aug 04 '21 at 05:42
  • 1
    Yeah, I didn't read your answer too carefully to be honest. When I saw the `.ConfigureAwait(false)` I became upset and I had to react instantly. – Theodor Zoulias Aug 04 '21 at 05:46
  • Is `progressBar1.BeginInvoke()` an alternative to using the IProgress approach? – variable Aug 20 '21 at 19:54
2

I've run this on the console and made a few changes to compare different configurations.

  • Without any exceptions, multiple runs for a list of 2000 tasks took between 2179 and 2189 ms.
  • With 5% chance of an exception, they took ~4s
  • With 50% chance of an exception, they took 22-23s.
  • With 75% chance of an exception, they took 31s-33s.
  • With an exception thrown each time, they took 42s

That's close to a linear relation - each exception adds around 20ms.

My first guess for the 20ms would be that Thread.Sleep(1) actually is not as precise as you'd hope. The documentation mentions the system clock resolution, which in the documentation for Task.Delay is described in a sidenote as 15ms. A stopwatch seemed to confirm that sleeping actually took 20ms. But with actual CPU-bound work that only took 2ms, instead of 40s it now took 60s when each task had to handle exceptions.

And when I increase the sleep duration to 1000ms, with 5% exceptions the total duration is ~12.2s. So it's not simply the sleep time adding up sequentially.

So I've used some debug outputs to see what's happening when running 10 tasks, all throwing exceptions that lead to 1000ms sleep. I've added outputs comparing task-local and global stopwatch times for: start, throwing, catching, after resuming from sleep.

Starting task 1 at: 0ms (task-local) 15ms (global)
Starting task 2 at: 0ms (task-local) 40ms (global)
Starting task 3 at: 0ms (task-local) 41ms (global)
Starting task 4 at: 0ms (task-local) 43ms (global)
Starting task 5 at: 0ms (task-local) 45ms (global)
Starting task 6 at: 0ms (task-local) 47ms (global)
Starting task 7 at: 0ms (task-local) 50ms (global)
Starting task 8 at: 0ms (task-local) 51ms (global)
Starting task 9 at: 0ms (task-local) 53ms (global)
Starting task 10 at: 0ms (task-local) 55ms (global)
Started Thread 2948
Started Thread 15380
Started Thread 17984
Started Thread 11564
Throwing exception in task 7 at: 2016ms (task-local) 2066ms (global)
Throwing exception in task 8 at: 2014ms (task-local) 2066ms (global)
Throwing exception in task 6 at: 2018ms (task-local) 2066ms (global)
Throwing exception in task 5 at: 2020ms (task-local) 2066ms (global)
Caught exception in task 7 at: 2084ms (task-local) 2134ms (global)
Caught exception in task 6 at: 2098ms (task-local) 2145ms (global)
Caught exception in task 5 at: 2102ms (task-local) 2147ms (global)
Caught exception in task 8 at: 2109ms (task-local) 2161ms (global)
Started Thread 15468
Throwing exception in task 9 at: 3015ms (task-local) 3068ms (global)
Caught exception in task 9 at: 3035ms (task-local) 3088ms (global)
Slept for 1s in task 7 at: 3107ms (task-local) 3157ms (global)
Throwing exception in task 4 at: 3118ms (task-local) 3162ms (global)
Slept for 1s in task 5 at: 3118ms (task-local) 3164ms (global)
Slept for 1s in task 6 at: 3115ms (task-local) 3162ms (global)
Slept for 1s in task 8 at: 3122ms (task-local) 3173ms (global)
Throwing exception in task 2 at: 3145ms (task-local) 3185ms (global)
Throwing exception in task 1 at: 3173ms (task-local) 3188ms (global)
Caught exception in task 4 at: 3143ms (task-local) 3187ms (global)
Caught exception in task 2 at: 3179ms (task-local) 3219ms (global)
Caught exception in task 1 at: 3215ms (task-local) 3230ms (global)
Throwing exception in task 3 at: 3142ms (task-local) 3184ms (global)
Caught exception in task 3 at: 3213ms (task-local) 3255ms (global)
Started Thread 27088
Throwing exception in task 10 at: 4010ms (task-local) 4065ms (global)
Caught exception in task 10 at: 4031ms (task-local) 4086ms (global)
Slept for 1s in task 9 at: 4038ms (task-local) 4092ms (global)
Slept for 1s in task 2 at: 4193ms (task-local) 4233ms (global)
Slept for 1s in task 4 at: 4190ms (task-local) 4233ms (global)
Slept for 1s in task 1 at: 4221ms (task-local) 4236ms (global)
Slept for 1s in task 3 at: 4222ms (task-local) 4264ms (global)
Slept for 1s in task 10 at: 5035ms (task-local) 5091ms (global)

Compare this to the output without exceptions:

Starting task 1 at: 0ms (task-local) 2ms (global)
Starting task 2 at: 0ms (task-local) 36ms (global)
Starting task 3 at: 0ms (task-local) 38ms (global)
Starting task 4 at: 0ms (task-local) 40ms (global)
Starting task 5 at: 0ms (task-local) 42ms (global)
Starting task 6 at: 0ms (task-local) 46ms (global)
Starting task 7 at: 0ms (task-local) 48ms (global)
Starting task 8 at: 0ms (task-local) 50ms (global)
Starting task 9 at: 0ms (task-local) 53ms (global)
Starting task 10 at: 0ms (task-local) 55ms (global)
Started Thread 12496
Started Thread 16480
Started Thread 10184
Started Thread 17696
Done waiting in task 2 at: 2023ms (task-local) 2059ms (global)
Done waiting in task 5 at: 2016ms (task-local) 2059ms (global)
Done waiting in task 4 at: 2018ms (task-local) 2059ms (global)
Done waiting in task 3 at: 2020ms (task-local) 2059ms (global)
Done waiting in task 1 at: 2066ms (task-local) 2068ms (global)
Done waiting in task 6 at: 2024ms (task-local) 2070ms (global)
Done waiting in task 7 at: 2023ms (task-local) 2071ms (global)
Done waiting in task 10 at: 2017ms (task-local) 2072ms (global)
Done waiting in task 9 at: 2018ms (task-local) 2071ms (global)
Done waiting in task 8 at: 2020ms (task-local) 2071ms (global)

I'm seeing a block of four tasks being handled together in the beginning. When they throw, they're throwing, being caught and handled together, then together they block the main thread before the next block of four can proceed, but it's starting to overlap a bit. For a huge number of tasks and exceptions, the exceptions trickle in sequentially in blocks - maybe depending on the number of available cores?

Writing console output can of course mess up the measurements, but I've seen that after roughly 800 tasks, 2000ms have passed, and the first task is done waiting. So while not all tasks have even started, the first exception starts slowing down the main thread.

Seeing this, I think it depends on your actual code when it comes to improving it. Can you change the API to allow sending multiple rows with one request? Maybe don't start sending all 6000 requests at once and individually - if one fails, the rest are likely to also fail. Maybe a single catch block around the await Task.WhenAll is enough?

Update: I did what I should have done in the beginning and measured without flooding the console. Now it's more obvious that catching each exception takes a significant amount of time (>20 ms). And that's happening on one thread, so one exception at a time. When the exception handling really takes only around 1ms, then switching to await Task.WhenAll just saves you as many milliseconds as you have exceptions.

badasta
  • 83
  • 6
  • What you are observing may be the result of a saturated `ThreadPool`. You could try adding this line at the start of the program: `ThreadPool.SetMinThreads(1000, 1000);`, to rule out this possibility. – Theodor Zoulias Aug 07 '21 at 02:55
  • 1
    I was curious and tried it. The overall amount of time it took was pretty much the same (~40s with 100% exceptions). – badasta Aug 07 '21 at 22:18
  • The demo code awaiting Task.Delay and the actual idea of sending requests both don't require threads and these (anecdotal) measurements seem to confirm this. I've found [this thread](https://stackoverflow.com/a/22492731/16607977) about throttling async work and think an important question to ask is how many requests should be allowed to run in parallel. – badasta Aug 07 '21 at 22:37