Stopwatch with an async action which awaits calls from a database

Question

How can I properly use the Stopwatch class with an async action event that awaits calls to my database asynchronously inside an async Post method on DotNet Core ?

Why

To time my code and check for bottleneck. This is a simplified test method that will contain more code as time goes on.

Errors

I tried using an Action event, a Task event and a Func<Task> event without success and they all give me errors which always occurs when I am awaiting a call from my database asynchronously using EF Core

When I use Action event

An unhandled exception of type 'System.ObjectDisposedException' occurred in System.Private.CoreLib.dll. Cannot access a disposed context instance.

When I use Func<Task>

System.Threading.Tasks.TaskCanceledException: A task was canceled.

It doesn't print anything when I use Task event and the rest of the code executes without errors

Code

Post Method

public async Task<JsonResult> OnPostTest() {
    // my Database Context
    using DatabaseContext dc = _dbContext;
    
    // list of json data that will be returned back to the client
    List<object>? listJsonData = null;

    // stopwatch initialization
    Stopwatch sw = new();
    sw.LogActionAsync(nameof(OnPostTest), (async () => { // new Task(async () => { // new Func<Task>(async() => {

        // get list of data from TableTest database with a valid name and are not marked as delete
        List<TableTest> listValidTabletest = await dc.ListTest.AsNoTracking().Where(t => !string.IsNullOrWhiteSpaces(t.strName) && !t.blnDelete).ToListAsync(); //<-- returns a list asynchronously and where the error occurs
        
        // initialize list that will be returned
        listJsonData = new();

        foreach (TableTest t in listValidTableTest) {
            // object that will be in the list of returned json objects
            var returnData = new {
                t.strName,
                t.arrPrices,
                t.strStartDate,
                t.strEndDate
            };

            listJsonData.Add(returnData);
        }
    }));

    return new JsonResult(new { 
        // return list or an empty array if list has not been initialized
        arrJsonData = listJsonData?.toArray() ?? Array.Empty<object>(),
        blnGetStatus = bool.TrueString 
    });
}

Stopwatch Extension Class

public static async void LogActionAsync(this Stopwatch sw, string? strMethodName, Action asyncAction, int intNbOfIterations = 1) {
    sw.Reset();
    sw.Start();

    List<Task> listOfTasks = new();
    for (int i = 0; i < intNbOfIterations; i++) {
        listOfTasks.Add(Task.Factory.StartNew(asyncAction)); // for Action event
       
        //listOfTask.Add(asyncTask); // for Task event
    }

    await Task.WhenAll(listOfTasks);
    //await asyncFuncTask; // for Func\<Task> event

    sw.Stop();

    // log duration to a file using Serilog
    Log.Debug($"{strMethodName} Action Duration: '{sw.Elapsed.Duration()}'");
}

---

EDIT: I changed my stopwatch extension method to async Task LogActionAsync... and my stopwatch object to await sw.LogActionAsync... but now nothing is being logged*. Any idea ?

Answer 1

There's a lot of bugs in this code. To summarize:

1. async void in two places.
2. Missing awaits.
3. Using a single database context concurrently.
4. Adding to a list of results concurrently.

So, let's fix these one by one.

---

1. async void in two places.
2. Missing awaits.

As another answer noted, LogActionAsync should not be async void but should be async Task and awaited.

I changed my stopwatch extension method to async Task LogActionAsync... and my stopwatch object to await sw.LogActionAsync...

You're still missing one more async void. It's a tricky one: lambdas, when assigned to Action variables, become async void. The proper delegate type for an asynchronous method without a return value is Func<Task>, not Action.

Code:

public static async Task LogActionAsync(this Stopwatch sw, string? strMethodName, Func<Task> asyncAction, int intNbOfIterations = 1) {
    sw.Reset();
    sw.Start();

    List<Task> listOfTasks = new();
    for (int i = 0; i < intNbOfIterations; i++) {
        listOfTasks.Add(asyncAction());
    }

    await Task.WhenAll(listOfTasks);

    sw.Stop();

    // log duration to a file using Serilog
    Log.Debug($"{strMethodName} Action Duration: '{sw.Elapsed.Duration()}'");
}

And now you can properly use await everywhere.

---

3. Using a single database context concurrently.
4. Adding to a list of results concurrently.

As another answer noted, you will need one database context per action lambda. This is a limitation of Entity Framework (in turn imposed by a limitation of most SQL on-the-wire protocols).

The List<T>.Add method is also not threadsafe, and the code is potentially invoking it from multiple threads concurrently. It's possible to use a concurrent collection, but it's easier and cleaner to return result data instead of modifying a shared collection as a side effect.

But, really, I suspect that the concurrency in the posted code is an accident. It seems very odd to run N "iterations" of something concurrently when doing timing; I believe the desired semantics are to run N iterations of something serially.

If my assumption is correct, then the code should look like this:

public static async Task LogActionAsync(this Stopwatch sw, string? strMethodName, Func<Task> asyncAction, int intNbOfIterations = 1) {
    sw.Reset();
    sw.Start();

    for (int i = 0; i < intNbOfIterations; i++) {
        await asyncAction();
    }

    sw.Stop();

    // log duration to a file using Serilog
    Log.Debug($"{strMethodName} Action Duration: '{sw.Elapsed.Duration()}'");
}

public static async Task<T> LogActionAsync<T>(this Stopwatch sw, string? strMethodName, Func<Task<T>> asyncFunc, int intNbOfIterations = 1) {
    sw.Reset();
    sw.Start();

    T result = default;
    for (int i = 0; i < intNbOfIterations; i++) {
        result = await asyncFunc();
    }

    sw.Stop();

    // log duration to a file using Serilog
    Log.Debug($"{strMethodName} Action Duration: '{sw.Elapsed.Duration()}'");
    return result;
}

public async Task<JsonResult> OnPostTest() {
    // my Database Context
    using DatabaseContext dc = _dbContext;

    // list of json data that will be returned back to the client
    List<object>? listJsonData = null;

    // stopwatch initialization
    Stopwatch sw = new();
    listJsonData = await sw.LogActionAsync(nameof(OnPostTest), (async () => {
        // get list of data from TableTest database with a valid name and are not marked as delete
        List<TableTest> listValidTabletest = await dc.ListTest.AsNoTracking().Where(t => !string.IsNullOrWhiteSpaces(t.strName) && !t.blnDelete).ToListAsync();
        
        // initialize list that will be returned
        var jsonData = new List<object>();

        foreach (TableTest t in listValidTableTest) {
            // object that will be in the list of returned json objects
            var returnData = new {
                t.strName,
                t.arrPrices,
                t.strStartDate,
                t.strEndDate
            };

            jsonData.Add(returnData);
        }

        return jsonData;
    }));

    return new JsonResult(new { 
        // return list or an empty array if list has not been initialized
        arrJsonData = listJsonData?.toArray() ?? Array.Empty<object>(),
        blnGetStatus = bool.TrueString 
    });
}