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?
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)