ASP.NET Perfecto - Taking a quick peek at the performance of your ASP.NET app

Introduction

Historically, using ETW is not very friendly. Existent tools are hard-to-use and the data generated is raw and mostly unprocessed. You can today generate ASP.NET traces using logman.exe and then use tracerpt.exe to generate a CSV file. This data is hard to look at it. Another option is to use FREB to generate traces. That log contains useful information, but sometimes is too much, especially if you just want to take a quick peek at a request or two. And ASP.NET events are only listed. The relation between the events is not used.

Currently, here are some issues associated with using ETW to measure ASP.NET performance:

1. Not user friendly.

2. Generates a lot of raw unprocessed data (for instance if generating a CSV file using logman.exe and tracerpt.exe).

3. FREB generates a file per each request. When browsing the log folder, it’s impossible to know which file belongs to which request. There is no summary that shows all requests traced.

4. Both methods just list the ASPNET events. They miss an important point. The information is not only in the fact that the event happened. An important piece of information is the duration between events. FREB shows duration for IIS event, but not for ASP.NET events. For instance, you can’t know how long your Page Load event took.

The tool that we are providing here will allow you to collect ETW traces for ASP.NET requests and look at them in a more friendly view. The tool doesn’t contain any executable. It just harnesses the functionality already in existence in Windows. In this case the data collector sets provided in the “Performance Monitor” (aka perfmon) in Vista or newer versions.

The tool is made out of three XML files. One file contains the data collector set definition (Perfecto.DataCollectorSet.xml). A second file (Reports.Microsoft.ASPNET.xml) contains the schema of the ASP.NET specific data included on ETW traces. A third xml file (Rules.Microsoft.ASPNET.xml) provides rules that will modify and rearrange the data so it’s easier to read and understand. Setup is very simple, just the XMLs and a setup.cmd script.

The tool can be used for purposes others than performance. For instance, you can see what modules are running in the pipeline. Or you can see what request are generating manage code to run.

We are considering adding this tool’s functionality to DebugDiag.

Setup steps:

1. Download and unzip perfecto.zip.

2. Run setup.cmd. This script will:

a) Create a folder at “%programfiles%\perfecto” and copy there the three xml files listed before.

b) Create the data collector set:

logman.exe import "Service\ASPNET Perfecto" -xml Perfecto.DataCollectorSet.xml

c) Open “Performance Monitor” (perfmon).

Running steps:

1. On perfmon, navigate to the "Performance\Data Collector Sets\User Defined\ASPNET Perfecto" node.

2. Click the "Start the Data Collector Set" button on the tool bar.

3. Wait for/or make requests to the server (more than 10 seconds).

4. Click the "Stop the Data Collector Set" button on the tool bar.

5. Click the "View latest report" button on the tool bar or navigate to the last report at "Performance\Reports\User Defined\ASPNET Perfecto".

Perfecto Requirements

1. Only works on Vista or newer Os.

2. Requires IIS tracing: (run dism /online /enable-feature /featurename:IIS-HttpTracing).

3. Only ~140K of disk space is needed for the Xml files at " %programfiles%\perfecto".

Using the data collector set.

1. How to View the Performance Counters Graph: The report has three different views in perfmon data collector sets. You can right-click on the report, select "View", and "Performance Monitor" to see the graphic view of the performance counters collected.

2. How to Send Data by Email: Right-click on the report, select "View", and "Folder". Select the files you want to send, right click and select "Send To\Mail Recipient". You need to have email client properly configured.

3. How to Start/Stop Collection From Batch File:

logman.exe start -n "Service\ASPNET Perfecto"

logman.exe stop -n "Service\ASPNET Perfecto"

Note: The View commands are also available as toolbar buttons.

Sometimes you can see an error like below:

Error Code: 0xc0000bf8
Error Message: At least one of the input binary log files contain fewer than two data samples.

This usually happens when you collected data too fast. The performance counters are set by default to collect every 10 seconds. So a fast start/stop sequence may end without enough counter data being collected. Always allow more than 10 seconds between a start and stop commands. Or otherwise delete the performance counters collector or change the sample interval.

Default sizes of the log files

One problem users usually have with ETW is that they can forget to turn off collection, so the ETL files can grow very big. To avoid this, we made the default in the data controller set to have a circular file: so older events are overwritten when the file grows beyond the default 5MB size. There is also a limit of 1GB for all files. This includes .etl, .blg and the reports XMLs.

These settings can be changed on the perfmon UI if you find they are not good for you:

1. To change maximum size of the log file, right click on the “ASPNET Perfecto” data collector set and chose properties. Select the "Stop Condition" tab.

2. To disable circular file, double click the AspnetTrace collector to open the properties and select the "File" tab.

3. To change the size of all log files, open the data manager in “Reports\User Defined\ASPNET Perfecto”. Right click for properties and change the “Maximum root path size:”.

ETW Performance Effect on Production Servers.

Enabling ETW events for the ASP.NET provider will make a hello world page around 38% slower, without impacting noticeable the memory usage. The effect on a web app such as IBuySpy is lower: around 11%.

Test Name

Metric

Unit

#Procs

Baseline

Result

Diff

Helloworld

Throughput

req/sec

16

40852.00

25338.00

-37.98%

Helloworld

Working Set

bytes

16

85499904.00

88651013.33

-3.69%

IBuySpy

Throughput

req/sec

16

4573.00

4062.33

-11.17%

IBuySpy

Working Set

bytes

16

172097376.00

165901248.00

3.60%

 

Sample report:

Below is a table that shows and excerpt of how the report looks like:

ASP.NET Requests

 

Verb

Path

Query String

Handler Name

Duration (millisecs)

GET

/app/page.aspx

test=1234

ASP.global_asax

7,443.85

Step Name

Elapsed (millisecs)

Duration (millisecs)

Create App Domain

0.00

5,954.18

Request Starts

6,014.74

0.00

Enter App Domain: /LM/W3SVC/1/ROOT/app-1-129151551736866465

6,015.22

0.00

System.Web.Security.WindowsAuthenticationModule

6,084.86

0.07

System.Web.Handlers.ScriptModule

6,085.22

12.52

System.Web.Security.DefaultAuthenticationModule

6,098.33

0.03

System.ServiceModel.Activation.ServiceHttpModule

6,098.50

15.07

System.Web.Security.UrlAuthorizationModule

6,113.88

0.90

System.Web.Security.FileAuthorizationModule

6,114.90

2.31

System.Web.Caching.OutputCacheModule

6,117.44

0.25

System.Web.Routing.UrlRoutingModule

6,117.82

0.27

System.Web.SessionState.SessionStateModule

7,246.15

0.29

System.Web.Profile.ProfileModule

7,246.56

0.05

System.Web.Handlers.ScriptModule

7,246.73

0.06

ASP.NET Execute Handler

Step Name

Page PreInit

Page Init

Page Load

Page PreRender

Page Save Viewstate

Page Render

7,246.95

Elapsed

7,429.90

7,430.11

7,430.37

7,430.92

7,437.30

7,437.45

194.04

Duration

0.05

0.04

0.40

0.03

0.01

1.59

System.Web.SessionState.SessionStateModule

7,441.25

0.13

System.Web.Caching.OutputCacheModule

7,442.12

0.04

System.Web.Profile.ProfileModule

7,442.50

0.01

System.Web.Handlers.ScriptModule

7,442.61

0.03

Other performance related articles: https://blogs.msdn.com/josere

perfecto.zip