Dela via

ETW in C#: Controlling which events get logged in an System.Diagnostics.Tracing.EventSource

  • Artikel

In my EventSource demo blog entry we defined an EventSource and turned on the logging with the command

PerfView /OnlyProviders=*MinimalEventSource run eventSourceDemo.exe

Which turned on all the events defined in the 'MinimalEventSource' we defined.    As you add more events to your EventSource, it becomes more and more likely that you will want more control over which events get logged.   In this blog, I will show you how to do this.  

Event Tracing for Windows (ETW) defines two mechanisms for controlling which events actually log their content.   Each event is tagged with two quantities:

  1. A small integer (enumeration) called a 'Level' which defines how verbose the event is.  Levels go from 0 to 5:   0 (Always) 1 (Critical) 2 (Error) 3 (Warning) 4 (Information) 5 (Verbose).  The default is 4 (Informational).   When the provider is turned on a level is specified Only those events that are less than or equal to the specified level will log messages. 
  2. A 64 bit, bit-vector called the events 'Keywords' which define 64 groups that an event can belong to.   When the provider is turned on a a set of keywords is passed in.  Only those events whose keywords overlap with the passed in keywords will log messages. 

 To see how to use these characteristics in your own eventSource consider the EventSource Example below.  

                [EventSource(Name = "MyCompany-WebServices")]
                internal sealed class MyCompanyEventSource : EventSource
                {
                    [Event(1, Keywords = Keywords.Requests)]
                    public void RequestStarted(string Url, int RequestID) { WriteEvent(1, Url, RequestID); }
       
                    [Event(2, Keywords = Keywords.Requests, Level = EventLevel.Verbose)]
                    public void RequestPhase(int RequestID, string PhaseName) { WriteEvent(2, RequestID, PhaseName); }
       
                    [Event(3, Keywords = Keywords.Requests)]
                    public void RequestCompleted(int RequestID) { WriteEvent(3, RequestID); }
       
                    [Event(4, Keywords = Keywords.Debug)]
                    public void DebugTrace(string Message) { WriteEvent(4, Message); }
       
                    public class Keywords // This is a bitvector
                    {
                        public const EventKeywords Requests = (EventKeywords)0x0001;
                        public const EventKeywords Debug = (EventKeywords)0x0002;
                    }
                    static public MyCompanyEventSource Logger = new MyCompanyEventSource();
}

 In this example, we define a 'MyComanyEventSource' and define a static instance of it (in brown at the bottom).   This EventSource has 4 events defined, and you can see that each of these events is 'Decorated' with an 'Event' Attribute which tells the EventSource base class more about the particular event.   These Event Attributes contain

  1. The Event Number.  Each event is given a unique number.  This is the same number that is passed to the first parameter of the 'WriteEvent' method in the event's body.  
  2. A set of additional ETW 'decorations' (Properties) for that event.   In this case we use two additional properties
    1. The 'Keywords' property indicates the keywords bitvector for the event (in blue).  You can see that we define two keywords: Requests, and Debug. 
    2. The 'Level' property indicates the level (verbosity) for the event.  By default is is 'Informational' but in the example above we made 'RequestPhase' a verbose event.

In addition to the event definitions themselves, there is also a nested class called 'Keywords' (you MUST use this name and it MUST be nested) which defined the numeric values for the keywords used in the event definitions.   Each of these should be a binary bit in the 64 bit long value.  

This example assumes that we have two event groups.  The first group (the 'Request' group) tracks a request as it journeys through the system.  Notice only the RequestStart event has the URL associated with the request.  The other events use a small integer value that is faster to write to indicate which exact events is being logged.   There is one verbose method (RequestPhase) which is meant mean for verbose diagnostic purposes and is often not needed.    The other group (the 'Debug') group has only one event DebugTrace that is meant for ad-hoc 'printf-sytle' diagnosis. 

Finally, the EventSource above follows a 'best practice' of naming its ETW provider a good name FROM THE U SER's POINT OF VIEW.   Names should at least start with your company name.  If you expect more than one EventSource for your company it is best to give them categories separated by '-'.   This is the convention that Microsoft has been following for the last several years.  (e.g. Microsoft-Windows-DotNetRuntime).  In the example above we named the provider 'MyCompany-WebServices'.   Please carefully consider this name as if you change it, it will break any users of your EventSource. 

The 'PerfView tool' supports using  levels and keywords with the following syntax.  

  • provider : keywords : level

You can add these at the command line or in the 'Additional Providers' textbox in the 'Advanced Options' section of the collection dialog.  By default PerfView turns on ALL keywords and the VERBOSE level, so the command

PerfView /OnlyProviders=*MyCompany-WebServices collect

Turns on all the events.   You can use '*' for the keyword to represent 'all' keywords so the command

PerfView /OnlyProviders=*MyCompany-WebServices:*:Information collect

Turns on all keywords (the :*:) that are a verbosity of Informational or below.  Thus this turns off the Verbose 'RequestPhase' event.   Currently PerfView does not support using the names of keywords, so you have to specify the keywords as a (hex) number.  Thus the command

PerfView /OnlyProviders=*MyCompany-WebServices:2 collect

Collects only the 'Debug' keyword events (at a Verbose level). 

Best Practices: Keep it Simple from the users point of view!!

Now that you have the ability to finely control which events are emitted, I am going to do something very surprising: I am going to tell you to NOT use it most of the time.  The reason is simple:  Users of your events are FAR more concerned about ease of use than they are about optimizing the size of data collected.    It is FAR more frustrating to not have the events you need than to have too many.  Really the ONLY time people will care is when the events are VERY verbose.   This leads to the following strategy

  • Events that fire less than 100 times a second on average are 'too small to care about'  Don't bother making special keywords for them, but make a catch all 'Default' keyword.
  • Events that fire more than 1K times a second on average need keywords to turn them off if they are not needed.
  • Events in between 100 and 1K are a judgement call
  • Define keywords from a USERS (or scenario) point of view.   Users don't like to set more than one keyword (too error prone) so define the keywords that all common scenarios can be done by setting a single keyword.   Most users will use simply use the default (turn everything on).  
  • Levels less than Informational are meant for relatively rare warnings or errors.   When in doubt stick with the default of Informational, and use verbose for events that can happen more than 1K events / second.    Typically users use Keywords much more than Level, so don't worry about it too much. 

For more best practices and features of EventSources, see the EventSource specification.  

 Again it is your turn, time to try it out!

If you have not already gone to my EventSource demo blog entry and built the VS 2010 demo, you can do that now.   You can try out the example above if you like or simply take a look at the 'MyCompanyEventSource' class in the  'AdvancedUsageDemo.cs' file.    As mentioned this demo works today (because it comes with EventSource.dll which defined EventSource), but will be even easier in a few months when V4.5 of the .NET Runtime ships and EventSource is available in the framework)

Review

Here are some other useful blog entries on EventSource:

  1. Introduction to EventSource 
  2. EventSource specification
  3. When you should be using EventSource

Comments

  • Anonymous
    August 14, 2012
    I've been trying to work with ETW in 4.5 RC and have been following your posts closely (as there isn't much else out there). EventSource'ing is very easy and much better than having to create manifests etc as previous. My one big question is can/how to create a second custom application that can be the ETW controller and consumer of real time events. I would love to be able to write my own custom viewer for my custom events so that they can be displayed in a visually friendly manner (graphs, charts, etc). I've not found anything anywhere. Is this even possible with 4.5 or would this have to be c++? I was originally hoping that EventListner would do this, but it seems that only provides an outlet within the same assembly. thanks

  • Anonymous
    August 15, 2012
    The comment has been removed

  • Anonymous
    August 15, 2012
    Thank you so much for the reply. I will look into the TraceEvent library and see what I can do right now. Using ETW with a custom viewer is a definite need for us. It's not critical right now to have the viewer, but will be sooner rather than later. I'll let you know if i have any questions.

  • Anonymous
    August 16, 2012
    So I've been playing around with extending PerfView with some success using Kernel events. However, I'm a bit stuck with trying to watch only my custom ETW eventsources. You suggest using DynamicTraceEventParser and some functions on that class. However, the PayloadByName is defined in the TraceEvent class. I'm kind of at a loss as to how to correctly instantiate the DynamicTraceEventParser with a TraceSource for my custom events. Do I need to define my own TraceSource and/or TraceEventDispatcher /TraceEvent? Thanks again.

  • Anonymous
    August 16, 2012
    The quick answer is that you need register your callback just like for the Kernel ones you did     var dynamicParser = yourTraceSource.Dynamic;     dynamciParser.All += delegate(TraceEvent data) {           // your code,  now data.PayloadByName will work....      }; This fits the general model: TraceEventDispatcher act as a 'push model' list of events.  It does not know how to parse events.   Instead you register TraceEventParsers with them each of which handle some SUBSET of hthe event stream.   In your case you want to regsiter the DynamicParser (which knows how to parse EventSources) and you can achive this registration as a side effect of calling the Dynamic Property).   Your code subscribes to C# events  that represent individual PARSED events.   Normally these C# events  are strongly typed and there is one per event, but the DynamicTraceEventParser can't do this.  It only has the 'All' event, which represent any event this parser knows about (all event soruces).    By the time this callback is fired, the event has been parsed, and thus properties like EventName, TaskName, OPcodeName, and the PayloadByName functions work (assuming is is an eventSource, It has to get the schema SOMEHOW).   Note that while TraceEventDispatcher has an EveryEvent C# event, normally you don't use this because it will NOT be parsed (since there is no parser, dispatcher don't know how to parse, that is the parser's job).   Vance

  • Anonymous
    August 27, 2012
    The comment has been removed

  • Anonymous
    August 28, 2012
    The comment has been removed

  • Anonymous
    August 29, 2012
    Hello and thanks for the feedback In terms of tooling i'm primarily working with the the Event Viewer control panel. The default view you get is at least 90% of what my coworkers will look at. Event viewer has user interface for filtering on all of the pre-defined etw fields (and you can even write xpath queries over the custom payload, though most people are unlikely to do this). Maybe teaching people how to use perfview would be a rationale step here. As it stands i still haven't found a way to use any of the existing ETW fields though. The rigid message structure requires a lot of up-front cost to add diversity to the log messages. Adding to the custom payload is easy, and adds to the diversity, but seems to be the naiive approach when ETW already provides places to put 'similar' information. I imagine separate providers for different classes / namespaces would really be the appropriate way to solve my problem. With a manifest based provider, setting up the manifests can be really cumbersome though. I am still thinking on whether this would be much easier with an EventSource, and you haven't covered how inheritance of EventSource classes works yet :)

  • Anonymous
    August 29, 2012
    The comment has been removed

  • Anonymous
    August 29, 2012
    The comment has been removed

  • Anonymous
    January 20, 2013
    I recently started following your blog and each article is short, precise and explaining one concept. Your samples are very helpful. I could create a sample solution based on your samples with the exception of custom parser. Do you have any article that explains how to create a custom parser? I saw some sample parsers in TraceEvent project. Any step by step article by taking a custom EventSource would be beneficial. Is the tool mentioned in this article "traceParserGen" available in any form?

  • Anonymous
    January 21, 2013
    Indeed custom parsers have not been discussed yet for a reason.    The reason is that custom parsers should not be created by hand, but rather generated from manifest (that is once you have the type information in the manifest you can make the parser automatically).    We have an internal tool called 'traceParserGen' that does this.   I have not blogged about it because it is not externally available (yet).    It is not available mostly because it is not user friendly enough (if your manifest is not just they way it likes it, errors with unfriendly diagnostics result).    At some point soon I will fix the most problematic of this unfriendliness and publish something, but until that time I don't want to blog about it.    It turns out that almost all of the TraceEventParsers in the TraceEvent library were generated with this tool, so you can get a good feel for what the tool would do simply by looking at some of the TraceEventParsers in TraceEvent.dll.   If this is really blocking you I can send you it 'as is' but you will have to live minimal docs and no demo.  

  • Anonymous
    January 21, 2013
    I apprecaite you sharing the information. My need is, to create application specific parsers that parse Error, Warning events and log to a common database. Towards this, custom parser really helps me. You can share the tool to my email nutulapati@hotmail.com OR sreenivasu.nutulapati@lpsvcs.com.

  • Anonymous
    February 18, 2013
    This is good information. I have this question: can I use negative values in my Keywords enum ?        public class Keywords        {            public const EventKeywords Page = (EventKeywords)1;            public const EventKeywords Database = (EventKeywords)2;            public const EventKeywords Neg = (EventKeywords)(-1); }

  • Anonymous
    February 18, 2013
    Keywords are interpreted as a bit-vector.   Thus as you add single keywords they should be a power of 2.   There already is EventKeywords.All which is defined to be -1 (all 1s).   I can't imagine it being useful to specify a negative number besides -1.  

  • Anonymous
    May 05, 2015
    The comment has been removed

  • Anonymous
    May 05, 2015
    @BillH   Keep in mind that the Keywords class does not modify the 'EvenKeywords' type, it only adds contants (that the type does not know about).  Thus you can't expect intellisense or the debugger to know about your new Login value.    To confirm that the value is being passed correctly, create a local variable that you assign Keywords.Login to and then check it in the debugger (or send to Trace.WriteLine), to see its value.   .  

  • Anonymous
    May 05, 2015
    I just set a test variable, and it says the value for the Keywords is 'None'.  The attribute has the Keywords set to 'Login'.  It seems the attribute is not setting the Keywords value somehow??

  • Anonymous
    May 06, 2015
    So the code problem that I posted works now, with one change. I moved the 'Keywords' class to still be nested, but at the bottom of the containing class. Should I always put the 'Keywords' class last??

  • Anonymous
    May 06, 2015
    I am glad you got it working.   I can't explain your result however.   Order should not have mattered.  

  • Anonymous
    December 16, 2015
    The comment has been removed

  • Anonymous
    January 20, 2016
    @Vidhi Every method that I've seen so far follows the rule that the WriteEvent contains the same parameters (+ id at the beginning) as the method signature. Yours should look like WriteEvent(1, id, strMessage).

  • Anonymous
    January 21, 2016
    I see that I missed this comment back in December (I was out of the office).   As @stej indicates however, it is an error not to pass exactly the same arguments through to WriteEvent as are declared in the method (The serializer determines what to serialize by reflection on the signature. If you wish to pass additional information then you need to make a private method that has ALL the information you want to pass, and then a [NonEvent] method that you actually call from your instrumentation site that then calls the private method with  the extra information.