Asp.net core middleware routing delay between request and action

Question

I am working on a rest API .net core 2.0 which takes JSON payload of around 1MB. While checking logs, I find a huge delay between request to action method invoking.

Logs:

20:05:12.7247|1|INFO|Microsoft.AspNetCore.Hosting.Internal.WebHost|Request starting HTTP/1.1 POST

20:05:12.7514||INFO|Service.RequestLoggingMiddleware|Middleware Request recieved at 2019-03-12 20:05:12.725
20:05:15.2839|1|INFO|Microsoft.AspNetCore.Mvc.Internal.ControllerActionInvoker|Executing action method

Around 2 seconds delay between request received and routed to the corresponding action. I have added only Nlog provider, custom middleware to log request reception and mvc in middleware pipeline.

Custom Middleware logging time of request:

 public class RequestLoggingMiddleware
 {
    private readonly RequestDelegate requestDelegate;
    private ILogger<RequestLoggingMiddleware> logger;
    public RequestLoggingMiddleware(RequestDelegate _requestDelegate,ILogger<RequestLoggingMiddleware> _logger)
    {
        requestDelegate = _requestDelegate;
        logger = _logger;
    }

    public async Task Invoke(HttpContext context)
    {
        try {


            string timestamp = DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff",CultureInfo.InvariantCulture);
            logger.LogInformation("Middleware Request recieved at {0}", timestamp);

            await requestDelegate.Invoke(context);
        }
        catch { }
    }


}

Middeware pipeline configured:

    public void Configure(IApplicationBuilder app, IHostingEnvironment 
     env,ILoggerFactory loggerFactory)

        {

         if (env.IsDevelopment())
        {
            app.UseDeveloperExceptionPage();
        }
        env.ConfigureNLog("nlog.config");
        loggerFactory.AddNLog();
        app.AddNLogWeb();
        app.UseMiddleware<RequestLoggingMiddleware>();
        app.UseMvc();
       }

Edit: I find delay is proportional to size of Json payload.

 public SampleController(ILogger<GroupsValidation1Controller> _logger)
 {
        logger = _logger;
 }

       [HttpPost]
 public   IActionResult Validate([FromBody]JObject inputValue)
 {
      logger.LogInformation(" method starts ");
    ///controllerlogic
     logger.LogInformation(" method ends");
 }

Why .Net Core MVC middleware is taking this much time? Is there any way to reduce delay spent in middleware?
I also find entire request is also logged though it is not configured. I am not sure if logging entire request is taking time. Is there any way to disable it?

Answer 1

I figured the entire delay is happening in model binding. As Json payload size is large, model binding to jobject type is taking time. Skipping model binding and reading raw request body or using custom model instead of jobject, I am able to reduce delay and improve performance of api.