What happens in BeginProcessRequest()?
Asked Answered
R

4

59

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

Refractor answered 12/6, 2013 at 11:31 Comment(5)
blog.stevensanderson.com/blogfiles/2007/ASPNET-MVC-Pipeline/…Saar
@Ravi BeginRequest() isn't on there! :(Refractor
Are you using any async handlers (IHttpAsyncHandler) ?Besant
My guess is that you are using async controllers. ASP.NET MVC does a lot a things behind the scenes.Gnaw
@Gnaw We use them in a few places - but not on the pages/traces in question...Refractor
M
87

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.

Mezzotint answered 12/6, 2013 at 18:54 Comment(9)
Thanks for such a fantastic answer to this question - I have a strong feeling you are correct, as on the pages in question - It's quite possible we perform a high number of bulky session operations.Refractor
I just tried this, since I've been having a similar issue. When you say "if you see multiple id's then you might be suffering from this" do you mean multiple IDs on the same request? or just a different Id for each request?Joe
A good answer, a lot of which (and more) can be found in this related questionSarilda
We don't use Sesssions, and we've disabled them and we still are seeing this issue.Dominations
I know this is an old question, but im with Doug, same issue, no use of Sessions!Charter
A lot of people chiming in about not using sessions. I'm also one of them. I'm not sure if my wait times are "long", but they are 85% of the entire transaction which seems long to me. I'm wondering, for us non-session people, could ActionFilters, ViewBag, ViewData, or TempData have anything to do with this?Hymnist
I'm also having the same problem on my AzureWebSite. Have tried disabling SessionState entirely. Made no difference.Ostraw
I am having same confusion as @amhed. I am highlighting it again When you say "if you see multiple id's then you might be suffering from this" do you mean multiple IDs on the same request? or just a different Id for each request?Galagalactagogue
The first time I saw this error in 5 years was today, at the same time as also seeing this error for the first time: "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached." This error, combined with @Scalayer's summarizing point that "generally this transaction time indicates that threads are being locked and waiting on requests to the server to be completed", gives the indication that this can also happen when a database connection pool maximum is reached.Idioblast
A
6

If you want to enable a certain controller to process requests in parallel from a single user, you can use an attribute named SessionState that was introduced in MVC since version 3. It’s not necessary to use a session-less controller in order to achieve parallelism, the Ready-only option of the SessionStateBehavior will let you pass security checks you may have implemented based on Session data.

[SessionState(System.Web.SessionState.SessionStateBehavior.ReadOnly)]
[OutputCache(NoStore = true, Duration = 0, VaryByParam = "*")]
public class ParallelController : Controller
{
    ...
}

I also had delays in System.Web.Mvc.MvcHandler.BeginProcessRequest(), when try to do a few long running actions and I saw it in NewRelic. This attributes have solved problem and gave ability to handle actions parallel for this controller.

Alberik answered 20/3, 2014 at 17:42 Comment(0)
S
2

I encountered this same problem in an app that had very minimal use of sessions. After taking the accepted answer into account, and even temporarily removing SessionState completely for diagnostic purposes, I still had significant issues with performance in this 'Method'

Based on todd_saylor's comment in this thread, I did a lot of research on my own site and found that BeginProcessRequest can be serve as New Relic's catch-all for miscellaneous performance losses that appear in different code areas. I was able to significantly reduce the time in this area, by profiling code on my local machine using Red Gate's ANTs Performance Profiler.

My local profiling revealed a few things:

  1. I was using Ninject as my DI container, which caused performance loss in its Object resolution. I replaced it with SimpleInjector and increased performance by an order of magnitude.
  2. I found that somewhere between AutoMapper's IQueryable Extensions Project().To<>() and the Linq's Sql Server provider, that the Dynamic Compiling and JITing of projections was responsible for 50% of my request time. Replacing that with CompiledQuerys made another significant dent.

Hope this helps someone else!

Skysail answered 3/4, 2015 at 19:26 Comment(0)
O
0

to anyone reading this experiencing IIS high CPU usage that is unexplained, take a look at this thread from NewRelic support forum I opened.

I have been dealing with this issue for over a week, until I realized it was their agent that was the root cause of the problem.

.NET agent causing high CPU usage on IIS

so first thing I suggest you try is removing the .NET agent and see if there's any change, before you dive into more complex experiments.

I post this answer on this particular question since I got here first while working on the issue, and thread agility set me on a long course that was not correct...(although very interesting by itself).

Outbreed answered 17/9, 2014 at 6:29 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.