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

Comments

  • Anonymous
    October 04, 2010
    Nice job. I was looking for it. Thanks

  • Anonymous
    May 02, 2011
    que significa error code 0xc0000bf8

  • Anonymous
    May 02, 2011
    Esto significa "Al menos uno the los coleccionadores the datos tiene menos de dos datos". Esto ocurre cuando los datos se coleccionan muy rapido. Los contadores de performance se leen cada 10 segundos, Si se presiona Start/Stop muy rapido, el sistema no tiene tiempo de leer mas de un dato. Para evitar esto, collecciona los datos por mas de 10 segundos. O borra el coleccionador de contadores. O cambia el intervalo de lectura. English: Maria: What does error code 0xc0000bf8 means? Jose: Means "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.

  • Anonymous
    April 03, 2012
    I am interested in this tool. Looks very impresive. I downloaded it but setup failed in Windows 7. Can you please confirm if it works on windows 7? Thanks - Its a great help!

  • Anonymous
    April 05, 2012
    Yes. It works for me on Windows 7. What's the failure? Feel free to take it offline by sending me mail directly (See 'Email Blog Author' at the top of the page).

  • Anonymous
    June 25, 2012
    Hi dear Jose, I made some changes of this tool to add processor and network interface counts, and I done it by editing xml files provided in the package, could you tell me how to create a report from scratch out? Thanks a lot!

  • Anonymous
    June 29, 2012
    David, sorry it took me so long to reply to you. We’ve been busy around here. Anyway, what I did to create my report was to add a new data collector set and export it as a template. The standard templates on the machine already come with many different report schemas. Looking at them, I reverse engineered how to create my own. The command below will find them on the hard drive: findstr /si /c:"</Report>" c:windows*.xml In any case, an empty report is just an xml like below: <?xml version="1.0" encoding="UTF-8"?> <?Copyright (c) Microsoft Corporation. All rights reserved.?> <Report version="1"> </Report> Another option is to use the IDataCollectorSet COM Interface. See msdn.microsoft.com/.../aa371952(v=vs.85).aspx Actually, the first version of perfecto used this API and C++ to create the collector. The sources are still somewhere. The problem with that version was that publishing to the web in executable format required the binaries to be signed. I avoided that but using XML only. Hope that helps, Jose.

  • Anonymous
    March 15, 2013
    It would help to know how to interpret the counters themselves. Otherwise we are looking at a list of numbers.  What is good? What screams out saying server is having problems?   This is good but requires some more information.

  • Anonymous
    March 15, 2013
    Agreed. The goal here was just to present the tool.

  • Anonymous
    February 13, 2014
    Hi Jose, This tool is impressive. Can you please confirm if I can use this tool to monitor application as a whole? I want to monitor total no. of requests coming, no. of requests completed, waiting, failed, avg. time taken for processing requests etc? I have already set up Windows Perfo Monitor and added counters. But it's bar graph is not very user friendly. So, I am looking for other options and want to try Perfecto. Regards, Suraj

  • Anonymous
    February 14, 2014
    I would not recommend to use this tool, as it is, to monitor an application in production due to the impact in performance of enabling ETW. See "ETW Performance Effect on Production Servers" above. You could disable the ETW portion of the collector and add/remove the performance counters you need.

  • Anonymous
    April 23, 2014
    The comment has been removed

  • Anonymous
    February 08, 2016
    What's you recommend now for monitor ASP.NET in Stagging, and monitor ASP.NET in Production ? Thanks a lot.