A Look at ETW – Part 3

In part two of this series on Event Tracing for Windows I wrote a simple EventSource to provide strongly-typed events with Entity Framework interceptors. After playing around with ETW a bit more, and still frustrated by the documentation, I decided to switch gears and do something fun, so here in part 3 I’ll try using ETW in an AOP solution.

AOP is of course a great fit for a cross-cutting concern like logging or tracing, and my AOP framework of choice, PostSharp, actually already has a Diagnostics Pattern Library which supports logging to trace, the console, NLog, Log4Net and the Enterprise Library Logging Application Block, but since there’s no built-in support for ETW I’ll get to write my own aspect.

In addition to using AOP for method entry-exit tracing, I also like how tools such as Azure Application Insights and Xamarin Insights make it easy to wrap a block of code in a using statement for tracing purposes, and want to do something similar with ETW. E.g., in Xamarin Insights:

using (var handle = Insights.TrackTime("something")) {
   .. stuff to track
}

Since I want to reuse these features I’ll bundle this up in a .NET library, and because naming things continues to be really hard, call it “SampleAnalytics”. The only dependencies are the NuGet packages for Microsoft.Diagnostics.Tracing.EventSource and PostSharp.

The EventSource

Although a strength of ETW is its strongly-typed events, after seeing several examples which use more “generic” events yet still benefit from ETW and its tooling, I’m going to try that and go with a few general-purpose events.

Several of the logging frameworks use the concept of “category” (or a dictionary of categories), so I’ve decided that might be useful here too. Since I want to trace both methods and code blocks I use “Action” and “actionName” to designate either. I also want to make timing optional: ETW events have a high-resolution timestamp and some tools will pair up start/stop events, so doing my own timing isn’t always necessary. If there’s no listener on my ETW events it’s also inefficient.

So the EventSource starts taking shape.

[EventSource(Name = "Samples-Analytics")]
public sealed class AnalyticsEventSource : EventSource {

  public static readonly AnalyticsEventSource Log = new AnalyticsEventSource();

  public class Tasks {
    public const EventTask TimedAction = (EventTask)0x1;
    public const EventTask Action = (EventTask)0x2;
  }

  private const int TraceActionTimedStartEventId = 1;
  private const int TraceActionTimedStopEventId = 2;
  private const int TraceActionStartEventId = 3;
  private const int TraceActionStopEventId = 4;

  [Event(TraceActionTimedStartEventId, Level = EventLevel.Verbose, Task = Tasks.TimedAction, Opcode = EventOpcode.Start)]
  public void TraceActionTimedStart(string category, string actionName) {
    WriteEvent(TraceActionTimedStartEventId, category, actionName);
  }

  [Event(TraceActionTimedStopEventId, Message = "Category '{0}' - Action '{1}' took {2} ms", Level = EventLevel.Verbose, Task = Tasks.TimedAction, Opcode = EventOpcode.Stop)]
  public void TraceActionTimedStop(string category, string actionName, long elapsedMilliseconds) {
    WriteEvent(TraceActionTimedStopEventId, category, actionName, elapsedMilliseconds);
  }

  [Event(TraceActionStartEventId, Level = EventLevel.Verbose, Task = Tasks.Action, Opcode = EventOpcode.Start)]
  public void TraceActionStart(string category, string actionName) {
    WriteEvent(TraceActionStartEventId, category, actionName);
  }

  [Event(TraceActionStopEventId, Level = EventLevel.Verbose, Task = Tasks.Action, Opcode = EventOpcode.Stop)]
  public void TraceActionStop(string category, string actionName) {
    WriteEvent(TraceActionStopEventId, category, actionName);
  }
}

This wasn’t quite as simple as it appears, since I found that an overload for WriteEvent(int, string, string, long) doesn’t exist in the base EventSource and needed to write it myself. This involved pointers and unsafe code, and the curious can see the code download for details.

Tracing code blocks

I’ll be doing tracing of both timed and untimed “actions”, so define a disposable TraceAction and TimedAction.

public interface ITraceAction : IDisposable {
  void Start();
  void Stop();
}

Untimed actions generate start and stop events:

public class TraceAction : ITraceAction {

  private readonly string _category;
  private readonly string _actionName;

  internal TraceAction(string category, string actionName) {
    _category = category;
    _actionName = actionName;
  }

  public void Start() {
    AnalyticsEventSource.Log.TraceActionStart(_category, _actionName);
  }

  public void Stop() {
    AnalyticsEventSource.Log.TraceActionStop(_category, _actionName);
  }

  public void Dispose() {
    Stop();
  }
}

While timed actions also use a Stopwatch:

public class TimedAction : ITraceAction {

  private readonly string _category;
  private readonly string _actionName;
  private Stopwatch _stopwatch;

  internal TimedAction(string category, string actionName) {
    _category = category;
    _actionName = actionName;
  }

  public void Start() {
    AnalyticsEventSource.Log.TraceActionTimedStart(_category, _actionName);
    _stopwatch = Stopwatch.StartNew();
  }

  public void Stop() {
    if (_stopwatch == null || !_stopwatch.IsRunning) return;
    _stopwatch.Stop();
    AnalyticsEventSource.Log.TraceActionTimedStop(_category, _actionName, _stopwatch.ElapsedMilliseconds);
  }

  public void Dispose() {
    Stop();
  }
}

Along with a helper class…

public static class Analytics {

  public static ITraceAction TrackTime(string actionName, string category = "Trace") {
    var action = new TimedAction(category, actionName);
    action.Start();
    return action;
  }

  public static ITraceAction TrackUntimed(string actionName, string category = "Trace") {
    var action = new TraceAction(category, actionName);
    action.Start();
    return action;
  }
}

 
With these in place I can now trace a block of code like this:

using (var timedAction = Analytics.TrackTime("Save Student")) {
  db.SaveChanges();
}

For method-level interception I’ll need AOP.

Tracing methods

PostSharp provides method interception with the OnMethodBoundaryAspect. They have a good amount of documentation showing how to use it so it’s very easy to get started. All that’s necessary is to sub-class the aspect and override any needed interception points:

public class SomeCustomAttribute : OnMethodBoundaryAspect {
 public override void OnEntry(MethodExecutionArgs args) ..
 public override void OnExit(MethodExecutionArgs args) ..
 public override void OnSuccess(MethodExecutionArgs args) ..
 public override void OnException(MethodExecutionArgs args) ..
 public override void OnYield(MethodExecutionArgs args) ..
 public override void OnResume(MethodExecutionArgs args) ..
}

I still want to use a “category” to help apply some semantic information to events, and timing should be optional here too. Both parameters can be set when the attribute is applied.

[Serializable]
public class ETWTraceAttribute : OnMethodBoundaryAspect {

  private string _methodName;
  private string _category;
  private bool _addTiming;

  public ETWTraceAttribute(string category = "default", bool addTiming = false) {
    ApplyToStateMachine = true;
    _category = category;
    _addTiming = addTiming;
  }

For example, applied to a method:

[ETWTrace(category: "Instructor")]
public ActionResult Index(int? id, int? courseID) {..}

And applied to a class:

[ETWTrace(category: "Course", addTiming: true)]
public class CourseController : Controller {..}

 
I’ll also grab the method information at compile-time rather than run-time, as it’s more efficient. I could have grabbed parameter and generic arguments too, but I’m not sure that the extra information will help when doing an ETW analysis so I’ve left them out for now:

public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo) {
  _methodName = method.DeclaringType.FullName + "." + method.Name;
}

At run-time, tracing should start when the method starts. The parameter values are available here too, but since the ETW event won’t be enabled without a listener I don’t want to incur any performance penalty in getting their string representation. The TrackTime and TrackUntimed helper methods defined above can be used here too, and the ITraceAction stashed within the MethodExecutionTag for later use.

public override void OnEntry(MethodExecutionArgs args) {
  var action = _addTiming ? Analytics.TrackTime(_methodName, _category)
                          : Analytics.TrackUntimed(_methodName, _category);
  args.MethodExecutionTag = action;
}

When the method completes successfully I’ll stop tracing. The method return value is available here also, but again, I don’t want to include it in the ETW event:

public override void OnSuccess(MethodExecutionArgs args) {
  var action = args.MethodExecutionTag as ITraceAction;
  action.Stop();
}

So that’s nearly all there is to it. It’s not as full-featured as PostSharp’s Diagnostic Library, but it’s a start. I did add OnException, OnYield and OnResume handling too; those are available in the source code download.

With a few simple changes to the ContosoUniversity sample application from part 2, a PerfView trace now shows both method-level and code block tracing:

Logging to an interface

Now that the ContosoUniversity sample is using the “SampleAnalytics” library it no longer needs its own EventSource too. In the spirit of more “generic” events, and finding that an EventSource can implement an interface, I’m going to remove all the logging I added in part 2 and have the interceptors use a simple logging interface:

public interface ILogger {
  void TraceInformation(string message, string category = null, string subcategory = null);
  void TraceWarning(string message, string category = null, string subcategory = null);
  void TraceError(string message, string category = null, string subcategory = null);
}

“Category” and “sub-category” will allow the ETW events to provide a bit more than printf-style logging.

Here’s the DbCommandInterceptor using ILogger, with a category of “Command” and a sub-category set to the calling method name via the CallerMemberName attribute.

public class SchoolInterceptorLogging : DbCommandInterceptor {

  private const string Category = "Command";
  private ILogger _logger; 

  public SchoolInterceptorLogging(ILogger logger) {
    _logger = logger;
  }

  public override void ScalarExecuting(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) {
    LogTraceOrException(command);
  }

  public override void ScalarExecuted(DbCommand command, DbCommandInterceptionContext<object> interceptionContext) {
    LogTraceOrException(command, interceptionContext.Exception);
  }

  ... and so on for NonQuery and Reader command types

  private void LogTraceOrException(DbCommand command, Exception exception = null, [CallerMemberName] string methodName = "") {
    if (exception == null) {
      _logger.TraceInformation(command.CommandText, Category, methodName);
    } else {
      _logger.TraceError(exception.Message, Category, methodName);
    }
}

With similar changes for the IDbConnectionInterceptor:

public class SchoolConnectionInterceptor : IDbConnectionInterceptor {

  private const string Category = "Connection";
  private ILogger _logger; 

  public SchoolConnectionInterceptor(ILogger logger) {
    _logger = logger;
  }

  public void Opening(DbConnection connection, DbConnectionInterceptionContext interceptionContext) {
    LogTraceOrException(connection, interceptionContext);
  }

  public void Opened(DbConnection connection, DbConnectionInterceptionContext interceptionContext) {
    LogTraceOrException(connection, interceptionContext);
  }

  private void LogTraceOrException(DbConnection connection, DbConnectionInterceptionContext context, [CallerMemberName] string methodName = "") {
    if (context.Exception == null) {
      _logger.TraceInformation(connection.Database, Category, methodName);
    } else {
      _logger.TraceError(context.Exception.Message, Category, methodName);
    }
}

The EventSource can now implement ILogger, along with the other trace events shown earlier:

[EventSource(Name = "Samples-Analytics")]
public sealed class AnalyticsEventSource : EventSource, ILogger {

    ... 

    private const int TraceInformationEventId = 5;
    private const int TraceWarningEventId = 6;
    private const int TraceErrorEventId = 7;

    ...

    [Event(TraceInformationEventId, Level = EventLevel.Informational)]
    public void TraceInformation(string message, string category = "", string subcategory = "") {
      WriteEvent(TraceInformationEventId, message, category, subcategory);
    }

    [Event(TraceWarningEventId, Level = EventLevel.Warning)]
    public void TraceWarning(string message, string category = "", string subcategory = "") {
      WriteEvent(TraceWarningEventId, message, category, subcategory);
    }

    [Event(TraceErrorEventId, Level = EventLevel.Error)]
    public void TraceError(string message, string category = "", string subcategory = "") {
      WriteEvent(TraceErrorEventId, message, category, subcategory);
    }
}

 
And finally, a PerfView collection now shows the traced actions along with other activity from the interceptors:

A zip of the modified sample application and “SampleAnalytics” library is available here. Source for the SampleAnalytics library only is also available on github.