Skip to content

Latest commit

 

History

History
472 lines (365 loc) · 24.7 KB

DiagnosticSourceUsersGuide.md

File metadata and controls

472 lines (365 loc) · 24.7 KB
Raw

DiagnosticSource User's Guide

This document describes DiagnosticSource, a simple module that allows code to be instrumented for production-time logging of rich data payloads for consumption within the process that was instrumented. At runtime consumers can dynamically discover data sources and subscribe to the ones of interest.

In addition to background on how the class works, this document also covers naming conventions and best practices when instrumenting code.

Relationship to Other Logging Facilities

In addition to DiagnosticSource, there are two other logging systems provided by Microsoft:

  1. EventSource docs and src. EventSource has been available since V4.5 of the .NET Runtime and is what is used to instrument the runtime itself. It is designed to be fast and to be strongly typed (payloads are typed, named properties), and to interface with OS logging infrastructure like Event Tracing for Windows (ETW) or LTTng on Linux.

  2. ILogger src. A number of popular third party formatted string logging systems for .NET have been built including NLog, SeriLog, and Log4Net. The ILogger NuGet package is designed to 'wrap' any of these and hide from the instrumentation code which exact logging system is being used. Using this wrapper makes the most sense if your goal is to 'plug into' a logging pipeline that assumes one of these logging systems.

DiagnosticSource has more architectural similarity to EventSource. The main difference is that EventSource assumes that the data being logged will leave the process and thus requires that only serializable data be logged. However, DiagnosticSource was designed to allow in-process tools to get at very rich data. Because the consumer is assumed to be within the same process, non-serializable types (e.g. HttpResponseMessage or HttpContext) can be passed, which gives the consumer a lot of potential data to work with.

As explained in DiagnosticSourceEventSource.cs, there is a bridge that pipes information from DiagnosticSources to an EventSource. Thus EventSource consumers can get at all DiagnosticSource events. While the data payloads from DiagnosticSource can't in general be passed through to the EventSource (because they are not serializable), there is a mechanism in the bridge that enables consumers to specify which fields to pass along to the EventSource.

What this means is that in general it is not necessary to instrument a code site multiple times. By instrumenting with Diagnostic source, both clients that need the rich data (and thus use DiagnosticListener) as well as any consumers using EventListeners (or OS facilities like ETW) can get at the data.

Instrumenting with DiagnosticSource/DiagnosticListener

Perhaps surprisingly, the heart of the DiagnosticSource logging architecture is not the DiagnosticSource class but rather the DiagnosticListener class which 'receives' the events. This is because the DiagnosticSource type is just an abstract base class that defines the methods needed to actually log events. It is the DiagnosticListener which holds the actual implementation.

Thus the first step in instrumenting code with DiagnosticSource is to create a DiagnosticListener. For example:

    private static readonly DiagnosticSource httpLogger = new DiagnosticListener("System.Net.Http");

Notice that httpLogger is typed as a DiagnosticSource. This is because this code only cares about writing events and thus only cares about the DiagnosticSource methods that the DiagnosticListener implements. DiagnosticListeners are given names when they are created and this name should be the name of logical grouping of related events (typically the component). Later this name is used to find the Listener and subscribe to any of its events.

Once you have an instance of a DiagnosticSource, logging is very straightforward. The interface consists of only two methods:

    bool IsEnabled(string name)
    void Write(string name, object value);

A typical call site will look like:

    if (httpLogger.IsEnabled("RequestStart"))
        httpLogger.Write("RequestStart", new { Url="http://clr", Request=aRequest });

Already some of the architectural elements are being exposed, namely:

  1. Every event has a string name (e.g. RequestStart), and exactly one object as a payload.

  2. If you need to send more than one item, you can do so by creating an object with all information in it as properties. C#'s anonymous type feature is typically used to create a type to pass 'on the fly', and makes this scheme very convenient.

  3. At the instrumentation site, you must guard the call to Write() with an IsEnabled() check on the same event name. Without this check, even when the instrumentation is inactive, the rules of the C# language require all the work of creating the payload object and calling Write() to be done, even though nothing is actually listening for the data. By guarding the Write() call, we make it efficient when the source is not enabled.

Creating DiagnosticSources (Actually DiagnosticListeners)

Perhaps confusingly you make a DiagnosticSource by creating a DiagnosticListener:

    static readonly DiagnosticSource mySource = new DiagnosticListener("System.Net.Http");

Basically a DiagnosticListener is a named place where a source sends its information (events). From an implementation point of view, DiagnosticSource is an abstract class that has the two instrumentation methods, and DiagnosticListener is something that implements that abstract class. Thus every DiagnosticListener is a DiagnosticSource, and by making a DiagnosticListener you implicitly make a DiagnosticSource as well.

DiagnosticListeners have a name, which is used to represent the component associated with the event. Thus the event names only need to be unique within a component.

Best Practices

Naming Conventions

DiagnosticListener Names

  • CONSIDER - the likely scenarios for USING information when deciding how many DiagnosticListener to have and the events in each. Keep in mind that it is very easy and efficient to filter all the events in a particular listener so ideally the most important scenarios involve turning on whole listeners and not needing to filter for particular events. You may need to split a source into multiple smaller ones to achieve this, and this is OK. For example there are both incoming HTTP requests and outgoing HTTP requests and you may only need one or the other, so having a System.Net.Http.Incoming and System.Net.Http.Outgoing for each sub-case is good.

  • CONSIDER - the likely volume of events. High volume events may deserve their own DiagnosticListener. You don't really want to mix high volume and low volume events in the same listener unless they both support the same scenario. It is OK however to put several low volume events in a 'miscellaneous' listener, even if they support different scenarios if it simplifies things enough.

  • DO - Consider the scenario when picking the name for the DiagnosticListener. Often, this name is the component in which the DiagnosticListener lives, but usage scenarios trump component naming. You want it to be the case that users can correctly guess which listeners to activate knowing just their scenario.

  • DO - Make the name for the DiagnosticListeners globally unique. This is typically done by making the first part of the name the component (e.g. System.Net.Http)

  • DO - Use dots '.' to create multi-part names. This works well if the name is a Name of a component (which uses dots).

  • DO NOT - name the listener after the Listener (thus something like System.Net.HttpDiagnosticListener is bad).

Event Names

  • DO - keep the names reasonably short (< 16 characters). Keep in mind that event names are already qualified by the Listener so the name only needs to be unique within a listener. Short names make IsEnabled() faster.

  • DO - use activities (see Activity Users Guide) for events that are marking the beginning and end of an interval of time. The key value of Activities is that they indicate that they represent a DURATION, and they also track what 'caused' them (and thus logging systems can stitch together a 'causality graph').

  • DO - If for some reason you can't use Activities, and your events mark the start and stop of an interval of time, use the 'Start' and 'Stop' suffixes on the events.

Payloads

  • DO use the anonymous type syntax 'new { property1 = value1 ...}' as the default way to pass a payload even if there is only one data element. This makes adding more data later easy and compatible.

  • CONSIDER creating an explicit type for the payload. The main value for doing this is that the receiver can cast the received object to that type and immediately fetch fields (with anonymous types reflection must be used to fetch fields). This is both easier to program and more efficient. Thus in scenarios where there is likely high-volume filtering to be done by the logging listener, having this type available to do the cast is valuable. Note that this type needs to be made public (since the listener needs to see it). Note that if there is doubt about the value DO NOT create an explicit type, as you CAN convert from an anonymous type to a explicit type compatibly in the future, but once you expose the payload type you must keep it forever. The payload type should simply have C# 'TYPE NAME {get; set; }' properties (you can't use fields). You may add new properties as needed in the future.

  • CONSIDER in high volume cases (e.g. > 1K/sec) consider reusing the payload object instead of creating a new one each time the event is fired. This only works well if you already have locking or exclusive objects where you can remember the payload for the 'next' event to send easily and correctly (you are only saving an object allocation, which is not large).

  • CONSIDER - if you have an event that is so frequent that the performance of the logging is an important consideration, and you have only one data item and it is unlikely that you will ever have more data to pass to the event, and the data item is a normal class (not a value type) then you save some cost by simply by passing the data object directly without using an anonymous type wrapper.

  • DO - use standard names for particular payload items. (TODO: Put the list here as we define standard payload names).

Filtering

  • DO - always enclose the Write() call in a call to IsEnabled() for the same event name. Otherwise a lot of setup logic will be called even if there is nothing listening for the event.

  • CONSIDER - enclosing IsEnabled(string, object, object) calls with pure IsEnabled(string) calls to avoid the extra cost of creating a context in case a consumer is not interested in such events at all.

  • CONSIDER - passing public named types instances to IsEnabled() overloads with object parameters to keep IsEnabled() as efficient as possible.

  • DO - when subscribing to DiagnosticSource with an advanced filter for event name and extended context, make sure the filter returns true for null context properties if the consumer is interested in at least some events with context.

Other Conventions

  • DO NOT - make the DiagnosticListener public. There is no need to as subscribers will use the AllListener property to hook up.

Consuming Data with DiagnosticListener

Up until now, this guide has focused on how to instrument code to generate logging information. In this section we focus on subscribing and decoding of that information.

Discovery of DiagnosticListeners

The first step in receiving events is to discover which DiagnosticListeners you are interested in. While it is possible to discover DiagnosticListeners at compile time by referencing static variables (e.g. like the httpLogger in the previous example), this is typically not flexible enough.

Instead DiagnosticListener supports a way of discovering DiagnosticListeners that are active in the system at runtime. The API to accomplish this is the AllListeners IObservable<DiagnosticListener>.

The IObservable interface is the 'callback' version of the IEnumerable interface. You can learn more about it at the Reactive Extensions site. In a nutshell, you have an object called an IObserver which has three callbacks, OnNext, OnComplete and OnError, and an IObservable has single method called Subscribe which gets passed one of these Observers. Once connected, the Observer gets callbacks (mostly OnNext callbacks) when things happen. By including the System.Reactive.Core NuGet package, you can get a bunch of useful extensions that make using IObservable nice.

A typical use of the AllListeners static property looks like this:

    // We are using AllListeners to turn an Action<DiagnosticListener> into an IObserver<DiagnosticListener>
    static readonly IDisposable listenerSubscription = DiagnosticListener.AllListeners.Subscribe(delegate (DiagnosticListener listener)
    {
        // We get a callback of every Diagnostics Listener that is active in the system (past present or future)
        if (listener.Name == "System.Net.Http")
        {
            // Here is where we put code to subscribe to the Listener.
        }
    });

    // Typically you leave the listenerSubscription subscription active forever.
    // However when you no longer want your callback to be called, you can
    // call listenerSubscription.Dispose() to cancel your subscription to the IObservable.

This code basically creates a callback delegate and using the AllListeners.Subscribe method requests that the delegate be called for every active DiagnosticListener in the system. Typically you inspect the name of the listener and based on that, decide whether to subscribe to the listener or not. The code above is looking for our 'System.Net.Http' listener that we created previously.

Like all calls to Subscribe(), this one returns an IDisposable that represents the subscription itself. Callbacks will continue to happen as long as nothing calls Dispose() on this subscription object. The above code never calls it, so it will receive callbacks forever.

It is important to note that when you subscribe to AllListeners, you get a callback for ALL ACTIVE DiagnosticListeners. Thus, upon subscribing, you get a flurry of callbacks for all existing DiagnosticListeners, but as new ones are created, you get a callback for those as well. Thus you get a complete list of everything it is possible to subscribe to.

Finally, note that the code above is taking advantage of convenience functionality in the System.Reactive.Core library. The DiagnosticListener.AllListeners.Subscribe method actually requires that it be passed an IObserver<DiagnosticListener>, which is a class that has three callbacks (OnNext, OnError, OnComplete), but we passed it an Action<DiagnosticListener>. The magic that makes this work is an extension method in System.Reactive.Core that takes the Action and from it makes an IObserver (called AnonymousObserver) which calls the Action in its OnNext callback. This glue is what makes the code concise.

Subscribing to DiagnosticListeners

A DiagnosticListener implements the IObservable<KeyValuePair<string, object>> interface, so you can call Subscribe() on it as well. Thus we can fill out the previous example a bit:

    static IDisposable networkSubscription = null;
    static readonly IDisposable listenerSubscription = DiagnosticListener.AllListeners.Subscribe(delegate (DiagnosticListener listener)
    {
        if (listener.Name == "System.Net.Http")
        {
            lock(allListeners)
            {
                if (networkSubscription != null)
                    networkSubscription.Dispose();

                networkSubscription = listener.Subscribe((KeyValuePair<string, object> evnt) =>
                    Console.WriteLine("From Listener {0} Received Event {1} with payload {2}",
                    networkListener.Name, evnt.Key, evnt.Value.ToString()));
            }
        }
    });

    // At some point you may wish to dispose the networkSubscription.

In this example, after finding the 'System.Net.Http' DiagnosticListener, we create an action that prints out the name of the listener, event, and payload.ToString(). Notice a few things:

  1. DiagnosticListener implements IObservable<KeyValuePair<string, object>>. This means on each callback we get a KeyValuePair. The key of this pair is the name of the event and the value is the payload object. In the code above we simply log this information to the console.

  2. We keep track of our subscriptions to the DiagnosticListener. In this case we have a networkSubscription variable that remembers this, and if we get another 'creation' we unsubscribe the previous listener and subscribe to the new one.

  3. We use locks. The DiagnosticSource/DiagnosticListener code is thread safe, but the callback code also needs to be thread safe. It is possible that two DiagnosticListeners with the same name are created at the same time (although that is a bit unexpected), so to avoid races we do updates of our shared variables under the protection of a lock.

Once the above code is run, the next time a Write() is done on 'System.Net.Http' DiagnosticListener the information will be logged to the console.

It is also important to note that subscriptions are independent of one another. Thus other code can do exactly the same thing as the code above, and thus generate two 'pipes' of the logging information.

Decoding Payloads

The KeyvaluePair that is passed to the callback has the event name and payload, but the payload is typed simply as an object. Odds are that you want to get at more specific data. There are two ways of doing this:

  1. If the payload is a well known type (e.g. a string, or an HttpMessageRequest) then you can simply cast the object to the expected type (using the as operator so as not to cause an exception if you are wrong) and then access the fields. This is very efficient.

  2. Use reflection API. For example, if we assume we have the method:

    /// Define a shortcut method that fetches a field of a particular name.
    static class PropertyExtensions
    {
        static object GetProperty(this object _this, string propertyName)
        {
            return _this.GetType().GetTypeInfo().GetDeclaredProperty(propertyName)?.GetValue(_this);
        }
    }

Then we could replace the listener.Subscribe() call above with the following code, to decode the payload more fully:

    networkSubscription = listener.Subscribe(delegate(KeyValuePair<string, object> evnt) {
        var eventName = evnt.Key;
        var payload = evnt.Value;
        if (eventName == "RequestStart")
        {
            var url = payload.GetProperty("Url") as string;
            var request = payload.GetProperty("Request");
            Console.WriteLine("Got RequestStart with URL {0} and Request {1}", url, request);
        }
    });

Note that using reflection is relatively expensive. However, using reflection is your only option if the payloads were generated using anonymous types. You can reduce this overhead by making fast, specialized property fetchers either using PropertyInfo.CreateDelegate or ReflectEmit, but that is beyond the scope of this document. (See the PropertySpec class used in the DiagnosticSourceEventSource for an example of a fast, delegate-based property fetcher.)

Filtering

In the example above the code uses the IObservable.Subscribe() method to hook up the callback, which causes all events to be given to the callback. However DiagnosticListener has overloads of Subscribe() that allow the controller to control which events get through.

Thus we could replace the listener.Subscribe() call in the previous example with the following code:

    // Create the callback delegate
    Action<KeyValuePair<string, object>> callback = (KeyValuePair<string, object> evnt) =>
        Console.WriteLine("From Listener {0} Received Event {1} with payload {2}", networkListener.Name, evnt.Key, evnt.Value.ToString());

    // Turn it into an observer (using System.Reactive.Core's AnonymousObserver)
    Observer<KeyValuePair<string, object>> observer = new AnonymousObserver<KeyValuePair<string, object>>(callback);

    // Create a predicate (asks only for one kind of event)
    Predicate<string> predicate = (string eventName) => eventName == "RequestStart";

    // Subscribe with a filter predicate
    IDisposable subscription = listener.Subscribe(observer, predicate);

    // subscription.Dispose() to stop the callbacks.

This very efficiently subscribes to only the 'RequestStart' events. All other events will cause the DiagnosticSource.IsEnabled() method to return false, and thus be efficiently filtered out.

NOTE: Filtering is only designed as a performance optimization. It is possible for a listener to receive events even when they do not satisfy the filter. This could occur because some other listener has subscribed to the event or because the source of the event didn't check IsEnabled() prior to sending it. If you want to be certain that a given event satisfies the filter you will need to check it inside the callback. For example:

Action<KeyValuePair<string, object>> callback = (KeyValuePair<string, object> evnt) =>
        {
            if(predicate(evnt.Key)) // only print out events that satisfy our filter
            {
                Console.WriteLine("From Listener {0} Received Event {1} with payload {2}", networkListener.Name, evnt.Key, evnt.Value.ToString());
            }
        };
Context-based Filtering

Some scenarios require advanced filtering based on extended context. Producers may call DiagnosticSource.IsEnabled() overloads and supply additional event properties:

    if (httpLogger.IsEnabled("RequestStart", aRequest, anActivity))
        httpLogger.Write("RequestStart", new { Url="http://clr", Request=aRequest });

And consumers may use such properties to filter events more precisely:

    // Create a predicate (asks only for Requests for certains URIs)
    Func<string, object, object, bool> predicate = (string eventName, object context, object activity) =>
    {
        if (eventName == "RequestStart")
        {
            HttpRequestMessage request = context as HttpRequestMessage;
            if (request != null)
            {
                return IsUriEnabled(request.RequestUri);
            }
        }
        return false;
    }

    // Subscribe with a filter predicate
    IDisposable subscription = listener.Subscribe(observer, predicate);

Note that producers are not aware of the filter a consumer has provided. DiagnosticListener will invoke the provided filter, omitting additional arguments if necessary, thus the filter should expect to receive a null context. Producers should enclose IsEnabled() calls with event name and context with pure IsEnabled() calls for event name, so consumers must ensure that their filter allows events without context to pass through.

Consuming DiagnosticSource Data with EventListeners and ETW

The System.Diagnostic.DiagnosticSource NuGet package comes with a built in EventSource called Microsoft-Diagnostics-DiagnosticSource. This EventSource has the ability to subscribe to any DiagnosticListener as well as pluck off particular data items from DiagnosticSource payloads.

Thus code that is using System.Diagnostics.Tracing.EventListener or ETW can get at any information logged with DiagnosticSource.

See DiagnosticSourceEventSource for more information on how to use it.