More on using EventSources with XPERF or WPR


In my introduction to EventSource blog, I showed a simple example of using EventSource to log ETW information. In that example I used the PerfView tool to collect and display the information.   It is also possible to do the same using the XPERF or WPR tools (part of the WIndows Performance Toolkit) and in this blog entry I give an example.   In this entry I give some background

For the most part, an EventSource is really just another ETW provider.    The main difference is that an EventSource has support for logging its manifest INTO THE DATA STREAM, to make the resulting ETW data stream SELF-DESCRIBING, in the sense that you don’t need other information (e.g. a registered manifest), to decode event payloads.    Thus while you CAN register the manifest of an EventSource, you don’t have to, and most EventSources don’t.  (If you are interested in registering EventSource manifest see my blog on channel support will lead you to the EventSource Samples Nuget package that has detailed samples and documentation on doing this (because channels REQUIRE that you register the manifest)). 

The fact that an EventSource EMITs this data is however not sufficient, you also need TOOLS to USE the information (instead of looking in the registration database), to complete the picture.   Both PerfView and WPA do this.  Thus these tools ‘just work’ on EventSources and decode their payloads as you would expect.   However decoding the payloads is not the only use of the registration database.   In the Operating system an ETW provider is identify by a GUID and normally will look up the name in the registration database and thus can convert the name to a GUID.   SInce EventSources don’t register themselves, it means that you can’t use an EventSource name to turn the provider on or off.     EventSource solves this by making it possible to FIND the GUID from the NAME without needing a registration database.    It does this by picking a VERY PARTICULAR GUID.   Basically what it does is take the name of the EventSource, capitalize it (to make it case insensitive) and then HASH the name in a standard way (using SHA1), and then use the HASH to form a Guid.  The details are not particularly important, the key is that knowing just the name, you can find the GUID for a EventSource, and it is VERY unlikely that two EventSources will have the same GUID.    

The EventSources also PROVIDE a mechanism to solve the name -> GUID problem but again, tools have to step up and use this.   The PerfView and WPA tools have done this (however at last check XPERF does not).    The convention that both PerfView and WPA use is that a name that is prefixed with a ‘*’ means ‘please hash the name into a GUID using EventSources’s standard hashing mechanism.   This allows you use names when turning providers on and off. 

 OK, with that background, we can apply this knowledge to the XPERF/WPR scenarios. 

The XPERF CASE:

Because XPERF does not support the *Name syntax, you must use the GUID in the XPERF command line.   To do this you need the GUID for the EventSource.   You can get this either by asking your EventSource for its name programmatically (it is the Guid Property on the EventSource), or perhaps easier simply turn on the provider using PerfView with the *Name syntax and then look in PerfVIew’s log for the GUID for the EventSource.   Once you have the GUID you can form the command line.

For example, I determined that for the MinimalEventSource, its GUID was 7370a335-9b9a-5ba0-63c2-8ce045c35503, thus I could turn it on using the command lines

  • xperf -start MySession -on 7370a335-9b9a-5ba0-63c2-8ce045c35503
  • Run your scenario
  • xperf -stop MySession -d output.etl

Which turn on the provider, runs the scenario and stops the provider.  The resulting output.etl file can be viewed with WPA or PerfView.   In WPA the events are in the ‘Generic Events’ view and in PerfView in the ‘events’ view.  

 The WPR CASE:

WPR directly supports the *Name syntax, so you don’t need to deal with the GUIDs.  However sadly unlike XPERF, WPR does not provide a way of adding another provider by passing a command line switch.   Instead you have to create  a WPRP file that describes the provider and its keywords/level and you refer to this WPRP on the command. line.   I have included such a file for the MinimalEventSource provider at the end of this blog.  If you download this you can run the commands

  • WPR -start  MinimalEventSource.wprp
  • Run your scenario
  • WPR -stop output.etl 

Most of this is a recap of this blog entry, which gives more hands-on details.  

MinimalEventSource.wprp

Comments (15)

  1. Manifest data vs. circular buffers says:

    Putting the manifest data in the stream is really great. Not only does it solve the registration problem but it allows a trace to be viewed on a machine that has no knowledge of the provider or has a different version of the provider. Love it.

    One problem I've run into is when the manifest data "falls out" of the buffer. It's written when the provider is turned on but a trace may run long enough that the manifest event ages out. In that case I see just the provider GUID with no details.

    I've had some luck generating a small ETL file with the provider manifest and then using "xperf -merge" to combine it with the ETL file with the events but no manifest, but that's a bit of a hassle.

    Is there a better way? Perhaps the EventSource providers could write the manifest to the stream in the rundown phase?

  2. vancem says:

    The solution to the circular buffer case is to ask the EventSource to dump its manifest again at the end of the trace (where it will be sure to be in the window).   This is just one example of a bunch of 'rundown' that is needed.  ETW supports this with the 'CaptureState' command.  

    PerfView does this for you automatically (if you collect EventSources with 'PerfView collect' it 'just works'.   I believe that you can do this with WPR by using the  <CaptureStateOnSave> in the wprp file (I will see about updating the WPRP file above, but you can do it yourself).  

  3. vancem says:

    I have just updated the MinimalEventSource.wprp associated with this blog to do the capture state.  You can use this as a template if you want your own eventSource events to work with in the circular case

  4. vancem says:

    One mot comment on this.   I mentioned that PerfView does the rundown of EventSource providers for you when it collects data, so that even in the circular buffer case you get manifest information in the file (so that your EventSource events can be decoded).   Well it can only do that if it knows about your EventSource when the trace is being stopped.   For 'PerfView collect' this is always true because you passed the EventSources to the command to get the started, but it does not need to be true if you use the 'PerfView start /Providers:*MySource ' but stop it with just 'PerfView stop'.  Today you have to pass the same set of providrsr to the stop (e.g. PerfView stop /providers:*MySource).     This is a pretty rare case, but I just got asked about it so I figured I would put it on the web for anyone who cares.

  5. Jeremy Quirke says:

    Hi Vance,

    I am still having difficulty getting the EventSource events to "resolve" in WPA with a custom application we are using.

    So I built the test application (Demo2: msdn.microsoft.com/…/system.diagnostics.tracing.eventsource(v=vs.110).aspx) and captured the output using:

    xperf -start MySession -on 659518be-d338-564b-2759-c63c10ef82e2 (the guid is correct per the hashing of "MyCompany").

    I see that perfview 1.6.0.0 shows the MyCompany events.

    But WPA 6.3.9600.16384 still shows the events generically (event ID) (including the manifest ID=65534)

    I also tried capturing with:

    logman start jq -p {659518be-d338-564b-2759-c63c10ef82e2} -o test.etl -ets

    Any idea what this could be?

  6. Jeremy Quirke says:

    One more:

    Interesting, if I capture with PerfView 1.6.0.0 …

    PerfView.exe /OnlyProviders=*MyCompany collect

    … and view with WPA, the "MyCompany' events are resolved (displayed with names, not numbers). My question then is, what is different about the ETL trace that allows WPA to understand the "registration free" event sources?

  7. vancem says:

    The way WPA works is that you have to do an operation called ‘merging’ which adds extra information to the .ETL file that allows WPA to decode the events.    By default WPR and PerfView do that merging, however XPERF has to be told (and logman does not understand the concept).  

    Thus you can collect with PerfView, or WPA, or

    Use the –d FILE.ETL option on your xperf –stop command

    Or use xperf -merge INFILE.ETL OUTFILE.ETL on the same machine after stopping.

  8. Jeremy Quirke says:

    Thanks Vance for your quick response.

    However, I did try this as well in my experiment.

    C:temp>xperf -start MySession -on 659518be-d338-564b-2759-c63c10ef82e2

    C:temp>xperf -stop MySession -d test_vance.etl

    Merged Etl: test_vance.etl

    The trace you have just captured "test_vance.etl" may contain personally identif

    iable information, including but not necessarily limited to paths to files acces

    sed, paths to registry accessed and process names. Exact information depends on

    the events that were logged. Please be aware of this when sharing out this trace

    with other people.

    And again, WPA does not resolve the events, but perfview does.

    Clearly there is enough information in the ETL for perfview to work properly, so I thought this was a problem with WPA.

    Just before I hit submit on this post, I then tried:

    C:temp>where xperf

    C:Program Files (x86)Windows Kits8.0Windows Performance Toolkitxperf.exe

    C:Program Files (x86)Windows Kits8.1Windows Performance Toolkitxperf.exe

    and noticed I was using v8.0 of xperf. I tried again with v8.1 and this made all the difference. I can now see the events in WPA.

    One last comparison showed this event showing up in the xperf 8.1 capture but not in the 8.0 capture.

    <Event MSec=   "915.8874" PID="5212" PName="Process(5212)" TID="10348" EventName="MetaData/EventInfo"

     TimeStamp="08/08/14 17:54:37.794626" ID="Illegal" Version="0" Keywords="0x00000000"

     Level="Always" ProviderName="KernelTraceControl" ProviderGuid="28ad2447-105b-4fe2-9599-e59b2aa9a634" ClassicProvider="True"

     Opcode="32" TaskGuid="bbccf6c1-6cd1-48c4-80ff-839482e37671" PointerSize="4" CPU="0" EventIndex="10">

     <Payload Length="224">

          0:  be 18 95 65 38 d3 4b 56 | 27 59 c6 3c 10 ef 82 e2   …e8.KV 'Y.<….

         70:  4d  0 79  0 43  0 6f  0 | 6d  0 70  0 61  0 6e  0   M.y.C.o. m.p.a.n.

         80:  79  0  0  0 77  0 69  0 | 6e  0 3a  0 49  0 6e  0   y…w.i. n.:.I.n.

    …  </Payload>

    </Event>

    which seems to have the GUID and the friendly name for the class. So I guess WPA is more fussy than Perfview and demands this event.

    Anyway, I'm happy now, thanks again and have a good weekend.

  9. WPR vs XPERF says:

    Why does WPR take so long to save a ETL file? I can wait over 30 minutes to save a 30 second ETL file with WPR.

  10. vancem says:

    You can actually answer this by collecting a trace!     There are two things that WPR does during that save that take a while.  (1) it scans the file for any references to DLL and then finds the PDB signature information (needed to look up symbol names), and inserts it into the file).  The other thing it does is generate symbol information (PDBS) for NGEN images (however once you do this on a particular machine, it will not be done again until those NGEN images change (months).    

  11. Emilian says:

    How to go about dumping this self- describing information from a native provider using mc.exe? I'd probably have to design my own events, etc, and I don't mind doing that as long as I know what to dump so that WPA is happy.

  12. vancem says:

    If your ETW provider that used mc.exe to generate a manifest and registered it (e.g. with wevtutil), then normal WPR (or PerfView) collection  will incorporate the information to decode the events (in WPA or PerfView) into the ETL file.  So you don't need to do anything.

    Of course this has the disadvantage that someone has to register the manifest which means an install step which is often not desirable.   I do note that for windows 10 (and I have been told it will be serviced into to win 7) there is new 'manifest free' logging called TraceLogging for native code (EventSource also uses it).   That is probably the next best thing.

    But it is also possible for you to emit manifests into the event stream in the same way that EventSource does it.  The format is very simple (it is UTF8 manifest, with a very simple 'envelope' so that it can be broken into chunks if need (events are limited to 64K).  You can actually see the details of this by looking at the EventSource code (which is now open sourced as part of CoreCLR (github.com/…/coreclr))

  13. Emilian says:

    I wonder if it makes sense to just write a simple managed tool that uses the EventSource, pretends to be the original provider and dumps an empty event to a log, after which one can go and xperf -merge the two logs in a post-processing step.

  14. vancem says:

    It is not clear what exactly your goal ./ scenario is.   For what it is worth, it is already the case that a ETW controller can simply ask the EventSource to send its manifest and any time it wants.  

  15. Emilian says:

    First, thanks for the comments, I really appreciate your blog and the discussion here.

    And yes, sorry, the scenario is to have a trace log produced by a native ETW provider captured on a machine that doesn't register the provider manifest, then be able to display the decoded events of said provider on a different machine in WPA.

    So as far as I understand, WPA is able to do that kind of manifest-free decoding on traces emitted by EventSources, because they include their manifests in the stream. Since a native provider using the generated headers from mc.exe doesn't do that, I was exploring the options.

    1) I guess one can emulate what EventSource does and have a piece of code that just dumps that information to ETW from the provider at a "convenient" time during the process lifetime, which however isn't well defined since a consumer can start/stop logging at any time during the process lifetime. So a push model for that piece of information wouldn't quite work – the manifest would need to be requested at the controller convenience. I guess that's why EventSources have the kind of functionality that allows for a manifest poll.

    2) A simpler and less complex alternative in my mind would be to do some kind of post-processing on the ETL file, so that the manifest gets attached to the log as though an EventSource produced it.

    2a) One way of doing that would probably be to look at the way the EventSources supply the manifest to the ETW controller, but then you probably need access to the controller source to understand how that information is integrated into the ETL file. You mentioned that this mechanism is simple, with a header of some sort or maybe it's really just an event with a binary payload that contains the manifest – I wouldn't know without looking at the EventSource code.

    2b) I was thinking that an easier solution might be to just have a managed tool which implements an EventSource from the manifest (using maybe the mc.exe generated .cs code), have that provider log one event (a trivialism which is may be unnecessary) and a consumer which writes that event to a log file. The result is a well-formed log file containing the manifest that self-describes it. Since xperf -merge can merge two log files and knows the ETL binary format, you can use it to augment the original ETL log with the new log from the managed tool. That way, to WPA it looks like the augmented log was produced by an EventSource since it already contains the manifest.

    Anyway, I was just trying to see if there's an easy way to get my native component's events to start showing properly in WPA, because WPA and ETW in general are a really useful tool to our team.

    On a separate topic, I was also wondering whether WPA offers an extensibility framework, since I remember reading somewhere that early xperf was supposed to have a COM interface model which allows a component to write a plug in to visualize its events on the analysis timeline of an xperf view.

    Thanks,

    Emilian