In ASP.NET Core 5 MVC app, ControllerActionInvoker.InvokeActionAsync method seems to be called twice in the same thread simultaneously?

Question

I use a CLR profiler to log the framework methods in a primitive APM kind of way. While using this, the request flow generally is such that it flows through the middleware that I inserted into the application dynamically and then to the request handlers.

In this case the ControllerActionInvoker (ASP.NET Core 5 MVC), here the request thread would be the same where the InvokeActionAsync() function returns a Task object and the task continues on a separate thread in the thread pool. But how would the InvokeActionAsync() be triggered a second time within the same thread before the first method even returned the Task object? This only happens when the Load is high, otherwise the request flow is predictable.

The logs are as below:

13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] MiddleWarePipeline.Invoke is called
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync is called.
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync is called.
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ----- some other -----
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ------functions ------
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ------are getting-----
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ----logged that ------
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] -------happen inside ----
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ----that particular -----
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] ------action method-----
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync has returned task obj.
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync has returned task obj.
13-11-2023 21:00:03 [4:(DEBUG)<t:23>] - [TName: ] MiddleWarePipeline.Invoke has returned  obj.

Is this expected behaviour? Is this the same request that triggers the InvokeActionAsync() twice, or is it two requests? if it is it two, how do they differentiate the two requests in the same thread?

Answer 1

Okay , The Profiler I was using was instrumenting the functions a second time when they were re-jitted during High-Load scenarios. I have now added a check to make sure if the methods have already been injected with code.

PS: The CoreCLR rejits code when There is a high load ?!(Will look into it and come back If I find anything)

Answer 2

Request thread would be the same where the InvokeActionAsync() function returns a Task object and the task continues on a separate thread in the thread pool. But how would the InvokeActionAsync() be triggered a second time within the same thread before the first method even returned the Task object, Is this expected behaviour? Is this the same request that triggers the InvokeActionAsync() twice, or is it two requests?

First of all, middleware execution twice is not a downsides. In general, this is the expected behavior when executing a middleware twice because when an HTTP request executes usually two endpoints get hit. So the middleware executes twice.

If you debug your application, you would observe that first call InvokeActionAsync would be executed for loading your application itself the base path should be your domain/local host or /.

And for the second time, your application has its resouce file. For instance, css, js or any other internal file within your application root folder which need additional execution.

Please have a look at the following network trace log:

Note: However, sometimes it is not expected for this method to be called multiple times for the same request within the same thread if you don't have additional resource which usually be callled when the program starts. For instance, static files.

If it is it two, how do they differentiate the two requests in the same thread?

Well, for ASP.NET Core in order to differentiate between multiple requests in the same thread, it uses an HttpContext object associated with each request. The HttpContext contains information about the current request, including headers, parameters, and other relevant details. This context is unique to each incoming request, and it is used to distinguish between different requests even if they are being processed on the same thread.

If you need more precise understanding of why InvokeActionAsync is being called twice in your specific scenario,you can analysis your call stack, log additional information during the request processing.

Additionally, inspecting the HttpContext during each invocation can help identify any differences between the two invocations

Note: Please refer to this official document for more if you want to know how you can check httpContext details and background thread.