Using Stopwatch and ContinueWith to Measure Task Execution Time in C#

Lately, as part of the major refactoring I've been writing about, my team and I have decided to introduce asynchronous programming to a project we've been trying to improve. For the most part, that work has been useful and relatively easy, but lately we've been running into an issue where several asynchronous tasks are seeming to take longer than they should. The pileup of tasks is causing us to try to determine which one is taking a while.

NOTE: This post is part of the Second Annual C# Advent. Check out the other posts there too! This post also has a sample project over on GitHub.

Here's the problem: given a set of tasks that are running asynchronously, how can we determine which one is taking longer than expected?

Let's get started!

The Setup

First let's see what we are working with.

Tasks tasks = new Tasks();

var task1 = tasks.OneSecondTask();
var task2 = tasks.TwoSecondTask();
var task3 = tasks.ThreeSecondTask();
var task4 = tasks.FourSecondTask();
            
Task.WaitAll(task1, task2, task3, task4);

We've got some tasks, and from their names we expect them to take one, two, three, and four seconds respectively. Let's introduce a stopwatch to see how long these tasks take.

Tasks tasks = new Tasks();

//Here's our stopwatch.
Stopwatch watch = new Stopwatch();
watch.Start();

var task1 = tasks.OneSecondTask();
var task2 = tasks.TwoSecondTask();
var task3 = tasks.ThreeSecondTask();
var task4 = tasks.FourSecondTask();
            
Task.WaitAll(task1, task2, task3, task4);

watch.Stop();

//Output the milliseconds elapsed to the console.
Console.WriteLine("Tasks take " + watch.ElapsedMilliseconds + " milliseconds");

Here's the output from running this:

Waaaaait a minute....  Since these are asynchronous tasks, we would expect the total execution time to be roughly the time of the longest task, e.g. four seconds. But the output says it's taking ten seconds!

Now we need to figure out why.  

Stop, and Watch

The simplest way I know to do this is to use a Stopwatch class.  But how do we do that so that it records each task individually, not all at the same time like above?

What we need is to hook some functionality into the task that runs after it completes.  For this, we use the ContinueWith extension on the Task class, like so:

var task1watch = new Stopwatch();
task1watch.Start();
var watchtask1 = tasks.OneSecondTask().ContinueWith(x =>
{
    task1watch.Stop();
    Console.WriteLine("Task 1 took " 
                      + task1watch.ElapsedMilliseconds 
                      + " milliseconds to run.");
});

Let me take a second to explain what is happening here. The ContinueWith function attaches another task which executes at the end of the first task. In our particular case, this "attached" task merely stops the stopwatch and outputs the elapsed milliseconds to the command line.

We need to do this for every task. Here's what it looks like for tasks two, three, and four:

var task2watch = new Stopwatch();
task2watch.Start();
var watchtask2 = tasks.TwoSecondTask().ContinueWith(x =>
{
    task2watch.Stop();
    Console.WriteLine("Task 2 took " 
                      + task2watch.ElapsedMilliseconds 
                      + " milliseconds to run.");
});

var task3watch = new Stopwatch();
task3watch.Start();
var watchtask3 = tasks.ThreeSecondTask().ContinueWith(x =>
{
    task3watch.Stop();
    Console.WriteLine("Task 3 took " 
                      + task3watch.ElapsedMilliseconds 
                      + " milliseconds to run.");
});

var task4watch = new Stopwatch();
task4watch.Start();
var watchtask4 = tasks.FourSecondTask().ContinueWith(x =>
{
    task4watch.Stop();
    Console.WriteLine("Task 4 took " 
                      + task4watch.ElapsedMilliseconds 
                      + " milliseconds to run.");
});

Task.WaitAll(watchtask1, watchtask2, watchtask3, watchtask4);

We know from our earlier test that one of these tasks is taking 10 seconds to run. Now let's run our new stopwatches, and see which of the tasks it is.

Surprise! Not just one, but TWO of the tasks are taking longer than we expected. Tasks 1 and 3 are fine, but task 2, which we expected to take two seconds, is taking five, and task 4 is the ten-second task. There isn't one bug, there's two!

This is why we are better off attaching stopwatches to each of the tasks rather than just the suspected one. We suspected task 4, but had we only watched it and not the others, we would have fixed it but totally missed the bug in task 2.

If you want to run this for yourself, the sample project is over on GitHub.

Summary

If you ever run into a situation where you have multiple tasks that might be taking longer than expected, you can use ContinueWith and the Stopwatch class to measure how long each task takes.

Don't forget to check out the rest of the C# Advent posts!

Happy Coding!