Troubleshooting app domain restarts and other issues with ETW tracing

You learn something new every day…

I was working on an issue with app domain restarts caused by page re-compilations because aspx pages were created and modified from the code. You can get lifetime event information such as shutdown reasons, compilation information etc. in the event log by enabling Application Life Time Events in your web.config (See this post for more info about this and application restarts in general)

We were seeing a lot of the following messages

EventID: 1305
Event code: 1001 Event message: Application is starting

EventID: 1305
Event code: 1002 Event message: Application is shutting down. Reason: Maximum number of recompilations was reached

EventID: 1305
Event code: 1003 Event message: Application compilation is starting

So we know that the application is restarting due to the number of re-compiles but we don’t know what pages we are talking about.

I ran it by my colleague Doug and he introduced me to ETW tracing.

ETW stands for Event Tracing for Windows. In short processes spit out “debug” information (event traces) that you can listen to. You can even instrument your own code to spit out such trace information. ETW is meant to be really light weight and is a really nice tool for troubleshooting a lot of issues.

IIS and ASP.NET are both heavily instrumented so there is a lot of information that you can get by listening to these. To make a long story short, the reason for these event log entries is that batch compilation was turned off, so every time someone hits a new page that no-one has browsed to before, it gets compiled and emits this event.

Logging ETW traces

Doug provided me with a set of cmd files to start and stop ASP.NET and IIS tracing (available in the DebuggingScripts repo under ETWTracing) as well as to parse the output to csv files that can be opened in Excel. If you want to look at this in more detail you can download Chapter 11 of Troubleshooting IIS 6.0.

Step 1: Configuring the providers you want to trace

You can list the providers available on your system using

logman.exe query providers

This will give you a list of GUIDs for these providers and you add them to a text file in the format

GUID  flags  level  #provider   (# here denotes a comment)

In our case, the events we want to trace are ASP.NET Events and IIS:WWW Server

#ASP.NET Events
{AFF081FE-0247-4275-9C4E-021F3DC1DA35}  0xFFFFFFFF    0x05

#IIS: WWW Server
{3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}     0xFFFFFFFE     0x05

There are a few other IIS providers (SSL etc. but I’ll leave those out for now)

Step 2: Starting event tracing

To start listening for events you run the following command

logman start aspnet_trace –pf aspnet_trace.txt –ct perf –o “c:\mylogdir\aspnet_trace_output.etl” –bs 64 –nb 200 400 –ets

If we break this down a bit we have

field	explanation
start	start collecting
aspnet_trace	the name of the collection
-pf aspnet_trace.txt	file with event trace providers
-ct perf	session clock type = perf
-o …	output path
-bs 64	event trace buffer size = 64k
-nb 200 400	number of event trace session buffers min=200 max=400
-ets	send commands directly without scheduling

In the repo you will find aspnet_trace_start.cmd so to start tracing, simply run aspnet_trace_start from a command prompt.

Step 3: Reproduce your issue

Step 4: Stop event tracing

To stop event tracing, simply run the command

logman stop aspnet_trace –ets

or run aspnet_trace_stop.cmd from the repo.

After tracing has finished you will find an aspnet_trace_output.etl file containing all the traces in the directory where the cmd files are located.

Parsing ETL files with LogParser

The final step before we can view all our traces is to parse it into a csv file and this is done using LogParser which you can download from here.

Update 2020: - Logparser is no longer available for download

Logparser really deserves a post of its own. It is a really useful tool that allows you to parse IIS logs, event logs, ETW logs, netmon logs etc. etc. and query them using sql style syntax. For example, you can use it to parse out all event log events where the message contains “application starting”, or all iis requests where the status is 500. Really really useful if you have a lot of data to go through. Doug has written a few posts about it that you might want to have a peak at.

In this case we simply use it to convert the ETW logs to a csv file so we can open it in Excel.

"C:\Program Files (x86)\Log Parser 2.2\logparser.exe" -i:ETW "select * into aspnet_trace_output.csv from aspnet_trace_output.etl"

The cmd file is aspnet_trace_convert.cmd. Just make sure before you run it that you put your logparser path (as shown below) in lieu of lp in the cmd file.

Once you have run

aspnet_trace_convert

you will find aspnet_trace_output.csv in the directory, and we are now ready to dissect the trace.

Sample data

As I mentioned earlier, ETW for IIS and ASP.NET gives you a lot of information. If you have an authentication issue you can use it to trace and see who was being authenticated or not authenticated. The ASP.NET tracing displays events where you enter and leave PageLoad, PageInit etc. and all the different asp.net modules. It also displays when you queue and dequeue asp.net requests, when you compile pages and any and all of the lifetime events.

Just to illustrate how we can narrow down the pages causing the restarts, I have set numRecompilesBeforeAppRestart=”3” so that the application will restart after 3 aspx file modifications for the purposes of the demo (default is 15), and batch=”true” to turn batch compilation on (which is the default)

<compilation numRecompilesBeforeAppRestart="3" batch=”true”>

Here I have made a number of requests and after each request to links.aspx I have modified the page (by entering a space) to make it recompile.

To sort out the interesting bits I have only filtered out the following aspnet request events:

Event	When Logged
Start	request is started (shows the url and query string)
AppDomainEnter	the request enters the domain (shows the name of the domain)
WebEventRaiseStart	a web event is raised (contains the event id)
CompileLeave	compilation is finished (if batch is turned off this shows the page that is compiled)

Each event logged also contains a context id which allows you to follow the requests through the asp.net subsystem. I have manually marked each request with a different number.

Request	Row	EventTypeName	UserData
1	1	Start	ConnID=24132632|ContextId={00000000-0000-0000-1700-0060010000fe}|Method=GET|Path=/BuggyBits/CompanyInformation.aspx|QueryString=
1	2	AppDomainEnter	ConnID=24132632|ContextId={00000000-0000-0000-1700-0060010000fe}|DomainId=/LM/W3SVC/1/Root/BuggyBits-1-128703740477482149
1	3	WebEventRaiseStart	ConnID=24132632|ContextId={00000000-0000-0000-1700-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1001|EventDetailCode=0
2	4	Start	ConnID=24140680|ContextId={00000000-0000-0000-1800-0060010000fe}|Method=GET|Path=/BuggyBits/Links.aspx|QueryString=
2	5	AppDomainEnter	ConnID=24140680|ContextId={00000000-0000-0000-1800-0060010000fe}|DomainId=/LM/W3SVC/1/Root/BuggyBits-1-128703740477482149
2	6	WebEventRaiseStart	ConnID=24140680|ContextId={00000000-0000-0000-1800-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1003|EventDetailCode=0
2	7	CompileLeave	ConnID=24140680|ContextId={00000000-0000-0000-1800-0060010000fe}|Files=Batch compilation: 20 files.|Status=success
2	8	WebEventRaiseStart	ConnID=24140680|ContextId={00000000-0000-0000-1800-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1004|EventDetailCode=0
3	9	Start	ConnID=24148728|ContextId={00000000-0000-0000-1900-0060010000fe}|Method=GET|Path=/BuggyBits/Links.aspx|QueryString=
3	10	AppDomainEnter	ConnID=24148728|ContextId={00000000-0000-0000-1900-0060010000fe}|DomainId=/LM/W3SVC/1/Root/BuggyBits-1-128703740477482149
3	11	WebEventRaiseStart	ConnID=24148728|ContextId={00000000-0000-0000-1900-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1003|EventDetailCode=0
3	12	CompileLeave	ConnID=24148728|ContextId={00000000-0000-0000-1900-0060010000fe}|Files=Batch compilation: 20 files.|Status=success
3	13	WebEventRaiseStart	ConnID=24148728|ContextId={00000000-0000-0000-1900-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1004|EventDetailCode=0
4	14	Start	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|Method=GET|Path=/BuggyBits/Links.aspx|QueryString=
4	15	AppDomainEnter	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|DomainId=/LM/W3SVC/1/Root/BuggyBits-2-128703740829979893
4	16	WebEventRaiseStart	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1001|EventDetailCode=0
4	17	WebEventRaiseStart	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1003|EventDetailCode=0
4	18	CompileLeave	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|Files=Batch compilation: 20 files.|Status=success
4	19	WebEventRaiseStart	ConnID=24156776|ContextId={00000000-0000-0000-1a00-0060010000fe}|EventClassName=System.Web.Management.WebApplicationLifetimeEvent|EventCode=1004|EventDetailCode=0

The event codes for WebApplicationLifeTimeEvents are

WebEventCode	Event Code
ApplicationCodeBase	1000
ApplicationStart	1001
ApplicationShutdown	1002
ApplicationCompilationStart	1003
ApplicationCompilationEnd	1004
ApplicationHeartbeat	1005

Summarizing the events we have

• Modifying web.config (restarting the app domain)
  • 1. Request for /BuggyBits/CompanyInformation.aspx
  • 1. The request enters a newly created appdomain /LM/W3SVC/1/Root/BuggyBits-1…
  • 1. Event 1001 raised = ApplicationStart
• Modifying links.aspx by entering a space
  • 1. Request for /BuggyBits/Links.aspx
  • 1. This request is executed in the same (existing domain) /LM/W3SVC/1/Root/BuggyBits-1…
  • 1. Event 1003 raised = ApplicationCompilationStart (to compile the changes in Links.aspx)
  • 1. CompileLeave . Batch compilation of the changes
  • 1. Event 1004 raised = ApplicationCompilationEnd
• Modifying links.aspx again by entering a space
  • 1. Request for /BuggyBits/Links.aspx.
  • 1. This request is executed in the same (existing domain) /LM/W3SVC/1/Root/BuggyBits-1…
  • 1. Event 1003 raised = ApplicationCompilationStart (to compile the changes in Links.aspx)
  • 1. CompileLeave . Batch compilation of the changes
  • 1. Event 1004 raised = ApplicationCompilationEnd
• 3rd modification of /BuggyBits/Links.aspx (causing an appdomain restart)
  • 1. Request for /BuggyBits/Links.aspx.
  • 1. This request is executed in a new appdomain /LM/W3SVC/1/Root/BuggyBits-2…
  • 1. Event 1001 raised = ApplicationStart
  • 1. Event 1003 raised = ApplicationCompilationStart (to compile the changes in Links.aspx)
  • 1. CompileLeave . Batch compilation of the changes
  • 1. Event 1004 raised = ApplicationCompilationEnd

Using this tracing we can follow the events and in this case see that it was changes in Links.aspx that caused the appdomain restarts.

If batch compilation is turned on we should only see compilation when changes occur or new pages are added. However if batch compilation is turned off we will see compilation every time we hit pages that haven’t been hit/compiled earlier, but still the last compilation before a restart should give a clue to which page updates cause the restart.

Final thoughts

I am sure that you can find lots of other good uses for ETW tracing, if you have written posts about where you use it, feel free to link to it in the comments.

Really what I wanted to show here was just how easy it is to set up and use so that you have a step-by-step for doing it when you need it.

Have fun,

Tess