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.