Understanding the ASP.NET Lifecycle

RELATED: "HTML5 for the ASP.NET Developer" and "Microsoft ASP.NET: What's This New Web API?"

Having a good understanding of the lifecycle of ASP.NET pages is crucial to troubleshooting issues in ASP.NET applications. Logging can be strategically added to events using the .NET Framework's built-in tracing capabilities. These logs can aid in pinpointing the causes of performance bottlenecks, as well as in gathering usage statistics for your applications. In this article I explain the key steps in the lifecycle of an ASP.NET page. I also show how to easily integrate tracing into these steps, and how to use these logs in conjunction with other tools to troubleshoot performance. This article is written in C# with ASP.NET 1.1 and Visual Studio.NET 2003, but the concepts also apply to VB.NET and ASP.NET 1.0 and 2.0.

I developed the concepts in this article while troubleshooting performance issues in an ASP.NET application deployment. Many things happen behind the scenes when an ASP.NET page is invoked. Eventually, the code in the page is processed and an HTML response is sent back to the client. For a good overview of this process, see Web Forms Page Processing in the .NET Framework documentation (see page processing in the index). But what processing actually takes place? When does authentication take place? When does the view state get parsed and processed? When does a button click event get fired? The answers to these questions are found in the .NET Framework documentation, but not necessarily where you would expect.

Look for lifecycle for server controls in the index for a page titled Control Execution Lifecycle . With the realization that an ASP.NET page is a special type of ASP.NET control, this document explains the lifecycle of a page. Figure 1 lists all the phases of the life of a control, as well as the methods that correspond to each step. Some of the methods also have corresponding events. For example, the Load step corresponds to the OnLoad method and fires the Load event. Visual Studio creates the Page_Load method and hooks it up to the Load event for you when you create a new page. Some of the steps, such as Load View State and Render, do not fire events although they have methods you can override.

Figure 1: The phases of the life of a control, as well as the methods that correspond to each step.

Page processing is just a part of what takes place when a request is handled by ASP.NET. Find about HttpApplication class under HttpApplication class in the index of the .NET Framework documentation. This document contains a table that lists events and the order in which they are fired. You can write code for these events and place it in the Global.asax file. Note that a page is a type of HTTP handler, so the part of the list in Figure 1 that refers to the handler is executed is essentially where all the page s lifecycle steps take place. Combining the events and methods from the HttpApplication class with the Page class yields a complete picture of what happens when a request is handled.

How can you take advantage of this information? Using the .NET Framework s tracing classes, we can simply add a line of code that writes to a file the date, time, and other basic information whenever any of these steps takes place. If performance is not as good as you expect, then you can use this information to see exactly where the performance hit takes place. Finding a one-second gap between AuthenticateRequest and AuthorizeRequest leads to a different conclusion than finding a one-second gap from the start of LoadViewState to the start of LoadPostData. The entire time from BeginRequest to EndRequest is how long ASP.NET spends processing the user s request; if this is five seconds, is the time being eaten up in code you write in the Page_Load event, or somewhere else?

If you are not familiar with the System.Diagnostics tracing classes I suggest you read up on them. Adding some instructions to the configuration section of the web.config file is a good place to start; see Listing One for an example that defines a trace switch as well as a text file to output trace statements to. Be sure that the folder where the log file should go ( C:Logs in Listing One) exists and that the user profile that runs ASP.NET (usually ASPNET) has rights to this folder; otherwise, you may see a Configuration Error when you start your application.

Some of the lifecycle steps are events, some are methods, and in some cases both are provided. For the HttpApplication object we can write events for all the steps, but the methods behind the scenes are not exposed. For the Page class, on the other hand, all the steps have analogous methods, but they do not all have events. Where an event is provided, we can write code to be executed when the event fires. For the methods, we need to override the method in order to add tracing; we also case the base method from our override so that everything continues to work correctly.

For example, if we want to add a line of code that will write the date and time to a log file using the trace classes whenever the page s Load step takes place, then we can add code to the Page_Load event. We can also override the OnLoad method, making sure we call base.OnLoad from our OnLoad method.

Tracing each step enables us to build a timeline of which steps took place when. Then we can determine how long each step took; this will expose which steps, if any, are suffering from performance issues. For example, if the Render step takes two seconds, then you ll know that the problem is there and not in the Load event. You are now in a much better position to find the source of the problem than if all you knew was that the whole request is taking about two seconds.

You ll need to log very specific information in order to properly reconstruct the timeline for each request. Because an ASP.NET application typically has multiple users, and thus concurrent requests, you need a way to match entries in the log file to a particular request (because the steps from different requests will be interspersed). Each concurrent request runs on a different thread, but all the steps of a single request run on the same thread. This makes the thread id very useful. Other information, such as the username, the URL of the requested page, and the session id are also useful. Listing Two contains an example of a trace statement that logs this information.

Looking at Listing Two in detail you can see that I added a trace statement to the beginning and to the end of the Page_Load event, which is created by default in Visual Studio when a new ASP.NET page is created. Tracing at the beginning and end of Page_Load allows me to determine how much time is spent in the code that I wrote in that event. Notice that I specified System.Diagnostics.Trace instead of simply Trace . This is necessary even if I have referenced System.Diagnostics with a using statement because the Page class has a property named Trace that is used for ASP.NET tracing. (ASP.NET tracing is another kind of tracing that is outside of the scope of this article. To learn more see ASP.NET tracing in the .NET Framework documentation. The tracing I am using here is referred to as System.Diagnostics tracing.)

Notice in Listing Two that I use the WriteLineIf method. It takes a boolean as the first parameter and only writes the line if that value is true. By using the trace switch that was created in Listing One, tracing can be easily turned on and off and different levels of logging can be applied simply by changing the web.config file. The levels and their corresponding values are nothing (0), Error (1), Warning (2), Info (3), and Verbose (4). I find it odd that you can t specify the enumeration by name in the web.config file, but maybe Microsoft will fix that in a future release. I set the value to 4 in Listing One, so all levels would be output. If you set the value to, say, 2, then only the Error and Warning levels would be output. You can create multiple switches to suit your needs.

In the call to WriteLineIf I delimit with tabs all the data that I output in order to make it easier to parse the data later. I output the current date/time, an arbitrary category (I chose page ), the name of the Web form s class (I get the name using reflection), the name of the step I am in, whether it is the start or end of the step, the user making the request, the id of the thread I am in, the requested URL (it may contain more useful information than just the name of the Web form s class), and the current session id (which may help draw together separate requests from the same user s session).

This may seem like a hefty chunk of code to put at the beginning and end of each event especially when you recall all the events from Figure 1 and consider how many Web forms you may have in your application. Fortunately, there is a more efficient solution than adding this code to all your forms. All pages that you create using ASP.NET inherit from System.Web.UI.Page by default. We can create a custom class, let s call it TracingPage, that inherits from the default Page class. Then, we have our pages inherit from our custom class instead of the default. In TracingPage, all the methods that correspond to each step can be overloaded and the logging can be performed there. Then, any page in your application can be made to do the tracing simply by having it inherit from TracingPage. Note that I prefer to overload the methods instead of adding event handlers; not all the page steps have events, but we can take care of all the steps by overloading their respective methods.

Take a look at my TracingPage class in Listing Three. I created a method called DoStandardTrace that logs all the information we need. I made it as generic as possible it even retrieves the name of the step that is being logged (such as OnInit) from the stack frame so that it doesn t need to be passed in (it assumes that it is being called directly by the method whose name it should log). I then override each of the methods in the Page class that correspond to a step that should be logged. In each method, I log the start of the method, call the base class implementation of the method, and then log the end of the method. When the base class implementation is called is when some of the processing actually occurs. For example, when base.OnLoad is called, your Page_Load event will get fired.

In the sample code accompanying this article (see end of article for download details), run WebForm2, which inherits from the TracingPage class. (Note: the sample assumes you have SQL Server and the pubs database installed locally.) After the page loads, click the button once to cause a post back. Your log file should now look similar to Listing Four. If you received a configuration error, be sure that the output folder for the log file exists. Notice that the initial page request did not execute the LoadViewState and the RaisePostBackEvent methods, but that the request caused by clicking the button did. Also note how the output looks. The request, for example, is /Lifecycle/WebForm2.aspx and it will also contain any query parameters that may have been included. The thread id is an integer; on your workstation it may often be the same value, but in a multi-user environment you should see the number change often as different threads from the pool service different requests. The session id, an alphanumeric string, will remain the same for all requests coming from the same browser session. Finally, notice that the user name was blank in my example as I did not turn on any type of authentication. If you are using Windows Authentication, the user name would be in the familiar domainuser format. Logging this sort of information can help you track down problems that users report. The session id and user name help you follow the workflow of requests performed by a given user.

The TracingPage class takes care of logging what happened during page processing. Now it s time to add some tracing to the global.asax file in order to trace what is happening at the application level. Open the global.asax file (Visual Studio 2003 adds it for you by default) and look at the source code. You ll see that events like Application_BeginRequest already exist, which makes it easy to add logging to them. The only choice you have here is to handle events you can t override methods like we did in TracingPage. Some of the events have been added. If you look at global.asax in design view, then you can open the properties window and select any event you want to capture; adding events this way will create new events called Global_[EventName]. However, you can also add events with the correct Application_[EventName], like the defaults in the file, and they will be picked up automatically.

I ve added logging for all the application events in the downloadable code for this article. In Listing Five you can see that the code is very similar to that in TracingPage. There is a generic routine to log the information that we want to capture, and then a call to that routine from each of the events. For certain events, however, some of the information will not be available, and attempting to access it will throw an exception. For example, in the Application_Start event, you cannot access the Request object, so I pass flags to the DoStandardTrace method telling it whether or not to try to log the request and the session (the two trouble-makers).

With tracing now in place for both page and global events, I encourage you to experiment with some pages in your existing ASP.NET applications and then examine the logs in order to get a feel for what kind of data is produced. You can customize the logging to suite your needs. For example, you could create multiple trace switches in order to change the granularity of what you log. You could create switches for each step, then configure which steps are logged by changing the switch values in web.config

You might also want to add logging to other important areas of your application. For example, if you have a data access wrapper, you could log right before and right after every stored procedure call, enabling you to analyze database performance in your ASP.NET application. Anywhere that your application performs operations where you may want to monitor performance are potential places to log Web services, remoting, third-party APIs, etc.

If you are collecting quite a bit of data, as you are likely to do in a real-world multi-user application, then you ll also need a way to process this data so that it is usable. Application_BeginRequest and Application_EndRequest give you the big picture of how long request processing can take. You could write macros in Excel to import the log file and process the data; once you find a BeginRequest you ll want to find the matching EndRequest for the same thread id. You might import the data into SQL Server in order to process it. You ll want to match up the Start and End log entries from each of the various page steps to calculate how long each step took. Then, match up each of the steps to a request and group all the data by request so that you can walk through the steps of an individual request.

You may run into some nuances when processing the data. Sometimes the Page s OnUnload method is called twice (this appears to be a bug). Also, if you make use of Response.Redirect or Response.End, you might notice that some of the steps you may have been expecting are skipped. Server.Transfer or your own custom HTTP handlers may also call for special processing. Finally, your processing code will need to pull data elements from different steps in order for it to make sense. For example, if you want to summarize data by BeginRequest/EndRequest, you ll need to find the user, requested URL, and session ids from other events that took place after BeginRequest because not all values were known yet.

You can use this information to calculate average response time for each page, etc. Or, for requests that took too long, you can look at each step to see where the issue is. The processed data can be used for usage statistics (which users are using which parts of the application, etc.), for performance statistics (did that new query optimization make a difference), or to follow the steps a user apparently took when running into some elusive bug that was reported.

I recently deployed a mission-critical trading application. Inexplicably, performance degraded considerably after it was in production for a short period of time. I was at a loss as to what the problem could be, but I had to make sure it got resolved quickly. I began by adding some tracing to check database performance. The problem wasn t there, so I added some tracing to the page lifecycle, which also appeared to be processing quickly at least from OnInit to OnUnload. I had to examine everything that might be happening from the split second the user clicked a button in the browser to the second that the new page finished rendering in the browser. In the end, several tools came into play. I used a third-party product called HttpWatch on the user s machine to see if there were any delays on the client before and after the request to the Web server. I enabled detailed logging in IIS and correlated what IIS thought the request processing time was with ASP.NET and HttpWatch.

Lifecycle tracing ended up pointing to a performance hit being taken in the authentication stage, at Application_AuthenticateRequest. I used netcap and netmon to capture all the network traffic on the Web server and client. I found that the delay correlated with the Web server communicating with a domain controller (DC) at a remote location. Apparently it was authenticating the user against the remote DC when it should have been communicating with a DC in the same rack. An active directory configuration issue was identified and resolved. Understanding and logging the complete ASP.NET lifecycle was the key to pinpointing and resolving this issue.

One last note on compatibility with Visual Studio 2005: The concepts presented in this article haven t changed. In fact, there are even more lifecycle steps in ASP.NET 2.0 that you can use for logging. The Page object adds methods such as OnLoadComplete, and the HttpApplication object expands, adding Pre- and Post- events such as PreAuthenticateRequest and PostAuthenticateRequest instead of just AuthenticateRequest. The TracingPage class from this article should get you started. If you are using partial pages (the default), then simply add the Inherits= TracingPage attribute to the @Page directive in the aspx file. Also, the documentation specifically includes instructions for using System.Diagnostics tracing and adding it to the web.config file, as presented here. I had some trouble getting any trace output at all with Beta 1, but I may have missed something. In any case, all indications are that ASP.NET 2.0 will work well with the concepts presented in this article.

The sample code accompanying this article is available for download.

Luther Miller, MCSD (.NET), is a Managing Architect for Sogtagon Corp. in San Francisco, where he manages multiple .NET projects. He spends his free time jogging and hoping that Futurama will go back into production. He can be reached at mailto:[email protected] with questions or comments.

Begin Listing One

 ...                                       ... 

End Listing One

Begin Listing Two

public static TraceSwitch lifecycleSwitch = new TraceSwitch("Lifecycle", "Lifecycle Log");private void Page_Load(object sender, System.EventArgs e){ System.Diagnostics.Trace.WriteLineIf(  lifecycleSwitch.TraceInfo, string.Format(   "{0:yyyy-MM-dd HH:mm:ss.ffff}t{1}t{2}t{3}   t{4}t{5}t{6}t{7}t{8}",   DateTime.Now, "Page", this.GetType().Name,   "Page_Load", "Start",   User.Identity.Name, AppDomain.GetCurrentThreadId(),   Request.Url.PathAndQuery, Session.SessionID )); // Put user code to initialize the page here sqlDataAdapter1.Fill(dataSet1); DataGrid1.DataBind(); System.Diagnostics.Trace.WriteLineIf(  lifecycleSwitch.TraceInfo, string.Format(   "{0:yyyy-MM-dd HH:mm:ss.ffff}t{1}t{2}t{3}   t{4}t{5}t{6}t{7}t{8}",   DateTime.Now, "Page", this.GetType().Name,   "Page_Load", "End",   User.Identity.Name, AppDomain.GetCurrentThreadId(),   Request.Url.PathAndQuery, Session.SessionID ));}

End Listing Two

Begin Listing Three

public class TracingPage : System.Web.UI.Page{ public static System.Diagnostics.TraceSwitch   lifecycleSwitch = new System.Diagnostics.TraceSwitch(   "Lifecycle", "Lifecycle Log"); public const string START_MARKER = "Start"; public const string END_MARKER = "End"; public string currentPage = null; public string currentUser = null; public string currentRequest = null; public int currentThreadId = 0; protected void DoStandardTrace(string marker) {   // Use the Stack Frame to determine which method   // is requesting logging so that we can log   // the method name without passing it in.   System.Diagnostics.StackFrame callingFrame =     new System.Diagnostics.StackTrace().GetFrame(1);   System.Diagnostics.Trace.WriteLineIf(    lifecycleSwitch.TraceInfo,     string.Format(     "{0:yyyy-MM-dd HH:mm:ss.ffff}t{1}t{2}t{3}t{4}       t{5}t{6}t{7}t{8}",     System.DateTime.Now,           // time stamp     "Page",                        // category     currentPage,                   // Web Form class     callingFrame.GetMethod().Name, // step (OnInit, etc.)     marker,                        // start, end, etc     currentUser,                   // user name     currentThreadId,               // current thread id     currentRequest,                // URL requested     Session.SessionID             // session id     )); } override protected void OnInit(System.EventArgs e) {   currentPage = this.GetType().Name;   currentUser = User.Identity.Name;   currentRequest = Request.Url.PathAndQuery;   currentThreadId = System.AppDomain.GetCurrentThreadId();   DoStandardTrace(START_MARKER);   base.OnInit(e);   DoStandardTrace(END_MARKER); } override protected void LoadViewState(object savedState) {   DoStandardTrace(START_MARKER);   base.LoadViewState(savedState);   DoStandardTrace(END_MARKER); } override protected void OnLoad(System.EventArgs e) {   DoStandardTrace(START_MARKER);   base.OnLoad(e);   DoStandardTrace(END_MARKER); } override protected void RaisePostBackEvent(   System.Web.UI.IPostBackEventHandler sourceControl,   string eventArgument) {   DoStandardTrace(START_MARKER);   base.RaisePostBackEvent(sourceControl, eventArgument);   DoStandardTrace(END_MARKER); } override protected void OnPreRender(System.EventArgs e) {   DoStandardTrace(START_MARKER);   base.OnPreRender(e);   DoStandardTrace(END_MARKER); } override protected object SaveViewState() {   DoStandardTrace(START_MARKER);   object returnObject = base.SaveViewState();   DoStandardTrace(END_MARKER);   return returnObject; } override protected void Render(   System.Web.UI.HtmlTextWriter writer) {   DoStandardTrace(START_MARKER);   base.Render(writer);   DoStandardTrace(END_MARKER); } override public void Dispose() {   DoStandardTrace(START_MARKER);   base.Dispose();   DoStandardTrace(END_MARKER); } override protected void OnUnload(System.EventArgs e) {   DoStandardTrace(START_MARKER);   base.OnUnload(e);   DoStandardTrace(END_MARKER); }}//class TracingPage

End Listing Three

Begin Listing Four

2004-07-18 14:58:14.3101 Page WebForm2_aspx OnInit Start 700 /Lifecycle/WebForm2.aspx 4fpvhuyyvt3zpkfyckw3k4v12004-07-18 14:58:14.3201 Page WebForm2_aspx OnInit End 700 /Lifecycle/W ...2004-07-18 14:58:14.3302 Page WebForm2_aspx OnLoad Start 700 /Lifecycle ...2004-07-18 14:58:14.4203 Page WebForm2_aspx OnLoad End 700 /Lifecycle/W ...2004-07-18 14:58:14.4203 Page WebForm2_aspx OnPreRender Start 700 /Life ...2004-07-18 14:58:14.4203 Page WebForm2_aspx OnPreRender End 700 /Lifecy ...2004-07-18 14:58:14.4303 Page WebForm2_aspx SaveViewState Start 700 /Li ...2004-07-18 14:58:14.4303 Page WebForm2_aspx SaveViewState End 700 /Life ...2004-07-18 14:58:14.7107 Page WebForm2_aspx Render Start 700 /Lifecycle ...2004-07-18 14:58:14.7608 Page WebForm2_aspx Render End 700 /Lifecycle/W ...2004-07-18 14:58:14.7608 Page WebForm2_aspx OnUnload Start 700 /Lifecyc ...2004-07-18 14:58:14.7608 Page WebForm2_aspx OnUnload End 700 /Lifecycle ...2004-07-18 14:58:14.7608 Page WebForm2_aspx Dispose Start 700 /Lifecycl ...2004-07-18 14:58:14.7608 Page WebForm2_aspx Dispose End 700 /Lifecycle/ ...2004-07-18 14:58:23.8238 Page WebForm2_aspx OnInit Start 700 /Lifecycle ...2004-07-18 14:58:23.8238 Page WebForm2_aspx OnInit End 700 /Lifecycle/W ...2004-07-18 14:58:23.8438 Page WebForm2_aspx LoadViewState Start 700 /Li ...2004-07-18 14:58:23.8538 Page WebForm2_aspx LoadViewState End 700 /Life ...2004-07-18 14:58:23.8839 Page WebForm2_aspx OnLoad Start 700 /Lifecycle ...2004-07-18 14:58:23.8939 Page WebForm2_aspx OnLoad End 700 /Lifecycle/W ...2004-07-18 14:58:23.9039 Page WebForm2_aspx RaisePostBackEvent Start 70 ...2004-07-18 14:58:23.9139 Page WebForm2_aspx RaisePostBackEvent End 700 ...2004-07-18 14:58:23.9240 Page WebForm2_aspx OnPreRender Start 700 /Life ...2004-07-18 14:58:23.9340 Page WebForm2_aspx OnPreRender End 700 /Lifecy ...2004-07-18 14:58:23.9340 Page WebForm2_aspx SaveViewState Start 700 /Li ...2004-07-18 14:58:23.9340 Page WebForm2_aspx SaveViewState End 700 /Life ...2004-07-18 14:58:23.9440 Page WebForm2_aspx Render Start 700 /Lifecycle ...2004-07-18 14:58:23.9540 Page WebForm2_aspx Render End 700 /Lifecycle/W ...2004-07-18 14:58:23.9540 Page WebForm2_aspx OnUnload Start 700 /Lifecyc ...2004-07-18 14:58:23.9540 Page WebForm2_aspx OnUnload End 700 /Lifecycle ...2004-07-18 14:58:23.9540 Page WebForm2_aspx Dispose Start 700 /Lifecycl ...2004-07-18 14:58:23.9640 Page WebForm2_aspx Dispose End 700 /Lifecycle/ ... 

End Listing Four

Begin Listing Five

...public static System.Diagnostics.TraceSwitch lifecycleSwitch = new System.Diagnostics.TraceSwitch(   "Lifecycle", "Lifecycle Log");protected void DoStandardTrace(bool request, bool session){// Use the Stack Frame to determine which method is// requesting logging so that we can log the method// name without passing it in.System.Diagnostics.StackFrame callingFrame = new System.Diagnostics.StackTrace().GetFrame(1);System.Diagnostics.Trace.WriteLineIf( lifecycleSwitch.TraceInfo, string.Format( "{0:yyyy-MM-dd HH:mm:ss.ffff}t{1}t{2}t{3}t{4}t{5} t{6}t{7}t{8}", System.DateTime.Now,                                    // time stamp "Global",                                               // category this.GetType().Name,                                    // Web Form class callingFrame.GetMethod().Name,                          // step (OnInit, etc.) "Event",                                                // start, end, etc  (request && (User != null)) ? User.Identity.Name : null,   // user name System.AppDomain.GetCurrentThreadId(),                  // current thread id request ? Request.Url.PathAndQuery : null,              // URL requested session ? Session.SessionID : null                     // session id ));}protected void Application_Start( Object sender, EventArgs e){ DoStandardTrace(false, false);}protected void Session_Start(Object sender, EventArgs e){ DoStandardTrace(false, true);}//// REQUEST EVENTS//protected void Application_BeginRequest( Object sender, EventArgs e){ DoStandardTrace(true, false);}protected void Application_AuthenticateRequest( Object sender, EventArgs e){ DoStandardTrace(true, false);}protected void Application_AuthorizeRequest( Object sender, EventArgs e){ DoStandardTrace(true, false);}...

End Listing Five