I have written an article here that explains how to install and configure Failed Request Tracing. Please use that for reference.
In this lab you will:
If you have not completed the previous labs, specifically Lab 2, then you need to download and configure the CSharpGuitarBugs website from here. NOTE: Failed Request Tracing are particularly good when troubleshooting general authentication and exceptions happening on an IIS server. For slow ASP.NET Webforms applications there are a lot of benefits for using FREB. However, for troubleshooting slow ASP.NET MVC web sites, see the bottom of the this lab for an example of tracing a slow request using PerfView. Basically, using FREB to trace a slow ASP.NET MVC request is not optimal because of different pipeline used for executing the MVC request, see the Figure 20 at the end of this article for an visual representation of the different request pipelines (ASP.NET MVC vs. ASP.NET pipeline). Similar for a PHP request, you would likely see that the request is handed over to the PHP_CGI.exe, but you would not see where in the PHP file the slowness was happening, for could use XDEBUG for that scenario, but it is not covered in this lab.
The article I wrote previously here is valid from IIS 7 until now.
The first step is to install the role via the Server Manager. As shown in Figure 1, open Server Manager and click on Add roles and features.
Click the Next button (~3 times), accepting the defaults, until you reach the windows illustrated via Figure 2. Scroll down and expand Web Server (IIS) -> Web Server -> Health and Diagnostics and select Tracing.
Click the Next button (~2 times) until you see the window shown in Figure 3 and click install.
Open the IIS manager console and notice the new feature is installed, as shown in Figure 4.
Now that Failed Request Tracing is installed, let’s configure it. In this scenario, there is a page that takes too long to load and you want to find out why.
Start by double-clicking on the Failed Request Tracing Rules feature from the feature pane, as seen in Figure 4. This opens the page shown in Figure 5, click the Add link on the action pane.
After clicking the Add link from the action pane, a configuration wizard starts that captures the required information for a rule. The first window, Figure 6, requests the type of page you want to monitor. For this example, leave the default and click the next button.
Clicking the Next button, open the window shown in Figure 7. It is possible to capture a trace based on Status code, time-taken or severity. For this lab, capture a trace when the request takes 6 or more seconds to complete.
Click the next button, which displays that shown in Figure 8. This window lets you select the:
Have a read of this article here that explains how to troubleshoot a request that uses Url Rewrite. It illustrates selecting only a specific Provider and Area so that you get only the information you are after.
Complete the configuration of the rule by pressing the Finish button. Figure 9 shows that the rule is now configured, but note, that although the rule is configured, it is no enabled.
To enable the Failed Request Tracing rule, click on the web site where you want to capture the trace and click on the Failed Request Tracing… link in the action pane, as shown in Figure 10.
Notice that the tracing is not enabled. Click on the Enable checkbox and then OK, to enable the tracing. Notice that the location in which the logs are written and the maximum number files are configurable. By default the maximum number of files is set to 50. This means that the 51st trace will overwrite the 1st so make sure to set that value appropriately.
Browse to the CSharpGuitarBugs website you created in Lab 1 here, as shown in Figure 11 and click on the Full Catalog – ASPX link.
This requests takes some time, over 10 seconds in this case and a Failed Request Trace log is created, as shown in Figure 12.
Right-click on the fr000*.xml file -> Open with -> Internet Explorer to view the trace, as shown in Figure 13.
Notice that the Time Taken is greater that 10 seconds as per the rule and that the request was made to an ASPX file, which is an ASP.NET Webform page. Failed Request Tracing is best for troubleshooting ASP.NET Webforms performance issues. Click on Compact View and scroll down, keeping an eye on the Time column. Points to look for:
Also note as shown in Figure 14 that some of the ASP.NET Webform events are shown in brackets. For example, the AspNetPagePreInitEnter/Leave in row 132-133 correspond with the Page_PreInit() method, the AspNetPageInitEnter/Leave on row 134/135 which corresponds to the Page_Init() and where the log stops being written on line 136 is the AspNetPageLoadEnter (notice there is no Leave) which corresponds to the Page_Load() method. Therefore, this is the method you would look at to determine why the request is taking more time than expected. Perhaps it contains some nested loops, poorly written SQL queries or a call to an external service which is responding slow. Check the code in that method.
NOTE: Another great use of this tracing is if a user mentions the site was slow sometime last week, or can only mention that the site is slow during given time periods with no specific request identified. You can enable this and let it run in the back ground and then review the logs at the end of each day searching for slow requests logs.
Mentioned at the beginning of this lab, Failed request tracing is a very useful tool for finding performance issues for specific ASP.NET Webform (ASPX) requests. However, due to the differences between the pipeline flow of the ASP.NET MVC application there is a better tool for finding specifically where within the request the slowness is happening. Follow these instructions to capture a trace of a slow performing ASP.NET MVC request using PerfView.
After reviewing the video, I opened the trace in PerfView and see that there are about 11 seconds between the start and the end of the request, as shown in Figure 17.
In a real world example, the analysis of this trace can take a very long time. In any case after making sure the symbols were loaded I looked around for what was happening during that trace. I found that there is a call to the Sleep() method in Controller for FullCatalog(), as shown in Figure 18.
Additionally, in the video is mentioned to select Open CPU stacks from the window shown previously in Figure 17, you can alternatively select Open Thread Stacks, which renders the something similar to Figure 19 that shows AWAIT_TIME and BLOCKED_TIME.
Double click on BLOCKED_TIME and a window similar to Figure 18 is rendered straight to the place where the Sleep() method is called which is the source of the slowness of the request.
I recommend that you capture a trace for any slow request you are troubleshooting just to see and learn how requests are managed on the server side, you can learn a massive amount by looking at these traces. Overtime you would perfect the analysis of the traces and the tool used to capture and analyze them.