Cloud Zone is brought to you in partnership with:

Neil Mackenzie is a Cloud Solution Architect for Microsoft. He has worked with computers for three decades. Neil started by doing large-scale numerical simulations for scientific research and business planning. Since then, he has primarily been involved in healthcare software, developing electronic medical record systems. He has been using Microsoft Azure since PDC 2008, and has used nearly all parts of the Azure platform — including those parts that no longer exist. Prior to joining Microsoft, Neil was a Microsoft MVP for Azure. Neil is a DZone MVB and is not an employee of DZone and has posted 17 posts at DZone. You can read more from them at their website. View Full User Profile

Semantic Logging Application Block (SLAB)

08.14.2013
| 3287 views |
  • submit to reddit

The use of elastically-scalable cloud services makes it more important than ever that services be monitored appropriately so that diagnostic information is available when needed. This can be seen in the way that Windows Azure Diagnostics (WAD) is a core feature of Windows Azure, since WAD provides a unified way to capture and persist various types of diagnostic information.

For many years, Windows has supported the tracing of applications through the Trace class in the Systems.Diagnostics namespace. This class exposes methods such as Write(), TraceInformation() and TraceError() that can be used to write events, which can then be captured and persisted by a listener. WAD, for example, provides a listener that persists these events to Windows Azure Tables.

The Trace class has a number of failings, including the absence of any structure to the captured information and the need to decide at the point of use information such as the severity (Warning, Error, etc.) of the event. This means that the same message could be used in different places with different severity levels, increasing the complexity of basing decisions on a trace event.

The EventSource class, in the System.Diagnostics.Tracing namespace, was introduced in .NET 4.5 to support structured logging. Rather than use methods like TraceInformation() to trace events, a set of strongly-typed methods is used to trace events. These methods reside in an application-specific class derived from EventSource. The resulting events are processed using the Event Tracing for Windows (ETW) mechanism, a high-performance trace-logging system widely used by the Windows infrastructure. ETW maintains the strong-typing of events, making the event information much more useful to consumers. The PerfView utility can be used to view any ETW event generated on a system.

The Microsoft Patterns and Practices Enterprise Library v6 introduced the Semantic logging Application Block (SLAB) that provides a set of EventSource consumers (listeners) that can be used to persist EventSource events to various sinks including flat files, SQL Server and Windows Azure tables. The latter could be used, for example, with an appropriately instrumented application deployed to Windows Azure Virtual Machines to persist trace information to a table where it could then be processed without the need to access the compute instance.

Dominic Betts has an excellent Channel 9 video describing SLAB. Grigori Melnik has a post on Embracing Semantic Logging. Vance Morrison, who seems to have the go-to blog for all things ETW, has a short introductory post on SLAB. Julian Dominguez did a presentation at Build 2013 on Creating Structured and Meaningful Logs with Semantic Logging. Mark Simms has a video on Design For Manageability, in the awesome Failsafe: Building Scalable, Resilient Cloud Services series, in which he provides motivation for instrumenting applications with more telemetry logging than you had likely dreamed of. Kathleen Dollard has a PluralSight course covering new features of .NET 4.5, including EventSource, which she also covers in this post.

The CTP version of the SLAB documentation can be found on CodePlex. The documentation downloads include a very readable Developer's Guide (pdf) and an extensive Reference Guide (pdf). The preview version of the complete Developer's Guide to Microsoft Enterprise Library documentation is downloadable from here.

The Enterprise Library v6 home page on CodePlex contains links to downloads and documentation. In v6, the various blocks have been partitioned so they can be installed independently of each other from NuGet. These include individual blocks like the Transient Fault Handling Block and the Semantic Logging Application Block. There are three SLAB downloads on NuGet (search for “semantic logging application block”): the core SLAB functionality, a Windows Azure Sink and a SQL Server Sink. The two sinks allow EventSource events to be persisted to Windows Azure Tables and SQL Server respectively.

EventSource

Event Tracing for Windows (ETW) is a kernel-level logging engine for Windows that has been around for several years, seemingly without garnering much attention outside Microsoft. Many Windows Services use ETW for tracing. Indeed, Mike Kelly describes in an MSDN article how ETW is used by Windows Azure Diagnostics.

One reason for the obscurity of ETW was the difficulty of creating event sources. The .NET 4.5 EventSource  class makes it really easy to create event sources. This allows an event source to be created merely by deriving a new class from EventSource, creating the trace-writing methods and exposing them through a singleton EventSource.

A single EventSource may have many trace-writing methods. These are defined on a separation of concerns basis. The parameter list, provided to the EventSource user, captures only the core information for the event. The filtering properties (level, keywords, etc.) for the event are specified at design time and are not specified by the EventSource user.

The following gist contains a simple example of an EventSource class:

using System;
using System.Collections.Generic;
[EventSource(Name = "MyDomain-MyEventSource")]
public class MyEventSource : EventSource
{
   public class Keywords
   {
      public const EventKeywords Database = (EventKeywords)1;
      public const EventKeywords ExternalApi = (EventKeywords)2;
   }

   public class Tasks
   {
      public const EventTask Timing = (EventTask)1;
   }

   [Event(1,
      Message = "Method entry: {0}",
      Level = EventLevel.Verbose)]
   internal void MethodEntry(String message)
   {
      if (IsEnabled()) WriteEvent(1, message);
   }

   [Event(2,
      Message = "External call to {0}/{1} - TimeSpan: {2}",
      Level = EventLevel.Informational,
      Keywords = Keywords.ExternalApi, 
      Task=Tasks.Timing)]
   internal void ApiTiming(String apiName, String apiOperation, Int64 elapsedTimeMilliSeconds)
   {
      if (IsEnabled()) WriteEvent(2, apiName, apiOperation, elapsedTimeMilliSeconds);
   }

   [Event(3,
      Message = "Invalid configuration entry: {0}",
      Level = EventLevel.Warning)]
   internal void MissingConfigurationEntry(String entryName)
   {
      if (IsEnabled()) WriteEvent(3, entryName);
   }

   public static readonly MyEventSource Log = new MyEventSource();
}


The EventSource attribute is used to provide an alternative name for the EventSource, otherwise the class name is used. This name needs to be unique across all systems, so it should include a corporate namespace, e.g., MyDomain-MyEventSource.

The Keywords and Tasks classes provide enumerations used initially to decorate event definitions and then to provide a structured filtering capability for ETW consumers. This allows the various events to be filtered by different listeners, e.g., a listener could listen only to Timing events for ExternalApi calls. EventKeywords and EventTask are enumerations, the values of which can be overridden. Another class, OpCodes, can also be used – along with an accompanying EventOpCode enumeration. The various enumerations are bitwise so that multiple Keywords, for example, can be aggregated for a single event. Note that, if used, the class names must be Keywords, Tasks and OpCodes.

Each event is decorated with an Event attribute that provides schema information for the event. An event is identified by the EventId, a unique (one-based) sequential integer. The Message property specifies a string used to format the message text for the event. The Level property specifies the level (Informational, Warning, Error, etc.) for the event. The Keywords, Tasks and Opcodes specify values from the classes defined earlier.

The core of an event definition is the method used to record it. The method parameter list captures all the information for the event. It invokes a heavily overloaded WriteEvent() method to write the event. The first parameter to the WriteEvent() method is an integer that must be the same as the EventId, otherwise the event will silently not be written. The IsEnabled() method on the EventSource class can be used to avoid writing the event when the EventSource is disabled.

The EventSource class is completed by the creation of a singleton static instance used to expose the event-writing methods. This can be used to write an event as follows:

MyEventSource.Log.ApiTiming(
   “Twitter”,
   “GET statuses/home_timeline”,
   stopwatch.ElapsedMilliseconds);

This writes the event to the ETW log from where it can be retrieved by a listener. The event is written in structured form allowing it to be subsequently recreated in a type-consistent manner, which simplifies the subsequent analysis of the event. The event can contain a human-readable message as well as the actual data used to compose the message.

The PerfView utility can be used to view the events created by the EventSource. When initiating the data collection using PerfView, the name of the EventSource can be provided with a * prefix (as an Additional Provider in the Advanced Options) – i.e., *MyDomain-MyEventSource. PerfView is a powerful ETW utility that comes with extensive documentation showing how to use it for analyzing ETW event logs. These contain a wealth of information about a running system since many Windows subsystems contain ETW instrumentation.

This section is standard ETW that makes no use whatsoever of SLAB.

Semantic Logging Application Block (SLAB)

SLAB builds on standard ETW by providing in-process and out-of process listeners that persist an ETW EventSource to a one or more of:

  • Console
  • Flat file
  • Rolling file
  • SQL Server
  • Generic database 
  • Window Azure tables

As of this writing, SLAB does not support persisting events to the Windows Event Log. Note that the use of SQL Server/Generic database or Windows Azure tables requires the appropriate supplementary NuGet SLAB download.

SLAB provides source code that can be used as a base for developing additional listeners. It also exposes extension points supporting the customization of message formatting.

In-process

The use of an in-process listener requires the creation and enablement of an EventListener. For example:

    EventListener consoleEventListener = ConsoleLog.CreateListener();

    consoleEventListener.EnableEvents(
       MyEventSource.Log,
       EventLevel.LogAlways,
       Keywords.ExternalApi);

In this example, MyEventSource is the class name for the event source and the listener is filtered to only persist events defined with the ExternalApi keyword. When no longer needed, the EventListener can be disabled and disposed of as follows:

consoleEventListener.DisableEvents(MyEventSource.Log);
consoleEventListener.Dispose();

And that is all that is required to host an in-process SLAB event listener. The various listeners provided by SLAB are all used as above with the proviso that some configuration is required, such as the filename for a file listener or the connection string for a Windows Azure storage account.

Out-of Process

SLAB provides a separate download (SemanticLogging-svc.exe) that can be run either as a console application or a Windows Service. The various SLAB listeners can be configured, in SemanticLogging-svc.xml, to persist the EventSource events to one of the supported sinks – the same list as an in-process. The advantage of doing this out-of-process is that the monitored application has no SLAB dependency – since EventSource is a a pure ETW feature – and does not suffer any performance degradation from the in-process use of SLAB.

The out-of-process configuration requires the specification of the EventSource and one or more listeners to it. The following example shows the SemanticLogging-svc.xml configuration of a Windows Azure Sink that persists all events, of Verbose or higher-level from an event source named MyEventSource, to the local storage emulator:

    <eventSource name=”MyEventSource”>
       <eventListeners>
          <eventListener name=”azureTable” level=”Verbose” />
       </eventListeners>
    </eventSource>

    <eventListeners>
       <azureTableEventListener name=”azureTable”
          instanceName=”myInstanceName”
          connectionString=”UseDevelopmentStorage=true”/>
    </eventListeners>

Windows Azure Table Listener

The Windows Azure Table Listener persists events to a Windows Azure table. By default, the table is named SLABLogsTable and the data is persisted every 10 seconds. The listener stores the following properties:

  • PartitionKey
  • RowKey
  • Timestamp
  • EventId
  • EventDate
  • Keywords
  • EventSourceGuid
  • EventSourceName
  • InstanceName
  • Level
  • Message
  • Opcode
  • Task

The listener takes advantage of the schema-less nature of Windows Azure Tables to also store the actual parameters provided when the event was created. The PartitionKey is generated as a per-minute bucket using DateTime.Ticks. The RowKey comprises the instance name, the Ticks count for the event, and an appended salt to guarantee uniqueness. By default, the PartitionKey and RowKey tweak the Ticks count so that the data is stored in reverse chronological order.

Summary

ETW provides a powerful way to trace applications in a structured way. The EventSource class, new in .NET 4.5, makes it really easy to use ETW. The Semantic Logging Application Block provides a number of listeners that can be used to consumer EventSource events and persist them to various locations, including Windows Azure tables.


Published at DZone with permission of Neil Mackenzie, author and DZone MVB. (source)

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)