Why doesn't async execution work in `select`?

Question

I am calling this action (ASP.Net Core 2.0) over AJAX:

[HttpGet]
public async Task<IActionResult> GetPostsOfUser(Guid userId, Guid? categoryId)
{
    var posts = await postService.GetPostsOfUserAsync(userId, categoryId);

    var postVMs = await Task.WhenAll(
        posts.Select(async p => new PostViewModel
        {
            PostId = p.Id,
            PostContent = p.Content,
            PostTitle = p.Title,
            WriterAvatarUri = fileService.GetFileUri(p.Writer.Profile.AvatarId, Url),
            WriterFullName = p.Writer.Profile.FullName,
            WriterId = p.WriterId,
            Liked = await postService.IsPostLikedByUserAsync(p.Id, UserId),// TODO this takes too long!!!!
        }));

    return Json(postVMs);
}

But it took too long to response (20 seconds!!!) in case I have many post objects in posts array (e.g. 30 posts).
That is caused because of this line await postService.IsPostLikedByUserAsync.

Digging into the source code of this function:

public async Task<bool> IsPostLikedByUserAsync(Guid postId, Guid userId)
{
    logger.LogDebug("Place 0 passed!");

    var user = await dbContext.Users
        .SingleOrDefaultAsync(u => u.Id == userId);

    logger.LogDebug("Place 1 passed!");

    var post = await dbContext.Posts
        .SingleOrDefaultAsync(u => u.Id == postId);

    logger.LogDebug("Place 2 passed!");

    if (user == null || post == null)
        return false;

    return post.PostLikes.SingleOrDefault(pl => pl.UserId == userId) != null;
}

The investigations showed, after some seconds, ALL "Place 1 passed!" logging methods are executed together for every post object. In other words, it seems that every post awaits until the previous post finishes executing this part:

 var user = await dbContext.Users
        .Include(u => u.PostLikes)
        .SingleOrDefaultAsync(u => u.Id == userId);

And then -when every post finishes that part- the place 1 of log is executed for all post objects.

The same happens for logging place 2, every single post seems to await for the previous post to finish executing var post = await dbContext.Pos..., and then the function can go further to execute log place 2 (after few seconds from log 1, ALL log 2 appear together).

That means I have no asynchronous execution here. Could some one help me to understand and solve this problem?

UPDATE:

Changing the code a bit to look like this:

    /// <summary>
    /// Returns all post of a user in a specific category.
    /// If the category is null, then all of that user posts will be returned from all categories
    /// </summary>
    /// <param name="userId"></param>
    /// <param name="categoryId"></param>
    /// <returns></returns>
    [Authorize]
    [HttpGet]
    public async Task<IActionResult> GetPostsOfUser(Guid userId, Guid? categoryId)
    {
        var posts = await postService.GetPostsOfUserAsync(userId, categoryId);
        var i = 0;
        var j = 0;
        var postVMs = await Task.WhenAll(
            posts.Select(async p =>
            {
                logger.LogDebug("DEBUG NUMBER HERE BEFORE RETURN: {0}", i++);
                var isLiked = await postService.IsPostLikedByUserAsync(p.Id, UserId);// TODO this takes too long!!!!
                logger.LogDebug("DEBUG NUMBER HERE AFTER RETURN: {0}", j++);
                return new PostViewModel
                {
                    PostId = p.Id,
                    PostContent = p.Content,
                    PostTitle = p.Title,
                    WriterAvatarUri = fileService.GetFileUri(p.Writer.Profile.AvatarId, Url),
                    WriterFullName = p.Writer.Profile.FullName,
                    WriterId = p.WriterId,
                    Liked = isLiked,
                };
            }));

        return Json(postVMs);
    }

That shows, that this line "DEBUG NUMBER HERE AFTER RETURN" is printed for ALL select methods together, that means that ALL select methods waits for each other before going further, how can I prevent that?

UPDATE 2

Substituting the previous IsPostLikedByUserAsyncmethod, with the following one:

public async Task<bool> IsPostLikedByUserAsync(Guid postId, Guid userId)
{
    await Task.Delay(1000);
}

Showed no problem in async running, I had to wait only 1 second, not 1 x 30. That means it is something specific to EF.

Why does the problem happen ONLY with entity framework (with the original function)? I notice the problem even with only 3 post objects! Any new ideas?

Answer 1

The deductions you've made are not necessarily true.

If these methods were firing in a non-asynchronous fashion, you would see all of the logs from one method invocation reach the console before the next method invocation's console logs. You would see the pattern 123123123 instead of 111222333. What you are seeing is that the three awaits seem to synchronize after some asynchronous batching occurs. Thus it appears that the operations are made in stages. But why?

There are a couple reasons this might happen. Firstly, the scheduler may be scheduling all of your tasks to the same thread, causing each task to be queued and then processed when the previous execution flow is complete. Since Task.WhenAll is awaited outside of the Select loop, all synchronous portions of your async methods are executed before any one Task is awaited, therefore causing all of the "first" log invocations to be called immediately following the invocation of that method.

So then what's the deal with the others syncing up later? The same thing is happening. Once all of your methods hit their first await, the execution flow is yielded to whatever code invoked that method. In this case, that is your Select statement. Behind the scenes, however, all of those async operations are processing. This creates a race condition.

Shouldn't there be some chance of the third log of some methods being called before the second log of another method, due to varying request/response times? Most of the time, yes. Except you've introduced a sort of "delay" in to the equation, making the race condition more predictable. Console logging is actually quite slow, and is also synchronous. This causes all of your methods to block at the logging line until the previous logs have completed. But blocking, by itself, may not be enough to make all of those log calls sync up in pretty little batches. There may be another factor at play.

It would appear that you are querying a database. Since this is an IO operation, it takes considerably longer to complete than other operations (including console logging, probably). This means that, although the queries aren't synchronous, they will in all likelihood receive a response after all of the queries/requests have already been sent, and therefore after the second log line from each method has already executed. The remaining log lines are processed eventually, and therefore fall in to the last batch.

Your code is being processed asynchronously. It just doesn't look quite how you might expect. Async doesn't mean random order. It just means some code flow is paused until a later condition is met, allowing other code to be processed in the mean time. If the conditions happen to sync up, then so does your code flow.

Answer 2

Actually async execution works, but it doesn't work as you expect. Select statement starts tasks for all posts and then they all work concurrently that leads you to performance problems you.

The best approach to achieve expected behavior is to reduce the degree of parallelism. There are no build-in tools to do that so I can offer 2 workarounds:

1. Use TPL DataFlow library. It is developed by Microsoft but not very popular. You can easily find enough examples though.

2. Manage parallel tasks by yourself with SemaphoreSlim. It would look like this:

   semaphore = new SemaphoreSlim(degreeOfParallelism);
   cts = new CancellationTokenSource();
   var postVMs = await Task.WhenAll(
   posts.Select(async p => 
   {
       await semaphore.WaitAsync(cts.Token).ConfigureAwait(false);
       cts.Token.ThrowIfCancellationRequested();
       new PostViewModel
       {
           PostId = p.Id,
           PostContent = p.Content,
           PostTitle = p.Title,
           WriterAvatarUri = fileService.GetFileUri(p.Writer.Profile.AvatarId, Url),
           WriterFullName = p.Writer.Profile.FullName,
           WriterId = p.WriterId,
           Liked = await postService.IsPostLikedByUserAsync(p.Id, UserId),// TODO this takes too long!!!!
       }
       semaphore.Release();
   }));
   

And don't forget to use .ConfigureAwait(false) whenever it's possible.