Profiling a .NET Web Application
Profiling a .NET Web Application
There are several tools readily available to help you monitor and identify performance problems which occur on the Web tier. The profiling tasks discussed in this section include analyzing IIS log files, using the new tracing feature in ASP.NET, viewing performance data with the infamous System Monitor (which you should be very familiar with by now).
IIS Log Files
IIS log files serve many purposes, including analyzing user behavior or traffic patterns, monitoring activity for security exploits, and aiding in troubleshooting or identifying problems with your Web applications. The purpose of the following IIS log file discussion is to first give you a quick overview and then to demonstrate how to quickly identify performance problems at a high level (the page level) on the Web tier. After you have identified the poorly performing pages within your Web application, you can drill deeper to identify the specific code that is causing the problem and fix it. Let us begin by becoming more familiar with the log files generated by IIS in response to client activity.
Log File Formats
There are various logging modules and formats available with IIS. With the exception of the ODBC logging module, which is written to a database, all of the other log files are ASCII text files. The NCSA Common Log File Format and the Microsoft IIS Log Format are both fixed ASCII formats that are not customizable. We always use the W3C Extended Log File Format for our testing efforts because you can customize it by selecting the fields you want to monitor. From an administrative point of view this is very useful because you log less data, you can conserve more available disk space and keep your log files more readable without sacrificing functionality. All of the ASCII text-based modules discussed above can be set to create new logs when the file size reaches a certain threshold or timeframe (hourly, daily, weekly, monthly). We are not going into great detail about every available log file format in IIS, but we do discuss more information relating to the W3C Extended Log File Format because we use it for identifying problems in Web applications that we encounter.
By default the W3C Extended Log File Format uses Greenwich Mean Time (GMT) for times listed by each request, where all of the other formats use the local time. Keep in mind that the times listed in the log files are generated by the server after processing a request but do not reflect network travel time to the client or client processing time.
TIP
If you are building a test script or debugging your Web application, we recommend selecting every field. Otherwise, select only the relevant fields required to profile your Web application. This will conserve disk space and make parsing or navigating around the log file much quicker and easier.
Below is a sample from one of our log files in the W3C Extended Log File Format. It is worth mentioning that we did not select every available field to be logged, but only the relevant fields for this Web application.
#Software: Microsoft Internet Information Services 5.0 #Version: 1.0 #Date: 2002-05-24 17:25:01 #Fields: date time c-ip cs-method cs-uri-stem cs-uri-query sc- status sc-bytes cs-bytes time-taken 2002-05-24 17:25:01 181.39.207.242 GET /storevbvs/default.aspx - 200 12893 373 2516
The first four lines of a properly formatted W3C Extended log, which begin with a pound sign (#), contain directives or header information such as the version of the log file format, the date and time the file was created, and field identifiers for various information which is logged for each entry. The field identifiers are prefixed in Table 6-2.
Prefix | Meaning |
s- | Server actions |
c- | Client actions |
cs- | Client-to-server actions |
sc- | Server-to-client actions |
Table 6-3 contains a complete list of available properties, definitions, and reference information for each field in the W3C Extended Log File Format.
Field | Appears As | Description |
Date | Date | The date on which the activity occurred. |
Time | Time | The time the activity occurred. |
Client IP Address | c-ip | The IP address of the client that accessed your server. |
User Name | c-username | The name of the authenticated user who accessed your server. This does not include anonymous users, who are represented by a hyphen. |
Service Name and Instance Number | s-sitename | The Internet service and instance number that was running on the client computer. |
Server Name | s-computername | The name of the server on which the log entry was generated. |
Server IP | s-ip | The IP address of the server on which the log entry was generated. |
Method | cs-method | The action the client was trying to perform (for example, a GET method). |
URI Stem | cs-uri-stem | The resource accessed; for example, Default.htm. |
URI Query | cs-uri-query | The query, if any, the client was trying to perform. |
Http Status | sc-status | The status of the action, in HTTP terms. |
Win32 Status | sc-win32-status | The status of the action, in terms used by Windows. |
Bytes Sent | sc-bytes | The number of bytes sent by the server. |
Bytes Received | cs-bytes | The number of bytes received by the server. |
Server Port | s-port | The port number the client is connected to. |
Time Taken | time-taken | The length of time the action took. |
Protocol Version | cs-protocol | The protocol (HTTP, FTP) version used by the client. For HTTP this will be either HTTP 1.0 or HTTP 1.1. |
User Agent | cs(User-Agent) | The browser used on the client. |
Cookie | cs(Cookie) | The content of the cookie sent or received, if any. |
Referrer | cs(Referer) | The previous site visited by the user. This site provided a link to the current site. |
Logging is enabled within IIS by default and can be disabled at the site, directory, or file level by right-clicking the element and clearing the Log Visits checkbox in the IIS MMC snap-in Properties dialog box, as shown in Figure 6-1.
Figure 6-1. Clearing the Log Visits checkbox
Disabling logging on certain directories that contain static or rarely changing files is another useful method of reducing your Web server log file size and saving valuable disk space. For example just by browsing the IBuySpy Web application home page http://localhost/storevbvs/Default.aspx, you write 16 different entries in the IIS log file for that one request. Fourteen images, one style sheet, and the actual Default.aspx page are referenced in the code. Keep in mind that as far as the user is concerned, it is only one URL request, even though it s several HTTP requests to the Web server (one request for Default.aspx, one for the style sheet, and 14 for the images). You can imagine how large the log file can grow and how much disk space can be consumed from a stress test script that requests multiple pages using several browser connections for an extended period of time.
There are several ways to verify how many items are referenced by a page and the size of each file. One such method useful in checking a single page is to first clear your browser cache and then request the page from your browser. You should see all of the different file elements referenced from the page from that one request. Add up the total number of file elements and their file size by viewing the file properties. This is a tedious method when you have many files to investigate. An alternative method that makes more sense to use when you have several files is to use a log parser and view the results in a report format. There are several commercial log parsers available today.
Identifying Problem Pages from a Log File
Now that we have presented some background information on what to look for in the log file let s look at a somewhat real-world example of how to use the IIS log file to quickly identify errors occurring on the Web tier. The next four steps are necessary for us to demonstrate this example.
The code in the IBuySpy sample site is very efficient, so we must first introduce a problem into the code of the ProductList.aspx page to simulate a page delay. We mentioned above that this is a somewhat real-world example because the code causes similar results on many different machines. If we tried to create a demo using code that performs poorly implemented string concatenation or some looping logic that returns many rows from a database, the performance and ASPX execution time from the ProductList.aspx page would vary depending on different hardware configurations. On the ProductList.aspx page, comment out line four as shown below.
<%'@ OutputCache Duration="6000" VaryByParam="CategoryID" %>
Then insert the code below between the <% to %> on line five of the ProductList.aspx page.
<% '///////////////////////////////////////////////////////////// ' TODO: -Comment out line 4 on ProductList.aspx. This will ' -disable the OutputCache so we can introduce a delay. System.Threading.Thread.Sleep(7000) '7 second delay '///////////////////////////////////////////////////////////// %>
Next, we disabled logging on the IBuySpy.css file, the Images subdirectory, and the ProductImages subdirectory in order to focus on tuning the code, which occurs on the ASPX file type.
Verify that you have installed the IBuySpy sample site correctly. Then, within IIS, verify that you have selected W3C Extended Log File Format and selected the following fields: date, time, c-ip, cs-method, cs-uri-stem, cs-uri-query, sc-status, sc-bytes, cs-bytes, time-taken.
Finally, we ran the Browse test script using Microsoft ACT for one iteration. The Browse test script is included on this book s companion CD and is discussed in more detail in Chapter 3. This is not really considered a stress test but more of an automated walkthrough of our user scenario because we only ran through one iteration with one browser connection.
NOTE
It is still important to optimize or reduce the size of your images and stylesheets to ensure that this does not become the bottleneck on your Web application.
The results of the script playback from the IIS log file are as follows:
#Software: Microsoft Internet Information Services 5.0 #Version: 1.0 #Date: 2002-05-30 18:36:11 #Fields: date time c-ip cs-method cs-uri-stem cs-uri-query sc-status sc- bytes cs-bytes time-taken 2002-05-30 18:36:11 181.39.207.242 GET /storevbvs/Default.aspx - 200 0 346 15 2002-05-30 18:36:18 181.39.207.242 GET /StoreVBVS/ productslist.aspx CategoryID=20&selection=2 200 0 377 7016 2002-05-30 18:36:18 181.39.207.242 GET /storevbvs/ Default.aspx test=count 200 0 357 16
Note that there are three requests in the above log. The first thing you should look for is to verify that the requests were successful and there were no errors generated. This is accomplished by looking at the field labeled sc-status, also known as the status code. Table 6-4 below is a useful table to reference HTTP status codes.
Status | Description |
2xx | Success. |
200 | OK: The request has succeeded. |
201 | Created: The request has been fulfilled and resulted in a new resource being created. |
202 | Accepted: The request has been accepted for processing, but the processing has not been completed. |
203 | Non-authoritative Information. |
204 | No Content: No response-request received but no information to send back. |
3xx | Redirection. |
301 | Moved: The data requested has a new location and the change is permanent. |
302 | Found: The data requested has a different URL temporarily. |
303 | Method: Under discussion, a suggestion for the client to try another location. |
304 | Not Modified: The document has not been modified as expected. |
4xx | Error seems to be in the client |
400 | Bad Request: Syntax problem in the request or it could not be satisfied. |
401 | Unauthorized The client is not authorized to access data. |
402 | Payment Required: Indicates a charging scheme is in effect. |
403 | Forbidden: Access not required even with authorization. |
404 | Not Found: Server could not find the given resource. |
5xx | Error seems to be in the server. |
500 | Internal Error: The server could not fulfill the request because of an unexpected condition. |
501 | Not Implemented: The server does not support the facility requested. |
502 | Server Overloaded: High load (or servicing) in progress. |
503 | Gateway Timeout: Server waited for another service that did not complete in time. |
All three of the log entries are GET requests (indicated by the method) and they appear to be successful with 200 status code. Also, there appears to be very little data transferred (indicated by the Bytes Sent and Received fields). The ASPX execution time or the Time Taken field for the Default.aspx page was quick, but the ProductList.aspx took over seven seconds (7016 milliseconds, to be exact). Voil , we have identified a problem. The IIS logs are very useful in helping you to identify pages that are executing slowly, transferring a lot of data and identifying errors in your Web application. Now that we have successfully identified a problem at the page level, we will discuss a new feature available in ASP.NET that will help us to trace the problem down to the line of code causing the delay.
Tracing Problems to the Code Level
Tracing is a useful new feature in ASP.NET for debugging or profiling problems which occur at the application, page, and code level of a Web application. You can print statements during code execution to help identify exactly what is happening at a certain point within your code. With traditional ASP pages, debugging or troubleshooting code is accomplished by inserting text or logic with multiple Response.Write statements at different points within the code as placeholders. To help you fully appreciate the new tracing feature in ASP.NET, we offer a brief discussion of our method to isolating slowly executing code within traditional ASP pages.
Tracing in Traditional ASP Pages
After the files with high execution times are identified from the IIS logs, we typically add several timers throughout the page to pinpoint the slowly executing code. When the page is requested the timers are written to a text file using the local file system of the Web server. Finally, you simply open the text file to view the timer information that was written between each block of code separated with a timer. Below is an example written in VBScript to illustrate this point.
<% Dim t1, t2 'Timer 1 start timer for section 1 t1=Timer %> INSERT CODE BLOCK HERE <% 'Timer 2 start timer for section 1 t2=Timer 'The following code can be placed at the end of the ASP file. Dim fso, filename, fileref filename = "C:\temp\" + cstr(Timer) + ".txt" 'A new file is created each time the page is executed. SET fso = createobject("Scripting.FileSystemObject") SET fileref = fso.createtextfile(filename ) 'Write timer values to the file time is in milliseconds. fileref.writeline("1," + cstr(t1) + "," + cstr(t2) + "," + cstr(t2-t1)) 'Close the file. fileref.close %> Another method for finding slowly executing code within traditional ASP pages is to first make a note of how long it takes the page to execute without modifying the code. Then place the Response.End method at different places within your code and request the page again noting the execution time. The Response.End method stops the execution of the code so you can compare the time against the time taken from the original request. This method often takes several tries to identify the culprit and might end up generating errors, because you are not executing the code in its entirety.
Tracing in ASP.NET
Tracing in ASP.NET can be performed at either the page or application level. Page-level tracing is implemented by adding Trace= True to the @ Page directive at the top of an ASPX file. The complete syntax is as follows:
<%@ Page Trace="True"%>
This will append an HTML table to the browser once the original content has rendered. The HTML table will contain detailed information on the request itself: timing information, server control tree (with rendering viewstate size), header, cookies, querystring along with form parameters, server variables, and of course, the ability to add custom messages. The syntax to add custom tracking information is Trace.Write() or Trace.Warn(). Both methods create the same output but Trace.Warn() writes the output in red text.
TIP
We want to caution you about only enabling tracing when you need to debug your Web application. When trace was enabled on the ProductList.aspx page, the server-to-client bytes transferred for this page changed from 13628 bytes to 32695 bytes according to the IIS logs. This is nearly three times the amount of data in the original request and this can easily skew a stress test.
Enabling tracing at the application level is accomplished by adding or modifying the following statements to the Web.config file.
<configuration> <system.Web> <trace enabled="true" requestlimit="15" pageOutput="true" traceMode="SortByTime" localOnly="true"/> </system.Web> </configuration>
After trace is enabled in the Web.config file, you can view the results of various requests by browsing to a special HttpHandler (Trace.axd) to view the output. The requestLimit parameter will control the number of requests to log for which trace information will be collected. You should also be aware that page-level tracing will override application-level tracing.
Identifying Problem Code in ASPX Pages
Let s take the above example, in which we used the IIS log file to identify a slow executing page, a step further and use the new Trace method discussed above to isolate the code that is causing a delay in our ProductList.aspx page.
Make sure you enabled tracing at the application level by adding or modify the following syntax to the Web.config file located in the IBuySpy Web application root directory.
<configuration> <system.Web> <trace enabled="true" requestlimit="15" pageOutput="true" traceMode="SortByTime" localOnly="true"/> </system.Web> </configuration>
Modify the following code block, which introduces the page delay by adding both statements beginning with Trace.Warn. These statements will write our custom messages around the suspected problematic code.
<% '///////////////////////////////////////////////////////////// ' TODO: -Comment out line # 4 on ProductList.aspx. This will ' -disable the OutputCache so we can introduce a delay. Trace.Warn("Find Delay", "Timer 1: Begin") System.Threading.Thread.Sleep(7000) '7 second delay Trace.Warn("Find Delay", "Timer 1: End") '///////////////////////////////////////////////////////////// %>Run the same Browse test script discussed above using Microsoft ACT for one iteration. This will simulate someone walking through our user scenario.
Finally, on the Web server that contains the IBuySpy sample site, type in the following URL from within your browser: http://localhost/StoreVBVS/trace.axd. The three requests that our script made should be displayed as in Figure 6-2 below.
Figure 6-2. Browse test script results
You should notice similar information displayed in the HTTP Handler (Trace.axd) compared to what we saw previously in the IIS log file. We already identified the ProductList.aspx page as the problematic page because it is taking more than seven seconds to load. Now click the View Details hyperlink for the ProductList.aspx page.
Because we used Trace.Warn the code we added should immediately stand out when you look at it online because the syntax is in red text. In Figure 6-3 below you can identify the code we added under the Trace Information heading and the Find Delay Category. From the Timer 1: Begin message to the Timer 1: End, it took around seven seconds to execute the code between the two statements we added. Voil ! Once again we successfully pinpointed the problem causing the delay. Now, you can verify that this is the problem by simply commenting out the suspected line of code and browsing directly to the ProductList.aspx page. The execution time should be reduced by seven seconds, indicating that indeed this was the problem causing the delay.
Figure 6-3. The problem code is in red text.
System Monitor Counters
System Monitor is an essential tool that can be used for monitoring and analyzing ASP.NET Web application performance. During performance testing, performance data can be analyzed in real time or collected for processing at a later time using System Monitor. Performance data is used in locating possible performance issues such as an inefficient processor, memory usage and any other factors that prohibits the application from performing and utilizing its targeted performance goals on the Web tier.
Performance Counters for IIS
In the following sections, we discuss the IIS counters and ASP.NET performance counters that our team uses in performance testing.
- Internet Information Services Global: File Cache Flushes and File Cache Hits
These counters can be compared to see the ratio of hits to cache clean up. A flush occurs when a file is removed from the cache. These global counters provide some indication of the rate at which objects are being flushed from the cache. Memory is wasted when flushes are occurring too slowly.
- Internet Information Services Global: File Cache Hits %
Displays the ratio of cache hits to total cache requests. This should stay around 80 percent on Web sites that have mostly static content.
- Web Service: Bytes Total/sec
Shows the total number of bytes sent and received by the Web server. A low number indicates IIS is transferring data at a low rate.
- Web Service: Connection Refused
Lower is better. High numbers indicate network adapter card or processor bottlenecks.
- Web Service: Not Found Errors
Shows the number of requests that could not be satisfied by service because the requested document could not be found (HTTP status code 404).
Performance Counters for ASP.NET
There are two sets of performance counters in ASP.NET that can be used in diagnosing and monitoring Web application performance. They reside under ASP.NET, and ASP.NET application performance objects. If you have multiple versions of ASP.NET installed, there may be multiple instances of these counters, each with a version stamp on them. The names without versions will always give you performance data for the highest version installed on the machine.
ASP.NET System Performance Counters
We will not discuss all performance objects and counters in the .NET Framework. All performance counters for ASP.NET information are found on the Microsoft MSDN Web site, and .NET Framework help file. In this chapter, we discuss in some detail the system performance counters, and application performance counters that our team uses in monitoring and analyzing performance of a .NET Web application.
- Application Restarts
Indicates the number of times and how often a Web application has been restarted. An application restart can occur because of changes in configuration, bin assemblies and too many page changes. This value is reset every time to 0 when the IIS host or w3svc restart.
- Requests Queued
The number of requests waiting for service from the queue. When the number of requests queued starts to increment linearly with respect to client load, this is an indication of reaching the limit of concurrent requests processed on the Web server.
- Requests Rejected
Shows the total number of requests not executed due to insufficient server resources to process the requests. This counter represents the number of requests that return a 503 HTTP status code Server is too busy . The value of requests rejected counter should ideally be 0.
- Request Wait Time
The number of milliseconds that the most recent request waited for processing in the queue. The average request should ideally spend very little time waiting to be processed.
ASP.NET Application Performance Counters
ASP.NET supports the application performance counters that can be used to monitor the performance of a single instance of an ASP.NET application. A unique instance appears for these counters, named _Total_, which aggregates counters for all applications on a Web server. The _Total_ instance is always available. The counters will display zero when no applications are present on the server.
- Cache Total Turnover Rate
The number of additions and removals to the total cache per second. Large turnover indicates the cache is not being used efficiently.
- Errors Total
The total number of parser, compilation, or runtime errors that occur during the execution of HTTP requests. A well-functioning Web server should not be generating errors.
- Request Execution Time -
The number of milliseconds taken to execute the last request. The value of this counter should be stable.
- Requests Failed
The total number of requests that have timed out, requests that are unauthorized (HTTP status code 401), requests that are not found (HTTP status code 404 or 414), or that resulted in a server error (HTTP status code 500).
- Requests Not Found
The number of requests that have failed due to resources not being found (HTTP status code 404, 414).
- Requests Not Authorized
The number of requests that have failed due to unauthorized access (HTTP status code 401).
- Requests Timed Out
The number of requests that have timed out.
- Requests/Sec
The number of requests executed per second. Under constant load, the number of requests/sec should remain within a certain range.
The above section covered the IIS counters, and ASP.NET performance counters that our team regularly uses in monitoring and analyzing ASP.NET Web applications.
EAN: N/A
Pages: 67