Semantic Logging Application Block (SLAB) 1.1

Activity tracing and sampling

The Semantic Logging Application Block (SLAB) now supports the ActivityId and RelatedActivityId properties available in the .NET Framework version 4.5.1. These properties can be used to correlate events that have been published while handling a specific request, and are available for the various sinks and formatters in SLAB. For more information about activity IDs and correlation see Improve Debugging And Performance Tuning with ETW. SLAB can still be used for .NET 4.5 applications; in that case the activity IDs will just be empty.

The current activity ID is stored as thread-local storage, so once it has been set, all events are tagged with it without changes to the EventSources producing them. This activity ID is set using the SetCurrentThreadActivityId method. Depending on the architecture of your application a current activity ID might have been set by the infrastructure, but your application can choose to provide a new activity ID. In that case a transfer event should be logged linking the two activity IDs using the WriteEventWithRelatedActivityId method instead of the usual WriteEvent method.

When the handling of a given request can spawn more than one thread, for example, when implementing a request handler asynchronously, the activity IDs in all the involved threads must be related to enable proper end-to-end tracing of the request. When using Tasks, each involved thread gets its own activity ID and the Task Parallel Library (TPL) scheduling code publishes the necessary transfer events relating the activity IDs.

Capturing the TPL events in addition to the application events is necessary to properly paint the end-to-end picture when using Tasks. These events are published by an EventSource named System.Threading.Tasks.TplEventSource that is implemented as an internal class. In order to get these events when using SLAB in-process, you can use the new EnableEvent extension method overloads provided by SLAB which take an EventSource name rather than an EventSource instance as shown in the following example:


The TPL produces a few transfer events for each task transition. The following table shows the relevant information from events involved in a specific request implemented asynchronously with Tasks:

ProviderName EventId ActivityId RelatedActivityId
Microsoft-Windows-ASPNET 2 415a6a4f-93ad-4f13-bd82-3abc1cf46940
System.Threading.Tasks.TplEventSource 12 415a6a4f-93ad-4f13-bd82-3abc1cf46940 00000003-0002-0000-ec2f-0000ffdcd7b5
MyEventSource 1 415a6a4f-93ad-4f13-bd82-3abc1cf46940
System.Threading.Tasks.TplEventSource 10 415a6a4f-93ad-4f13-bd82-3abc1cf46940 00000005-0002-0000-ec2f-0000ffdcd7b5
System.Threading.Tasks.TplEventSource 12 415a6a4f-93ad-4f13-bd82-3abc1cf46940 00000006-0002-0000-ec2f-0000ffdcd7b5
MyEventSource 2 00000005-0002-0000-ec2f-0000ffdcd7b5
System.Threading.Tasks.TplEventSource 7 00000005-0002-0000-ec2f-0000ffdcd7b5 00000006-0002-0000-ec2f-0000ffdcd7b5
System.Threading.Tasks.TplEventSource 10 00000006-0002-0000-ec2f-0000ffdcd7b5 00000009-0002-0000-ec2f-0000ffdcd7b5
System.Threading.Tasks.TplEventSource 7 00000006-0002-0000-ec2f-0000ffdcd7b5 0000000a-0002-0000-ec2f-0000ffdcd7b5
System.Threading.Tasks.TplEventSource 7 415a6a4f-93ad-4f13-bd82-3abc1cf46940 00000003-0002-0000-ec2f-0000ffdcd7b5
Microsoft-Windows-ASPNET 3 415a6a4f-93ad-4f13-bd82-3abc1cf46940

Here, one of the TPL events indicates the transfer from activity ID 415a6a4f-93ad-4f13-bd82-3abc1cf46940 to activity ID 00000005-0002-0000-ec2f-0000ffdcd7b5. This event is logged between two events from MyEventSource, the first logged before awaiting on a Task and the second logged after so they have different activity IDs but belong to the same request.

If your application logs relatively few events but has a lot of Task-related operations, the ratio of TPL events to application events might get too high and cause the capacity of the SLAB sinks to be consumed with TPL events. Additionally, the SLAB sinks themselves are implemented using Tasks so their actions produce TPL events which will be captured, too. Sampling can be used to address these data flooding issues to some extent.

When sampling is configured, the involved EventSources only log events from certain requests. When a request is chosen for sampling, all events related to the request are logged regardless of the thread from which they are logged, while requests not chosen for sampling don’t get any events logged for EventSources that participate in sampling.

Sampling is configured by supplying specific parameters when enabling event listeners (when used in-process) or when setting up an Event Tracing for Windows (ETW) session (when out-of-process). There are two ways in which an event source can be involved in sampling: to initiate sampling and to participate in sampling.

To initiate sampling an EventSource must receive the ActivitySamplingStartEvent parameter when enabling events for an EventListener. The value for this parameter is a space-separated list of event specifiers (either the name or the ID of an event) optionally followed by a sampling range. The following snippet illustrates how to supply these parameters:

    new Dictionary<string, string> { 
        { "ActivitySamplingStartEvent", "RequestStarted:10" } 

In the example the RequestStarted event from the EventSource named “Microsoft-Windows-ASPNET” is used to initiate sampling with a rate of 10, that is, 1 out of 10 requests will be sampled. ASP.NET events are a good match for starting sampling since they are directly related to requests, but other events can be used as long as an activity ID is set when they are logged. Different events in an EventSource can start sampling at different rates.

To participate in sampling an EventSource must receive the ActivitySampling parameter with a value of “true” when enabling events for an EventListener. Events from an EventSource configured this way will only be logged when sampling is active in the current thread as the result of events logged from a different EventSource. The following snippet illustrates how to enable sampling for the TPL events:

                new Dictionary<string, string> { 
                    { "ActivitySampling", "true" } 

Not all EventSources are required to participate in sampling. You might choose to sample the TPL events while capturing all your application events. In this case you’ll only be able to correlate your application events for the requests that were sampled, which may or may not be appropriate on a given case.

An added benefit of sampling is that it will likely result in the exclusion of the TPL events originated by the SLAB sinks, as long as no sampling-starting event was logged before the sinks were created. With “1” being a valid sampling rate, you can get the TPL events for all requests and still avoid the TPL events from the sinks.

Sampling with SLAB can only be configured programmatically using SLAB in-process; there is no out-of-process mechanism to configure sampling. If the TPL event source is configured when using SLAB out of process the sinks will get all TPL events in the system (including those originated in SLAB’s sinks themselves). Because of this, capturing TPL events when using SLAB out-of-process is not supported in the current version.

Known issues:
  • Activity tracing does not work in certain circumstances when running on Windows 8 or Windows Server 2012. This is a known issue that will be fixed in an upcoming .NET 4.5.1 servicing release.
  • The database sink requires a schema update to include the new columns for activity IDs.

Last edited Mar 27, 2014 at 8:18 PM by gmelnik, version 11