What happens in BeginProcessRequest()?

Question

We are using NewRelic to provide server-side application traces.

We have noticed that some of our applications consistently spend about 100ms in the method System.Web.Mvc.MvcHandler.BeginProcessRequest().

This happens before any custom controller code is called (which is logged separately, and not cumulatively) - it's not obvious why it would be spending so much time in this method.

What kinds of things will MVC do in this method? Could this simply be request queuing?

[EDIT:] As suspected - Scalayer's answer below was spot-on. We removed & optimized away all our session dependencies, and saw a massive increase in application scalability & stability

Answer 1

What you might be seeing is commonly referred to as thread agility in .NET.

What you're probably seeing as far as the results underneath the topical label (i.e. Application code in System.Web.HttpApplication.BeginRequest()) is a thread agility problem; in most cases the time you see here isn't necessarily code being executed but the web context waiting for the threads to be released back to it from a reader-writer lock.

The Application_BeginRequest() "pause" is one that is pretty pervasive in a ASP.NET web stack. In general when you see long load times in BeginRequest, you are dealing with ASP.NET thread agility and/or thread locks - especially when dealing with IO and session based operations. Not that it's a bad thing, this is just how .net makes sure your threads remain concurrent.

The time gap generally occurs between BeginRequest and PreRequestHandlerExecute. If the application is writing several things to session then ASP.NET will issue a reader-writer lock on HttpContext.Current.Session.

A good way to see if this is an issue that you might be facing would be to check the thread IDs to see if agility is an issue - the IDs will be different for a given request.

For instance. While debugging, perhaps you could add the following to your Global.asax.cs:

protected void Application_BeginRequest(Object sender, EventArgs e) { 
      Debug.WriteLine("BeginRequest_" + Thread.CurrentThread.ManagedThreadId.ToString()); 
   }

Open up the debug output window (From Visual Studio: View >> Output, then select "Debug" from the "show output from" dropdown).

While debugging, hit a page where you have seen the long time. Then view the output log - if you see multiple id's then you might be suffering from this.

This is why you might see the delay sometimes but not other times, the application code might be using session a little differently or session or IO operations might be higher or lower from page to page.

If this is the case some things you can do to help speed things up depending on how session is used on the site or each given page.

For pages that do not modify session:

   <% @Page EnableSessionState="ReadOnly" %>

For pages that do not use session state:

<% @Page EnableSessionState="False" %>

If the app does not use session (web.config):

<configuration>
    <system.web>
      <sessionState mode="Off" />
    </system.web>
</configuration>

So let's take the following example:

User loads a page, then decides to go to another page before the first request is done loading ASP.NET will force a session lock causing the new page request load to wait until the first page request finishes. With ASP.NET MVC each action locks the user session for synchronization; causing the same issue.

All of the time it took for the lock to be release will be reported via new relic, not to mention the ones where the user abandoned the session and the thread coming back is looking for a user who no longer exists.

Incidentally the UpdatePanel control causes the same behavior -

http://msdn.microsoft.com/en-us/magazine/cc163413.aspx

What can be done:

This locking problem is one of the reasons Microsoft has the SessionStateUtility class -

http://msdn.microsoft.com/en-us/library/system.web.sessionstate.sessionstateutility.aspx

So that you can override the default behavior if you face this problem as seen here in this Redis implementation:https://github.com/angieslist/AL-Redis

There are many options to the default state provider used by .net based websites. But know generally this transaction time indicates that threads are being locked and waiting on requests to the server to be completed.