Tuesday, November 5, 2013

Transfer Events & Activity Based Logging using EventSource .net 4.5.1

Logs are never looked at in isolation. If we need to look at the log in order to determine the root cause of a problem then it is a particular scenario that we are interested in. With the great testing efforts we do before releasing a product, there might be still some dormant issues which might have been missed. But since they are not apparent and not very easy to reproduce, we are specially interested in the particular order of operations user performed in order to uncover the dormant issue. We need end-to-end tracing support for our .net applications.

Enterprise applications never work in isolation. We have learnt that there cannot ever be a global enterprise system which deals with everything in the Enterprise. So these applications and machines work together in order to accomplish an enterprise operation. That is why everyone has started talking about enterprise integration, I think this would continue to grow.It is possible that our applications perform great in isolation but there are issues when they work together. The only way to uncover such issues is to use the same logging using some identifiers so that we could correlate these operations to understand the scenario.

ETW has long supported the scenario based logging using Transfer Events. You can even find some reference in Park & Buch's article published in 2007 in msdn magazine. The support is provided through tagging these events with Activity Id. The technology supports a scenario based Id (Activity Id), with a related Activity Id for each event.



When .net framework 4.5 was released, the transfer events were missing from the API. EventSource API is based on Manifest based ETW providers rather than the classic provider (no need to register events at install time). This feature has been there for both of these provider. Since technology already supports it, it was just a matter of time to include the support in the API, and .net 4.5.1 does include that support now.

Improvements in EventSource API to support Transfer Events
In order to support transfer events, Microsoft has provided various little updates in EventSource API in .net 4.5.1. Let's start with the EventSource type itself. In order to identify scenario, EventSource is provided with a new property called CurrentThreadActivity. This can be used as the Activity Id for a particular scenario. This is a read-only property. In order to specify the value, there are two modifier methods. This is one of the biggest improvement in .net framework 4.5.1. This is strategic.



We use WriteEvent() method in [Event] methods in order to write events data to ETW infrastructure. There are two new WriteEvent() methods introduced by the same type to include related Activity Id for the operation. The latter of the following methods provides better performance.



Both of these Ids are available through EventWrittenEventArgs in EventListener's OnEventWritten() method. There are two new properties added to the type. The ActivityId is the same as the CurrentActivityId value for the EventSource when WriteEvent() is called; and RelatedActivityId is the value passed as one of the argument to the method.



Sample Event Source with Transfer Events
Let's create a sample C# application using .net framework 4.5.1. Here we are using Visual Studio 2013 RC. The EventSource has two event methods; one of which is TransferEventEx which uses activity Ids.


And here is an EventListener using AcitivityId and RelatedActivityId from EventWrittenEventArgs.


Now we can use the above EventListener to enable the events written using MyEventSource. First we need to set the ActivityId for the scenario, then we need to specify the operation based Id; used as RelatedActivityId.


Transfer Events for Inter-application Enterprise Scenarios
As stated in the beginning, the real benefit of transfer events can be observed tracing end-to-end scenarios performed across application boundaries. The following is an example of a scenario identified by an Id = X (Activity Id). There are three related activities in the scenario tagged with related activity Id (s) identified with A, B and C. These applications can use ETW for their event logs. For the case of EventSource (manifest based provider), these events can be picked up by a central Semantic Logging Service. The data for these events can be pushed to an event store or any other sink of interest.



Download

6 comments:

Pedro Ferreira said...

Hi Muhammad, just found your blog and I'm in heaven with all the ETW posts!

Being used to the WCF way of doing E2E tracing (not sure if specific to WCF but at least used by it), I'm trying to understand how this activity ID gets propagated. Is it linked to the Trace.CorrelationManager.ActivityId?

Also, is there any recommended pattern for transferring between distinct Event Sources?

There is not a lot of info out there on ETW in .NET, especially around best practices and how to organize event sources in a large project. Any tips would be much appreciated

Thanks

Muhammad Shujaat Siddiqi said...

Hi Pedro,

You are right about the difficulties of incorporating the ETW logging in .net applications. Framework 4.5 comes with EventSource, which makes it a lot easier for writing to ETW infrastructure. It uses Manifest based provider which doesn't require any registration. For the transfer events, it uses activity Ids. This was not released as part of .net framework 4.5 but it was later incorporated in 4.5.1. I have given a few talks about the same concepts. I have the links posted in my twitter account. I hope they help.

A casual scribbler said...

Hi Muhammad, Is there a way to write events with Activity ID in the event viewer.

Muhammad Shujaat Siddiqi said...

Apologies for late reply.

I don't think there is separate field for related Activity Id yet. But we can always make it part of the message. See this:
http://www.shujaat.net/2013/09/net-45-eventsource-windows-event-log.html

Ram Nagireddy said...

Hi Muhammad

I was wondering if this applies to Out of Process as well. It would be great help if you can tell how to use activity correlation using out of process or just provide tip can it be achieved. Appreciate your help.

Ram Nagireddy said...

Hi Muhammad

Can you please tell us how can transfer of events activity using out of process logging.