Vance Morrison's Weblog

Updated Instructions for collecting ETW data on a ARM WinRT device (e.g. Surface)

Vance Morrison — Thu, 09 May 2013 12:52:37 GMT

I have updated my blog entry on collecting ETW data on an ARM WinRT device. Previously I told you to use the WPR's 'GeneralProfile' to collect the data. This is OK for some investigations, but does not collect all the same events that PerfView would have collected (most notably GC events, JIT compile events and async Task Events). We have created a DotNetRuntimeProfile.wprp, that will tell WPR to collect these extra events. See the posting for more details. I do recommend this if you need to collect ETW for managed code applications on the ARM device.

Vance

PerfView does JavaScript investigations too

Vance Morrison — Tue, 02 Apr 2013 23:15:51 GMT

Do you have a windows store JavaScript/HTML applications that needs performance tuning?

PerfView can handle JavaScript. In particular

It automatically collects the necessary events so that it can decode the names of the JavaScript functions on any stacks that are captured. (Note however that if your JavaScript has been obfuscated, you do have problem).
When you use the Memory->Take HeapSnapshot command on a process that has a JavaScript heap it will dump that heap (it will also dump the .NET heap if it has that (or both)).

For the most part, investigations of JavaScript applications are basically the same as that for .NET. The main differences is in the heap dumping. Because JavaScript objects don't have a 'type' basically what PerfView can't aggregate as much (normally it aggregates by type), and what it shows instead is object property names (in .NET it shows the type names and NOT the property/field names). The basic strategy however is the same, so the PerfView videos are pretty relevant.

Vance

I have a note to myself to beef up the documentation in this regard, and well as do some targeted videos, but it may be a while

Using TraceEvent to mine information in OS registered ETW providers

Vance Morrison — Sat, 09 Mar 2013 21:49:27 GMT

In previous blocks on TraceEvent I shows you how easy it was to start up ETW sessions to collect information generated by System.Diagnnostics.Tracing.EventSource classes (typically logging that you yourself did). But I also mentioned in other blogs that the one of the real strengths of ETW was the fact that you get to correlate lots of OS generated events with your own. Well in this entry I will show you how to do this (although I will show you even better ways in later blogs).

In this blog I will walk though a simple application called 'ProcessMonitor' which basically prints a line to the screen every time a process on the system starts or stops. There is a ZIP file of a VS2010/VS2012 solution at the end of the blog and I encourage you to open it and read the code and play around with it. I have removed comments and error handling a the 'essential' code is only about 35 lines of code. Here it is.

The basic structure is basically the same as the 'real time' (no file) EventSource example that I already blogged about. Basically you

Open a TraceEventSession (with a null file name to indicate a 'real time session'. A session is a 'controller' which can turn ETW providers on and off.
Connect a ETWTraceEventSource to that session, A TraceEventSource represents the stream of events that were sent to the session. An ETWTraceEventSource knows the 'basic' structure that is common to all events (like that every event has a process id, time stamp, source provider, task and opcode, but does NOT know how the name of the event or how to deserialize the payload of the event.
Connect one or more TraceEventParsers to the ETWTraceEventSource. A TraceEventParser knows how the event names and how to deserialized the payload bytes of the raw ETWTraceEventSource FOR A PARITULAR SET OF EVENT PROVIDERS. In this case we connect the 'RegisteredTraceEventParser, which knows how to decode any event that was registered with the operating system (using wevtutil). EventSource are NOT typically registered (although they can be), for EventSources you connect a DynamicTraceEventParser (because EventSources log their event information at EventSource startup time (dynamically). However in this case we are interested in the OS providers, and so RegsiteredTraceEventSource is what we want. It is common to register both.
Subscribe to the event callbacks of TraceEventParsers that you connected to your source. Some parsers are 'strongly typed' in that they know the exact name and fields of every event they know about at compile time (ClrTraceEventParser and KernelTraceEventParser are like this). These are the best to use because they are VERY efficient (no string lookups), you get to use normal C# property accesses (since the names of these properties are known at compile time), and are type-safe (no casting needed). However both DynamicTraceEventParser and 'RegisteredTraceEventParser can not work like this because they fetch the information about events at runtime (not compile time), and thus look more like a reflection API. In a later blog post I will show you how to fix this by generating TraceEventParsers for use at compile time, but until that we will make do with the limitations of 'RegisteredTraceEventParser . Because 'RegisteredTraceEventParser' does not know at compile time the names of ANY events, you can't subscribe to particular events with this TraceEventParser, instead you can only subscribe to 'All' meaning all events this parser knows how to parse. Once inside the callback you can then filter out the particular events of interest. In our case most of the code above is the delegate body that gets called on every event that 'RegisteredTraceEventParser knows how to parse.
Enable the ETW Providers for the events you are interested in. In the example above we use the GetProviderByName() API to convert the name Microsoft-Windows-Kernel-Process to is unique ID, and then used that to enable the provider with and level (verbosity) of 'Informational' and a 'keyword' (bitset) argument '0x10' . The 'keyword ' argument is a bitset that indicates which events to enable. It is not uncommon to use -1 (all 1s bitset, or every event in the provider), however in this case we 'knew' the right bitset was 0x10 (more on how we did that below).
Process incoming events by calling the ETWTraceEventSource's 'Process()' method. For files, this returns when all the events in the file are processed. For real-time sessions, it only ends when the 'ETWTraceEventSoruce.StopProcessing()' method is called.

Once Process() is called, as events come in your event handlers will be called (for real time sessions there typically is a 1-3 second delay between the event happening and being called back in your Parser). In our case we are looked for events with at 'TaskName' of 'ProcessStart' and 'ProcessStop' and based on what we see there we call 'PayloadByName' to fetch particular payloads (and cast them to the correct type), and then process them (in this case simply print a message to the Console.

So you can see, that the actual mechanics of making this tool is reasonably straightforward, however we make two important observations:

The callback code is not very friendly. It has lots of 'magic names' which if incorrect, will simply cause nulls to be returned (which means casting will throw an exception). You had to know what type various things were (was CPUCycleCount an int, uint, long, ulong?) and you can imagine that the code behind 'PayloadByName' is relatively inefficient (it much do some sort of string lookup when it is called and then box its result into an object (which we then have to cast). This is no horrific (as it would be if we had to deserialize the data blob ourselves), but is not unlike the string parsing you do when processing a CSV file, which we would like to avoid.
There is also a discovery problem. How do we know that the provider 'Microsoft-Windows-Kernel-Process' event exists, and how did we know that the 0x10 keyword was what we wanted? Thus this example alone is really not sufficient, we need to understand what providers are out there and what keywords they have. How do we do this?

The answer to the first problem is to generate a provider-specific TraceEventParser at compile time. That is what we want is to have something that takes a provider (or more specifically a description of all the events in a provider called the manifest), and generates code that knows how to parse THOSE PARTICULAR EVENTS. Now you just link in that code, and the you can now get a much better experience, where intellisense works and each event knows the fields that are valid. We have a tool called 'TraceParserGen' which does exactly this, which I will talk about in a future blog. In the mean time I will show you how to find the strings I used in the code above for yourself in this blog entry.

Then answer to the second point (how do we figure out what providers are out there and what events are in the provider) for today at least is the 'logman query providers' command.

You can find out all the providers that have been registered in the operating system by running the command

logman query providers > providers.txt

It is a long list, which is why I redirected it to a file. Generally you care most about the providers that begin with 'Microsoft-' because these are the 'new' ETW providers. Most of the others are 'old' providers' and may not provide any useful information about how to enable them. It also does not include providers that did not publish themselves to the OS (EventSources DO NOT publish themselves an thus are not on the list). Thus the command above is pretty much only useful to find out what OS providers there are (which is still VERY useful).

There is a very useful variation of the command above. You can give it a -pid <num> argument

logman query providers -pid 5400

Which looks for all USER MODE providers that CAN BE ENABLED in the process given. This will include all EVENTSOURCEes (however it will just show their GUID, so it is not super-helpful), and will NOT show KERNEL providers (they are implicitly available for all processes), but will show you the USER MODE OS providers that are available, which is still pretty handy.

Once you have a provider you are interested in, you can find out what Keywords and level it allows by specifying a provider name on the 'logman query providers' command. For example have doing a logman query providers and seeing Microsoft-Windows-Kernel-Process, we can guess that if we wanted to know about process stuff that this provider would probably do it. Thus we execute the command

logman query providers Microsoft-Windows-Kernel-Process

And we get the output

Value Keyword Description
-------------------------------------------------------
0x0000000000000010 WINEVENT_KEYWORD_PROCESS
0x0000000000000020 WINEVENT_KEYWORD_THREAD
0x0000000000000040 WINEVENT_KEYWORD_IMAGE
0x0000000000000080 WINEVENT_KEYWORD_CPU_PRIORITY
0x0000000000000100 WINEVENT_KEYWORD_OTHER_PRIORITY
0x0000000000000200 WINEVENT_KEYWORD_PROCESS_FREEZE

Which shows us that the keyword 0x10 will get use the WINEVENT_KEYWORD_PROCESS events and the keyword 0x40 would get us the WINEVENT_KEYWORD_IMAGE, so if we cared about processes and image loads, setting the keyword 0x50 (the OR) should give us what we need.

Another pretty common technique is to just 'try it and see'. For example, once we were interested in Microsoft-Windows-Kernel-Process we simply 'try it and see' using PerfView.

PerfView /onlyProviders:Microsoft-Windows-Kernel-Process collect

Let it run for a bit, and then look at the 'events' view in PerfView. By default if you simply specify a provider name in PerfView, it turns on ALL keywords and VERBOSE level, so you should get everything. you can then see what you got. Doing this for Microsoft-Windows-Kernel-Process we see the following in the events view

That the Microsoft-Windows-Kernel-Process provider has 4 events. In PerfView an events is show as 'Provider/Task/Opcode' so the first event in that display has a 'TaskName' of 'ImageLoad' and an empty opcode (Info). We also see the event with the 'ProcessStart' TaskName and the OpcodeName of 'Start'. These are probably of interest
Looking at particular exmaples we see that a ProcessStart/Start event has fields like 'ParentProcessID' and 'ImageStart' and that the ProcessStop/Stop event has fields like 'ExitCode' and 'CPUCycleCount'. This is how we know what strings to pass to 'PayloadByName'.

It is possible to probe this information at runtime (if you just to a ToString() on a TraceEvent, it will dump a XML representation of all the fields of the event into the returned string). There are also the 'PayloadNames' property that tell you all the legal values to pass to 'PayloadByName'. Typically, it is easier to simply 'try it an see' in PerfView, however.

So there you have it, You are now armed with the ability to go data mining for all the interesting events in the ETW system. Keep in mind however, that for kernel events, your first reactions should be to explore the KernelTraceEventParser, because it is already got a nice, efficient, strongly typed wrapper. However if it is not there, You can use RegisteredTraceEventParser to decode it. Couple this with the ability to also see your EventSources, and things start to get very exciting...

So now its your turn. Open the ProcessMonitor.ZIP file attached, drag it to your machine, open it in Visual Studio and take a look (it has lots of comments I omitted above). Play around with it (try other providers, and keywords, Play with image load events or file open events).

Vance

More Support for EventSource and strongly typed logging: The Semantic Logging Application Block

Vance Morrison — Sat, 09 Mar 2013 18:14:00 GMT

If you have been following my blog at all, you have seen my articles about System.Diagnostics.Tracing.EventSource, a class that introduced in V4.5 of the .NET Runtime for production logging. This class replaces the System.Diagnostics.TraceSource class and we strongly encourage people to consider using EventSource instead of TraceSource for any future work (You can events from one go to the other 'stream' so you can transition slowly if you need to) We like to believe EventSource is 'ultimate' in logging APIs for .NET in that you should be able to do pretty much any logging you desire with it and we should not have to change it in incompatible ways, ever. We believe this simply because of the 'shape' of a logging statement, here is a prototypical one

myEventSource.MyEvent(eventArg1, eventArg2, ...)

Basically at the call site you specify

The EventSource (myEventSource)
The Name of the Event being raised as a method (MyEvent)
Any 'payload' arguments you wish to log as part of logging that event.

Notice I did not specify any formatting strings, logging levels, or other meta data at the call site, just what 'has to be there'. What may not be quite so obvious is that all the event arguments are passed without loss of type information (the MyEvent method is strongly typed, not a 'params object[]'). Unlike 'printf' 'string.Format' logging we did not 'stringify' anything and loose information. It is all passed to the logging method. This information is preserved in the EventSource 'pipe' which means that when you access a particular event you can do so in a strongly typed way, accessing each payload argument with a property accessor as this snipped of code demonstrates.

MySourceParser.MyEvent += delegate(MyEventTraceEvent data) {

Console.WriteLine("MyEvent: Arg1 = {0} Arg2 = {2} ", data.MyArg1, data.MyArg2); // Where MyArg1, and MyArg2 are the names of the parameters of the 'MyEvent' method.

}

Thus you really can get to the point where your logging is what you wanted, it is like passing data a method call in the program being monitored, through the logging pipeline (serialization) to pop out as a to strongly typed structure in some automation that processes logging information files. Basically you get a 'full fidelity' (without loss of type information or 'metadata' like payload names) end to end pipeline for logging information. This is ideal in event logging, and EventSource is in a position to deliver it.

We are not completely there yet as there are missing pieces. However far more of it is actually in place, people just don't know about it. I am trying to fix this with my blog, but there is a lot to tell and event that is a work in progress. Well in the blog entry I am here to tell you about one of the big pieces of this overarching 'strongly typed eventing story' that is falling into place:

The Semantic Logging Application Block

Microsoft has a team called the 'Patterns and Practices' team whose job it is to illustrate gpod and proven practices in using Microsoft technologies. As part of their work they write guidance and build samples of real applications, but they also write utility libraries that 'flesh out' Microsoft technologies that currently only provided 'the basics'. This team recognized that the strongly typed pipeline that EventSource provides is a great foundation, but only provided the basics, and they could provide the next layer of 'value add' libraries.

This is what the Semantic Logging Application Block is. 'Semantic Logging' is their term for strongly typed logging. They like the term because it strongly conveys the fact that the logging happens at a more structural level, and is much closer to the logging the semantics of the program (since you pass strongly typed fields without losing the types or the names of the event or fields), than classic string based logging does. This 'Embracing Semantic Logging' article gives a great summary of their view of why they like semantic logging and why you should too.

As you might expect, I heartily endorse their philosophy on logging, and their efforts to 'flesh out' the EventSource foundation, and make it as useful as possible to as many as possible. If you are not already a convert to EventSource, I strongly encourage you to read 'Embracing Semantic Logging'.

For those of you who are already 'on board' with strongly typed logging, what can Semantic Logging Application Block do for you?

EventListeners that send your EventSource data to various places like a flat files, Azure storage, the windows event log, a database etc.
An EventListener host/service that can process events from any processes on the system and do application specific monitoring / rollups.

For more complete details see their the PDF file documentation on the 'Download' tab. Here are the links for the current release (but are likely to be broken in the future)

So, if you are doing logging on the .NET platform, you should be using EventSource. If are looking around for what reusable code you can leverage, take a look at the Semantic Logging Application Block.

Vance

A Lab on investigating Memory Performance with PerfView

Vance Morrison — Thu, 28 Feb 2013 04:40:00 GMT

As part of a conference that I participated in this week, I have created a lab on using PerfView to investigate Memory issues.

The lab covers both managed and unmanaged code techniques.

The ZIP file below of two Visual Studio 2012 projects which create leaky apps (one C++ and one C#), as well as an MHT file (multi file HTML), which is the document that leads you through the lab. It is loaded with screenshots and is quite detailed. It does assume you have VS 2012 installed and are running on Windows 8.

For those who don't have those prerequisites, I have put the data files that you would have collected into PreWin8DataPackage.zip on my public skydrive. Simply click on the link which takes you to skydrive, and then open the ZIP file by double clicking on int and the contents to a local place and then you can open them in perfView and follow along without needing Win8 or VS 2012. .

To use the InvestigationMemory.ZIP attached below, file simply open it, and drag its contents to a convenient folder on your machine (e.g. the desktop). Then open the MHT file (it should open in the browser) and follow the instructions.

Enjoy

New version of TraceEvent / PerfMonitor Posted to bcl.codeplex.com

Vance Morrison — Mon, 07 Jan 2013 14:27:05 GMT

For several years now, I have had code called the 'TraceEvent library' that allows you to access ETW files (ETL files) from C#.

However for over a year now, I have not updated the public version of that library. Well, that time has ended.

I updated the TraceEvent library as well as the PerfMonitor sample at http://bcl.codeplex.com to sync up with the latest internal versions. The TraceEvent library is version 1.2.7 (corresponding to the version of PerfView that uses it), and the version of PerfMonitor is Version 2.0.

For those of you don't know, the TraceEvent library is the power behind the PerfView tool, and that makes it pretty powerful. With it you can

Use the TraceEventSession class to turn on ETW providers, including the Windows Kernel provider (CPU sampling) and the .NET Runtime providers. You can turn on capturing stack traces for most events.
You can tell the sesson to either log the data to a (ETL) file or send it to a in-memory buffer for 'real time' consumption of the events.
Use the TraceEventSource class to read the resulting data (either ETL files or the in-memory buffer), and parse resulting payloads
The library has built in support for the Kernel and .NET Runtime providers.
It also built-in support for System.Diagnostics.Tracing.EventSource using he 'DynamicTraceEventParser' class. Thus you an always properly parse EventSource data.
As well as support for the RegisteredTraceEventParser, which knows how to decode any 'Manifest Based' provider (basically any OS supplied provider).
The 'TraceLog' class creates a high level abstraction, which knows about Processes, Threads, Modules, and how to Decode Stacks. It has a routines (the DiaLib) that know how to look up address in PDBS to get symbolic names as well as get symbolic names for Just in Time (JIT) compiled code. The result is that you can get at symbolic names for stacks (this is how PerfView works).

In short, most of what you see PerfView do with an ETL file, you can do yourself. Now if you just need a 'tweek' of what PerfView does, I recommend using PerfView's extensibility model to do the job (see the Help -> Extending PerfView menu entry in PerfView). However if you want something 'stand alone'. TraceEvent is a good choice.

If you have used TraceEvent in the past, there are some small braking changes, but the port should be easy (I updated PerfMonitor in a couple hours). There have been numerous fixes, as well as the addition of the RegisteredTraceEventParser and much better support for Symbolc resolution The DiaLib stuff is new). It is worth upgrading to.

The PerfMonitor utility can be thought of as a 'command line' version of PerfView. However I don't recommend using it as an actual tool, it almost all cases, PerfView is a better tool than PerfMonitor. PerfMonitor is more of a sample of how to use TraceEvent in non-trivial ways (it is easier to understand without all the GUI goo cluttering up the logic).

I will probably post more detailed 'how to's of using ETW with TraceEvent in future blog posts.

Vance

Why doesn't my EventSource produce any events?

Vance Morrison — Sat, 22 Dec 2012 01:16:00 GMT

This is a quick entry to warn about a pitfall that you are likely to run into sooner or later if you build or maintain EventSources.

As I have blogged about, it is very easy to get started with EventSources. Here is some code that someone might write

And then use it by using by doing

MyEventSource.Log.MyFirstMessage("The time is " + DateTime.Now);

You turn your EventSource on by doing

PerfView /providers=*MyEventSource run MyApp.exe

but you find that there are no events in the resulting log file from MyEventSource!

What is going on? The root of the problem is that there is a bug in the code above (can you spot it?). Notice that the First and second message call 'WriteEvent' with exactly the same ID. This is a mistake. Each event in an eventSource must be given a unique ID. In fact the rule is stricter than that: the event you pass 'WriteEvent' must be exactly the event ID that EventSource thinks it should have. This ID is either

The ID assigned to it explicitly with the Event attribute (not used in the above case) OR
The ordinal number of logging methods' where a logging method is defined to be a method that returns void.

Thus 'MySecondMessage MUST use the ID 2, not 1 (since it is the second logging message in the class). This insures that there is a unique ID given to each event that an EventSource generates. EventSource checks for this and throws an exception if this (and many other error conditions) occur.

So where is my Exception? This is the unfortunate part. Late in the development of EventSource users made the strong request that EventSource NEVER FAIL by default. This is a useful property, as logging is often 'optional' and you don't want to some startup error with ETW to cause your application to fail. This feature was implemented by simply wrapping the body of the constructor in a try-catch, which sets a flag in the catch clause that will make any subsequent WriteEvent call simply do nothing.

This satisfies the desire for EventSource to never throw, but it also makes finding any mistake in your EventSource very difficult. Worse, there seems to be a bug in VS where exception that are caught are not always displayed in the output window and setting the 'Exceptions' dialog to stop on any exception thrown does not seem to work (probably because in the typical case EventSource is called from the class constructor (to initialize a static variable)).

This is all very unfortunate, and leads to 'mysterious' failures if you make ANY mistake in your EventSource.

The good news is that there is a pretty easy work-around that works today. It is simply this

When you make any changes to your EventSource, immediately use PerfView /providers=*EventSourceName collect test it. (That is use PerfView's default settings and your provider to turn it on)
If you don't find your events as expected, Open the 'Exceptions Stacks' view in the data file

This will show you something like this

Which shows you all exceptions thrown during the trace, include any that were swallowed by a try-catch in the implementation of EventSource.

Notice that you get the exactly exception message, which tells you pretty clearly what you did wrong (in the example above the 'EventMessage1' event was passed 1 but it should have been 2.

So the simple advice is

if your EventSource is not working after an update, simply look at the 'Exceptions view'.

What is nice is that once you know about this, it is probably EASIER than trying to debug it in the debugger (because you had to use something to turn on the provider anyway). Now you don't even need a debugger to resolve the issue.

Using TraceSource to log ETW data to a file

Vance Morrison — Fri, 21 Dec 2012 06:19:00 GMT

Yesterday's blog post was showing how you can use EventSource to generate ETW events and the TraceEvent library to read them in 'real time'.

Today we will do a slight variation on that example. Instead of reading the events in real time, we will simply log them to a file, and then later (it happens to be right after the file was generated), we open this file and process it. As you would hope the actual difference in the code is pretty minimal. This example also cleanly separates 'generation' of data from 'processing of data', which is nice.

Generating the file

At it's heart, this is the code to generate the file is pretty simple.

This code creates a TraceEventSession, giving it a name, and in this case a file name to log the data to. Next we tell the session that the OS session should be stopped (reclaimed) when the TraceEventSession is disposed. We then enable any providers we want to log (in this case only one), and then collect for 12 seconds and then close the TraceEventSession (the using statement) which closes the file. At this point we have our data.

Processing the file

To process the file we use the following code.

This code opens the data file, hooks up the DynamicTraceEventParser (which knows how to parse EventSource providers, and register a callback for ANY event that the parser recognizes (the All event). In this callback we print out the event and also print something special when we see the 'Stop' event.

After setting up the callbacks we call 'Process' that reads the file and does all the necessary callbacks. It returns when there are no more events in the file to process.

And that is about it. As you can see it probably EASIER to do ETW data collection in two pieces (they split very nicely into two pieces). The first piece ONLY deals with TraceEventSession (the controller), and the latter piece ONLY deals with ETWTraceEventSource and parsers (the READER). Each one is pretty easy to understand.

Check out the complete sources

The MonitorToFile.zip has the complete, buildable source code (uses a VS 2010 or VS2012 solution). The code is a bit longer because it has a lot of comments and a bit of error handling, but I hope you will be able to easily recognize the snippets above as the 'heart' of the program.

Advanced scenarios: Circular buffers and Kernel events.

Once you understand the basics, you may be interested in some of the more advanced features. In particular there is the ability to log to a 'circular' file, where the file size is constrained to a maximum and when the maximum is reached it starts overwriting the oldest data in the file. This allows you to create a 'flight recorder' and allows you see the last few minutes of processing before an interesting event happened. Setting up a 'trigger' that will stop such a circular buffer logging session is a pretty common scenario. But the loss of the events in the beginning of the trace brings problem, the most serious of these is that the decoding of some events requires information from other events. In particular EventSources themselves generate a 'manifest' event when they start that describes the fields of every other event the EventSource will generate. If this event is lost, then libraries like TraceEvent.dll can't decode the payloads of the events (a HUGE loss). To fix this, when you collect a circular trace, right before you stop the trace you need to force any EventSource that you started to emit is manifest event again. This way you make up for the loss this event that happened earlier in the trace but was discarded by the circular buffering. It is reasonably straightforward, but does complicate the code a bit.

We have seen that it is pretty easy to log EventSource data. The same is true for .NET events as well as some OS events. However some of the most important events (the Kernel OS events) have additional restrictions on them, and one of these restrictions is that kernel events can only be logged in a session by itself. Thus if you want both EventSource data as well as Kernel OS data, collecting the data is more complex. If there is interest I will talk about this scenario, but you can also look at the PerfMonitor source code right now to see how it is done. This is particularly tricky for real time sessions because different buffer flushing protocols will make the events come from the two sessions in clumps that are only loosely related to the time the event happened. Thus it is a bit trickier to properly sort the events from the two sources. The PerfMonitor code has a special class specifically to solve this problem.

How many samples are enough when using a sample based profiler in a performance Investigation?

Vance Morrison — Thu, 20 Dec 2012 20:13:19 GMT

Performance analysis is my job, and so I answer a lot of questions about perf, and this blog is about a frequently asked question I get.

When doing CPU analysis, many profilers, including the PerfView tool are sampling profilers. In particular, for PerfView, by default every millisecond it will stop each processor and take a stack trace. Thus you don't see every method that gets executed, but only those that happen to be on the stack when these 1 msec samples are taken. PerfView allows you to control this (there is a CPU Sample Interval MSec text box in the 'advanced' area of the collection dialog box). Using this textbox you an set it as fast as once ever 1/8 of a msec and as slow as once every 100 msec or more. This leads to the question: How many samples are enough? This is the subject of this blog entry.

First the obvious: From an overhead perspective slower is better .125 sampling is 8X more expensive! both in terms of runtime as file size (EVERY manipulation of the trace is not 8X slower (e.g. file transfers, Perfview view updates ...)). Thus assuming you get the quality of information you need, slower is better.

So: the question is what rate will get you the quality you need. It is important to realize that the answer to this question is NOT about the RATE, but whether you have enough TOTAL sample for you SCENARIO OF INTEREST. There is information in the PerfView documentation on this very point (see How many samples do you need?) which you can quickly find by following the 'Understanding Performance Data' link at the top of the CPU view. What that section says is that the potential error of a measurement varies as the square root of the number of samples. Thus if you have a 100 samples, you have reasonable confidence that the 'true' number is between 90 and 110 (10% error). If you had 10K samples (100 times more), you would have reasonable confidence that the number is between 99900 and 10100 (a 1% error). Now while you might think you should drive the error as small as possible, really you don't need that. Typically you don't care about 1% regressions, you care about 10% regressions. If your scenario had 1K samples, a 1% regression is 100 samples and the error of that 100 sample measurement is 10 (sqrt(100)) or 10% (that is you are confident that the true regression is between 90 and 110 msec). As you can see that is typically 'good enough' This leads to the rule of thumb that you need between 1K and 10K samples OVER YOUR SCENARIO to get an error that is good enough for most investigations.

It is important to realize that this has NOTHING to do with how small any particular function is. The basic intuition is that if a function is small, unless it is called a lot you don't care about it. If it is called a lot, it WILL show up in the samples if you have enough samples in your SCENARIO OF INTEREST. Thus the driving factors are

What the period of time is for the scenario of interest is. If this is a 'one shot' scenario (only happens once), then you need a rate that will capture between 1 and 10K samples in that time period. Thus the MOST COMMON reason for needing a high sample rate is that you have a short scenario (100msec) that only happens once. (thus you would LIKE .1msec sampling to get to 1000K total samples). But typically you are measuring AVERAGES over LONG time (e.g. you measure the average over 10 seconds of requests), then you can easily get your 10K samples using 1msec time. In fact whenever you have a RECURRRING scenario it is EASIER AND BETTER, to simply measure for a longer period of time rather than increase the sampling rate. (In fact, when you have long traces, you can make perfView more responsive without loosing the accuracy you need by limiting the time interval you look at to say 10 or 20 seconds of trace.
What error rate you can tolerate. If you are looking for 'big' things (e.g. 10% of the total trace), then 1K samples is enough. 10K samples allows you to see 1% regressions (100 samples), with 10% error (which is fine). If you were looking for .1% regression you would need 100K samples to be able to find .1% regressions with 10% error.

The result of all of this is

What matters is the total number of samples in your scenario of interest.
If you have a RECURRING scenario, you should simply collect for a longer period of time.
If you have a ONE SHOT scenario and that scenarios is short (e.g. 100Msec) you need to increase the sample rate AND/OR run the scenario multiple times (making it a RECURRING scenario).

An End-To-End ETW Tracing Example: EventSource and TraceEvent

Vance Morrison — Thu, 20 Dec 2012 19:42:00 GMT

I have already made a series of blogs about EventSource starting with my tutorial introduction to EventSource. This gives you enough information to generate events, and using the PerfView tool, lets you look at these events in a viewer. This is great for a broad variety of ad-hoc scenarios. However what if you want to go further and build automation that processes your EventSource events programmatically? This is what this blog entry is about. Here I show you how to use the TraceEvent library (there is a old version of the code available here, but the version of this DLL that is included in the ZIP file associated with this blog is much newer, and I recommend using that until the codeplex site gets updated (hopefully soon). The TraceEvent library is all about reading ETW data, and it is the library that the PerfView tool itself is built upon. Here we show you how easy it is to use this library to programmatically enable your EventSources and parse the results programmatically.

You will notice that I have attached a SimpleMonitor.zip file to this blog entry. This zip file contains the TraceEvent.dll library as well as a simple, one page demonstration application called 'SimpleMonitor'. To demonstrate the 'end-to-end' scenario, this application contains both parts: the EventSource that generated the events as well as the logic that turns on the EventSource and parses the resulting events. Normally these two parts would be in different processes but to make the demo super-simple to run, both parts are in the same executable.

The Event Generator generates 3 types of events, MyFirstEvent, MySecondEvent, and Stop. It happens to generate the first two once a second for 10 seconds then logs the Stop event and then goes silent. The listener code turns on this provider, watches for these particular events, takes different actions on each of them, using the event payloads in the events in the processing. The processing consists of computing the time delay between the 'MyFirstEvent' and 'MySecondEvent'. When it sees the 'Stop' event the listener shuts down and the whole program exits. This example is simple enough to demonstrate the end-to-end process in a small amount of code. Here is a condensed version where I simplified it to highlight the essentials.

Basically you create a TraceEventSession which is a 'sink' which represents a stream of ETW events. These sessions are KERNEL objects, and in particular they can live beyond the lifetime of the process that created them (thus you can have one process 'start' a session' and another 'stop' it. You can create a session that logs to a file, but in this case we passed 'null' as the file name which means we don't want it to go to a file but we will read it in 'real time'. Session are for CONTROLLING ETW sessions (thus you see that later we do an 'EnableProvider' on the session to turn on the particular EventSource we want. You an turn on many providers on the same session, but in this case we did only one.

Because we want to READ the data that is being logged to this session in real time, we attach a 'ETWTraceEventSource' to the session. This knows how to READ etw events. You can tell this to read from a file, but in our case we told it to read in real time directly from 'My session', so this is where it will get its data. Now an ETWTraceEventSource knows how to read ETW events, but every different provider has its own different 'payloads' and you need something that understand the particular payload for the events you are interested in decoding completely. This is what a 'TraceEventParser' is: something that knows how to parse a PARTICULAR provider's events. We will see in later blog entries how we can create TraceEventParsers that are designed to decode just ONE EventSource's events, however in this case we are using the 'DynamicTraceEventParser' which knows how to decode ANY EventSource (but can only do so relatively inefficiently and is relatively cumbersome to code against).

One way you can get parsed events from a TraceEventParser is to ask the parser to call you back when a particular event happens. In this case we ask the DynamicTraceEventParser, to call us back whenever any event happens (by subscribing to the 'All' event). Thus the anonymous delegate shown above get a callback whenever any event happens that the 'DynamicTraceEventParser' knows how to parse (which includes all EventSources). In the demo we simply print the event (which will show you all the payload fields printed out nicely as XML), and look for an event called 'Stop'. When that happens to close the source (which stops the listern).

Once we have set up the callbacks for our READER, we turn our attention back to the SESSION and tell it to actually enable the EventSource that we want. From that point events are starting to accumulate in the session. We then call the 'Process()' event on the SOUCE (the reader), which will start reading events from the session and dispatching them to the parsers which dispatch them to our callback. This continues until there are 'no more events'. For files, this is the end of the file, but for real-time sessions, it only stops when the source is closed (which we do when we see the Stop() event).

So in recap to get at EventSource event programmatically you

Create a session which allows you to turn on and off particular event sources
Enable one or more EventSources in the session
Connect up a ETWTraceEventSource to the seesion which can READ the events
Connect up a TraceEventParser, that knows how to PARSE a Particular provider's events
Subscribe to the TraceEventParser's events that you are interested in. What you get back is a fully parsed event
Call source.Process() which runs the dispatch loop and only returns when all events are read (or the source is closed())
Call source.Close() or source.Dispose() (They are synonyms) when you are done
Call session.Dispose() when you are done with the session (this is what the using clause does)

You can see that you can do all of this in just a few lines of code. If this piques your interest, you should definitely download the source and take a look. It is not long (2 pages), and most of it is comments that describes in detail what the code is doing. It is definitely worth a read.

Next time I will show you how this changes when you log to a file instead. In later blog entries I will also show you how you can build parsers that are specific to your EventSource, and make building the processing code easier and significantly more efficient. You can also turn on other providers that are built into the OS and the .NET Runtime, and capturing stack traces when event fire, which is where things really start to get interesting.

Source Code Guide

To look at the complete source, simply open the SimpleMonitor.zip file and copy it to your machine. You can build the solution in Visual Studio. All the interesting code is in Program.cs, and only consists of about 2 pages of code which hopefully you will recognize from the snippet above.