Slow Process In ASP.NET MVC Life Cycle

Question

This is my Global.asax.cs. The important thing to note is, I merely throw out some messages as the various events get executed.

public class MvcApplication : System.Web.HttpApplication
{
    string file_path = "c:/temp/app.out";

    protected void Application_Start() { /* default codes here */ }

    protected void Application_BeginRequest()
    {
        File.AppendAllText(file_path, "BeginRequest starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
    }
    protected void Application_PreRequestHandlerExecute()
    {
        File.AppendAllText(file_path, "PreRequestHandlerExecute starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
    }
    protected void Application_PostRequestHandlerExecute()
    {
        File.AppendAllText(file_path, "PostRequestHandlerExecute starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
    }
    protected void Application_EndRequest()
    {
        File.AppendAllText(file_path, "EndRequest starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
    }
}

Here is my controller.

public partial class MyController : Controller
{
    [HttpGet]  public ActionResult PlaceOrders()
    {
        System.IO.File.AppendAllText("c:/temp/app.out", "PlaceOrdersGet starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
        // Logic here.
        return View(vm);
    }
    [HttpPost] public ActionResult PlaceOrders(Orders vm)
    {
        System.IO.File.AppendAllText("c:/temp/app.out", "PlaceOrdersPost starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
        // Logic here.
        return PlaceOrders();
    }

}

What baffles me is the log info captured:

BeginRequest starts at 2018/11/08 04:21:04.900
PreRequestHandlerExecute starts at 2018/11/08 04:21:04.900
PlaceOrdersGet starts at 2018/11/08 04:21:04.900
PostRequestHandlerExecute starts at 2018/11/08 04:21:05.244
EndRequest starts at 2018/11/08 04:21:05.244

BeginRequest starts at 2018/11/08 04:24:52.391
PreRequestHandlerExecute starts at 2018/11/08 04:24:52.407
PlaceOrdersPost starts at 2018/11/08 04:24:55.110
PlaceOrdersGet starts at 2018/11/08 04:24:56.094
PostRequestHandlerExecute starts at 2018/11/08 04:24:56.438
EndRequest starts at 2018/11/08 04:24:56.438

When I do a GET for PlaceOrders(), the first block shows that PlaceOrdersGet happens almost instantaneously after PreRequestHandlerExecute. However, when I do a POST to PlaceOrders, it takes almost 2.7 seconds from PreRequestHandlerExecute to PlaceOrdersPost! The only difference between these two blocks, is that the latter has a ViewModel returned, while the former doesn't.

I have browsed a bit the web, but couldn't find any help to drill further down this issue. I know there's this ProcessRequest method that gets called, but that's as far as I could go. This has had grave adverse impact on the overall performance.

Any help or simple codes to spill out more timing info would be appreciated.

user_2763850 · Answer

I think I have found the answer. Yes, the delay of 2.7 seconds here

PreRequestHandlerExecute starts at 2018/11/08 04:24:52.407
PlaceOrdersPost starts at 2018/11/08 04:24:55.110

is indeed due to Model Binding!

The solution is to model-bind myself...

I have simply modified my HttpPost Action from

[HttpPost] public ActionResult PlaceOrders(Orders vm)
{
    System.IO.File.AppendAllText("c:/temp/app.out", "PlaceOrdersPost starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);
    // Logic here.
    return PlaceOrders();
}

to the following:

[HttpPost] public ActionResult PlaceOrders(FormCollection fc)
{
    System.IO.File.AppendAllText("c:/temp/app.out", "PlaceOrdersPost starts at " + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + Environment.NewLine);

    var vm = new Orders();
    // Assign fc to vm here.
    // Logic here.
    return PlaceOrders();
}

And this is the log I get:

PreRequestHandlerExecute starts at 2018/11/08 13:27:09.088
PlaceOrdersPost starts at 2018/11/08 13:27:09.106

At least there is now negligible delay from PreRequestHandlerExecute to PlaceOrdersPost.

user_2057407 · Answer

I don't have enough reputation to make a comment, but how large is your Orders model and where do you use it? If it's a large model with collections and you are populating those collections it may take a while for the model to populate with JSON. As far as I can see there is no reason for that model as you are not using it anywhere. Try without the Orders model in your post action and see how long it takes.

Slow Process In ASP.NET MVC Life Cycle

2 Answers