Laszlo - ETW Logging implementation for Service Fabric

ETW Logging implementation for Service Fabric

02/18/2018

5 minutes

ETW Logging is suggested for Service Fabric application. ETW has numerous advantages, but the biggest one is being extremely fast.

Preamble

This is poor man's logging. Consider using existing libraries in production applications, such as EventFlow.

The EventSource

When adding actors or services to a SF solution, we get a ServiceEventSource or an ActorEventSource class in the sample projects. Having multiple of the same files is not necessary as long as we are fine sharing the EventSource name across services. There are several constraints around the EventSource class, one of them it must be sealed.

Once we have our EventSource derived class, we can customize it. The given skeleton is fine for the empty project, but we might want to emit our own semantic messages or such as Debug, Info, Error, etc. For this we will register new Event and NonEvent methods.

private const int MessageEventId = 1;

[Event(MessageEventId, Level = EventLevel.Informational, Message = "{0}")]
public void Info(string message, string applicationName, string serviceName, string nodeName, string typeName, string correlationId)
{
  if(IsEnabled())
  {
    WriteEvent(MessageEventId, message, applicationName, serviceName, nodeName, typeName, correlationId);
  }
}

This method registered as an event has a numerous important details. Methods registered for events must comply with certain rules, otherwise our ETW events will not be emitted. Some of these:

You must call WriteEvent method
It is suggested to call IsEnabled()
Pass the Event ID, followed by the same arguments as the defined method is passed
Depending on the WriteEvent overload we call, we might face additional performance overhead, while also have to make sure the parameters passed are serializable
Method name is suggested to match the Task + OpCode if given
etc.

In my example, I use quite many parameters, so filtering on events is an easier task.

Then we can also add some higher level methods (non events) which can call our newly created events. One example is

[NonEvent]
void Log(string message, EventLevel level, string type, string correlationId);

Another method could also take an Exception parameter if it needs to be logged.

The basic idea, is that from any application we emit regular informational/verbose messages or an error/warning, where we might also want to attach the details of an exception.

I extract these non event methods along with a bool IsEnabled(EventLevel level); to an interface called ILogProvider. This gives us an abstraction on the actual class emitting the events, say we want to change ETW to a file we only need to implement the given Log and IsEnabled methods, while ETW/file provider related details remains hidden from the user of ILogProvider. The ILogProvider will be the dependency of our ILogger implementation (IoC).

I have chosen the name 'provider' against 'sink' as from ETW's standpoint, we are creating an event provider. Consumers, Controllers (such as PerfView) of this providers can run separately from our application. There is an excellent online course on ETW Providers, Consumers, Controllers by Kathleen Dollard.

Logger

The Logger (along with its ILogger interface) provides the high level logging abstraction I want to use in my application's code. For example for info level message, I will have 2 methods to use. One for emitting an informational level of log message. One for checking if info level of logging is enabled.

public interface ILogger
{
  bool IsInfoEnabled()

  void Info(string message);
...
}

This latter method, IsInfoEnabled, is available for performance reasons. A general use case for logging, that we construct a rather complex log message, which could involve several string operations. Such as $"State loading for user '{userId}' failed on request '{requestId}'". Secondly, consider all the semantic information we need to add for the message In the NonEvent method above I add a correlation Id to track related service calls, and a typename for the class emitting the log message as contextual details. There are several other properties that can be added to the message, like service name, service type name, etc.

These messages not only allocate memory and concatenate strings, but as string being a reference type, it also puts a pressure on the GC. Say the given log level is not enabled, we could waste huge amount of resources to construct log messages, that we do not care about. To avoid wasting all these CPU cycles it seems a good practice to check if a given log level is enabled before emitting the message. (Note that another option could be having an overload for Info, which takes a Func<...,string> to construct the log message. The Func would be only invoked if the given log level is enabled, which only delays the usage of IsEnabled method.

LogFactory

Finally, using DI we would like to pass our ILogger implementation to the place of usage (say to our objects with business logic). Some argue for and some against passing it to each and every class. Accessing it through a ServiceLocator is also an antipattern. Mark Seemann's Ambient context seems like a good choice to avoid using ServiceLocator or polluting our constructors (in case of constructor injection). Note, that ServiceEventSource are ActorEventSource are singletons.

My choice is usually having a LogFactory to provide a static readonly implementation for an ILogger field in the classes I use the logger.

There are several frameworks existing to provide us a nice Logging facade, in this post I have shown a quick and dirty way to put together the poor man's logger for ETW and Service Fabric.

C# Service Fabric logging

Hello, I am Laszlo

.NET developer