Getting started with semantic logging

A more traditional style of logging is to write a line of text for any significant event deemed worthy of recording. If there is an issue with the application which requires analysis of the logs, it largely requires someone to scan through the log files (of which there could be many) line by line to piece together the information needed.

Often it can take some time and be difficult, if not impossible, to get the information needed or to correlate the log entries. From experience log messages are often poor quality and added as an afterthought, although with high diligence and agreed rules for writing log messages, it is possible to write high quality logging. However due to the freeform textual nature, it will likely always require a lot of manual effort to review.

Semantic logging is the idea of using strongly typed events to create a consistent log structure. This approach can have a number of benefits. Due to the reliably consistent formatting and structure of the log files, it becomes simpler to query and analyse them. It is easier to automate any parsing of the data, whether that is to facilitate analysis or for consumption by another application or process.

It is easier to correlate log entries from multiple sources.

This post takes a look at some of the tools available in Windows that can help achieve this.

Event Tracing for Windows

Event Tracing for Windows (ETW) is a general purpose and high performance tracing facility provided by the operating system at the kernel level. It was first introduced in Windows 2000 and has grown to become one of the key instrumentation technologies for Windows. It provides a way for recording events both by applications and kernel-mode device drivers. It gives you the ability to enable or disable trace logging on demand.

To use ETW, you need to create an event provider. An event tracing session needs to be created, which can be set up to listen to events from one or more providers. A session can be configured with a number of logging modes, for example writing to a trace file (.etl), writing to the Windows Event Log, or delivering messages real-time to other consumers. This diagram gives an overview of the architecture of ETW:

The events themselves contain a header and event data. The header consists of a number of standard pieces of data such as timestamp, eventid, level, task, opcode, channel and keyword. I won't go into detail as to what each of those pieces of data means here. The event data is arbitrary data added by the provider performing the event logging.

A manifest is required to make any sense of the custom event data. For older ETW consumers, a manifest file must be generated and installed (more detail further down the article). For newer consumers, the manifest information can be read from the event stream itself.

ETW is supported in the .NET Framework and recent additions mean this interface to ETW has changed. .NET 4.5 added the System.Diagnostic.Tracing namespace and classes can derive from its EventSource and EventListener classes for tracing. These classes should be used in preference to any older mechanisms (e.g. TraceSource or EventProvider).

There is also an EventSource NuGet package available. This makes it possible to use EventSource from .NET 4.0 and 3.5, or if the latest and greatest changes to it are required in .NET 4.5 or later. The NuGet package introduces EventSource and related classes in the Microsoft.Diagnostics.Tracing namespace.

Some of the benefits of using the NuGet package are that it adds the ability to write to the Event Log,  generates a manifest at build time, and gives you build time validation of user defined EventSources.

Writing Trace Events

To write trace events, you first need to define a provider. To do this you derive from the EventSource class:

[EventSource(Name="Company-EventLog")]
public sealed class MyEventSource : EventSource
{
  public static MyEventSource Log = new MyEventSource();

  [Event(1, Message="Request submitted: {0}", Channel = EventChannel.Operational)]
  public void RequestSubmitted(string requestId)
  {
    this.WriteEvent(1, requestId);
  }
}

A couple of salient points. The derived class must be sealed. Every public method is treated as a logging method. The methods in this class call to the WriteEvent method and have an eventId, which starts at one and must increment by one for each new method. The EventSource attribute defines the provider name and where the events sit in the Event Viewer if logged there (e.g. Applications and Services Logs > Company > EventLog > Operational).

To use this event source in your application code, you would simply do:

MyEventSource.Log.RequestSubmitted("12345");

If you include the EventSource NuGet package, it will add some guides on how to use it, so read those for more information.

It will also set your project up so that when you build it a myNamespace.myProviderName.etwManifest.man and myNamespace.myProviderName.dll are created. The first message created by a provider is a manifest message, which provides data about how the event is translated into meaningful and readable data. Some consumers can understand this manifest event and immediately consume and understand the events.

Some older consumers require the generated .man file to be installed – the Windows Event Viewer is one of them.

To install or uninstall the manifest, calls to wevtutil.exe can be made:

wevtutil.exe im C:\temp\mynamespace.Company-EventLog.etwManifest.man /rf:"C:\temp\mynamespace.Company-EventLog.etwManifest.dll" /mf:"C:\temp\mynamespace.Company-EventLog.etwManifest.dll"

wevtutil um C:\temp\mynamespace.Company-EventLog.etwManifest.man

To create an etl file for later analysis, the logman tool can be used to create a trace session, then start, stop and delete it. By default this will be written to C:\PerfLogs

logman.exe create trace my-trace-session -p Company-EventLog

logman.exe start my-trace-session

logman.exe stop my-trace-session

logman.exe delete my-trace-session

Consuming Trace Events

Aside from writing to the Event Log or generating a trace (.etl) file as mentioned above, you can define other types of consumer. A couple of ways of doing this would be the Semantic Logging Application Block (SLAB) and Tx (LINQ to Logs and Traces).

SLAB can be used to create an observable event listener for an EventSource, and then define one or more event sinks. There are a number of sinks available out of the box including ConsoleSink, RollingFlatFileSink and SQLDatabaseSink. SLAB can be used in-process or out-of-process. In-process is simple to set up and use but out-of-process can provide other benefits such as resiliency to application crashes and receiving log data from multiple sources.

Tx allows you to do Language Integrated Queries (LINQ) directly over event sources. It is possible to do queries on real-time feeds from ETW sessions as well as on past traces and log files (such as .etl files).

Another option is the Windows Performance Recorder.

Analysing Trace Events

There are a number of tools already available to help you analyse trace events. Here is a brief summary of some of them. You'll want to investigate each to work out which is appropriate for your needs:

• Windows Performance Analyzer is a tool that creates graphs and data tables of ETW events
• PerfView is a performance analysis tool that can be used to both create and analyse etl files. It is a tool used internally at Microsoft and has a lot of options making it rather powerful. The UI is a bit special though!
• SvcPerf is a tool based on Tx. It requires a manifest file to be added. It has a more modern looking UI and can be used from the command line, but is more limited in use than PerfView.
• LINQPad (using the Tx driver) can be used over real-time ETW sessions of .etl files. It is capable of generating the manifest from the event feed and allows ad-hoc querying of the data events.

That concludes this introduction to semantic logging and Event Tracing for Windows. In the next post in the series we take a look at Event stream manipulation using Rx.