I have an ASP.NET Core MVC web application that has an endpoint which returns some data as a json. The onlly issue is that my data is around 5 MBs of raw (non-idented) JSON, and the response takes a really long time.
I set up some metrics and found that, on average, the processing that my application does takes around 30ms. Yet the whole response is returned after over 250ms.
I am testing with a local instance of the app running on my machine and sending a get request with postman, so networking delay is minimal.
Here is what my controller looks like
[HttpGet("getData")]
public IActionResult GetData()
{
Stopwatch sw = Stopwatch.StartNew();
long a, b, c;
var data = this._cacheInternal.GetValidDataSet();
a = sw.ElapsedMilliseconds;
sw.Restart();
var processedData = this.ProcessData(data, false);
b = sw.ElapsedMilliseconds;
sw.Restart();
var serialized = JsonConvert.SerializeObject(processedData);
c = sw.ElapsedMilliseconds;
this._log.Info($"Data: {a} ms. Processing {b} ms. Serialization {c} ms.");
return this.Ok(serialized);
}
Here is what I have discovered when examining the AspNetCore logs.
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
Request starting HTTP/1.1 GET http://localhost:5000/api/status/getData
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Route matched with {action = "GetData", controller = "Status"}. Executing action DemoApp.Controllers.StatusController.GetData (DemoApp)
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[1]
Executing action method DemoApp.Controllers.StatusController.GetData (DemoApp) - Validation state: Valid
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Executed action method DemoApp.Controllers.StatusController.GetData (DemoApp), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 31.4532ms.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker[2]
Executed action DemoApp.Controllers.StatusController.GetData (DemoApp) in 69.2546ms
info: Microsoft.AspNetCore.Hosting.Internal.WebHost[2]
Request finished in 175.2726ms 200 text/plain; charset=utf-8
The logging of the stopwatch for this request is the following :
Data: 1 ms. Processing 19 ms. Serialization 10 ms.
And as you can see from the logs for my controller:
... returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 31.4532ms.
This matches what I have with my stopwatch metrics and is the amount of time that the app is actually executing my code.
From there on there are two more points that ASP takes over:
Executed action DemoApp.Controllers.StatusController.GetData (DemoApp) in 69.2546ms
Request finished in 175.2726ms 200 text/plain; charset=utf-8
So my question is how can I find out what is happening in those two time points after ASP takes the result I pass to this.Ok()
that takes so much time (and fix it)
Again, the response I return is quite large (for this example 1.2MB raw JSON). But I don't understand what is causing such a long delay (given that the serialization I do only takes 10ms)
I am using ASP.NET Core MVC and targeting .NET Core 2.1. The app is hosted with Kestrel.
map
thenuse
a delegate that skips the controller pipeline and returns data itself but it may not be appropriate, especially if you need MVC stuff like authorization. – Fatherinlaw