Condividi tramite

More on using EventSources with XPERF or WPR

  • Articolo

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

  • Anonymous
    April 20, 2014
    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?

  • Anonymous
    April 21, 2014
    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).  

  • Anonymous
    April 21, 2014
    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

  • Anonymous
    April 22, 2014
    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.

  • Anonymous
    August 07, 2014
    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?

  • Anonymous
    August 07, 2014
    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?

  • Anonymous
    August 07, 2014
    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.

  • Anonymous
    August 07, 2014
    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.

  • Anonymous
    October 03, 2014
    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.

  • Anonymous
    October 03, 2014
    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).    

  • Anonymous
    April 08, 2015
    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.

  • Anonymous
    April 08, 2015
    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))

  • Anonymous
    April 10, 2015
    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.

  • Anonymous
    April 10, 2015
    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.  

  • Anonymous
    April 10, 2015
    The comment has been removed