Using the DiagnosticSource in .NET Core: Theory

DiagnosticSource is a simple but very useful set of APIs (available in the System.Diagnostics.DiagnosticSource NuGet package ), which, on the one hand, allows different libraries to send named events about their work, and on the other hand, allows applications to subscribe to these events and process their.

Each such event contains additional information (payload), and since event processing occurs in the same process as sending, this information can contain almost any objects without the need for serialization / deserialization.

DiagnosticSource already used in AspNetCore, EntityFrameworkCore, HttpClient, and the SqlClient, that actually gives developers the ability to intercept incoming / outgoing http requests, database queries, access to objects such as HttpContext, DbConnection, DbCommand, HttpRequestMessageand many others, and even modify these objects if necessary.

I decided to divide my story about DiagnosticSource into two articles. In this article, we will use a simple example to analyze the principle of operation of the mechanism, and in the next I will talk about events that exist in .NET that can be processed with its help and show several examples of its use in OZON.ru.

Example

To better understand how DiagnosticSource works, consider a small example c intercepting database requests. Imagine that we have a simple console application that makes a request to the database and outputs the result to the console.

publicstaticclassProgram
{
    publicconststring ConnectionString =
        @"Data Source=localhost;Initial Catalog=master;User ID=sa;Password=Password12!;";
    publicstaticasync Task Main()
    {
        var answer = await GetAnswerAsync();
        Console.WriteLine(answer);
    }
    publicstaticasync Task<int> GetAnswerAsync()
    {
        using (var connection = new SqlConnection(ConnectionString))
        {
            // using Dapperreturnawait connection.QuerySingleAsync<int>("SELECT 42;");
        }
    }
}

For simplicity, I picked up SQL Server in a docker container.

docker run --rm --detach --name mssql-server \
    --publish 1433:1433 \
    --env ACCEPT_EULA=Y \
    --env SA_PASSWORD=Password12! \
    mcr.microsoft.com/mssql/server:2017-latest

Now let's imagine that we have a task: we need to measure the execution time of all queries to the database using Stopwatchand output the "Request" - "Runtime" pairs to the console.

Of course, you can simply wrap the call with a QuerySingleAsynccode that will create and start an instance Stopwatch, stop it after the query has been executed, and display the result, but then several difficulties arise at once:

• What if the application has more than one request, and much more?
• What if the code that executes the request is already compiled, connected to the application as a NuGet package, and we do not have the ability to change it?
• What if the database request is not done via Dapper, but through EntityFramework, for example, and we do not have access to either the object DbCommandor the generated text of the request that will actually be executed?

Let's try to solve this problem using DiagnosticSource.

Using the System.Diagnostics.DiagnosticSource NuGet Package

The first thing to do after connecting the System.Diagnostics.DiagnosticSource package NuGet is to create a class that will handle the events of interest to us:

publicsealedclassExampleDiagnosticObserver
{ }

In order to start processing events, you need to create an instance of this class and register it with an observer in a static object DiagnosticListener.AllListeners(located in the namespace System.Diagnostics). Let's do this at the very beginning of the function Main:

publicstaticasync Task Main()
{
    var observer = new ExampleDiagnosticObserver();
    IDisposable subscription = DiagnosticListener.AllListeners.Subscribe(observer);
    var answer = await GetAnswerAsync();
    Console.WriteLine(answer);
}

In this case, the compiler will fairly tell us that the class ExampleDiagnosticObservershould implement the interface IObserver<DiagnosticListener>. Let's implement it:

publicsealedclassExampleDiagnosticObserver : IObserver<DiagnosticListener>
{
    void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener)
    {
        Console.WriteLine(diagnosticListener.Name);
    }
    void IObserver<DiagnosticListener>.OnError(Exception error)
    { }
    void IObserver<DiagnosticListener>.OnCompleted()
    { }
}

If we run this code now, we will see that the following will be displayed in the console:

SqlClientDiagnosticListener
SqlClientDiagnosticListener
42

This means that somewhere in .NET there are two registered objects of the type DiagnosticListenerwith the name "SqlClientDiagnosticListener"that worked when executing this code.

The method IObserver<DiagnosticListener>.OnNextwill be called once at the first use for each instance DiagnosticListenerthat is created in the application (usually they are created as static properties). Now we just brought the name of the instances to the console DiagnosticListener, but in practice this method needs to check this name and, if we are interested in processing events from this instance, subscribe to it using the method Subscribe.

I also want to note that when DiagnosticListener.AllListeners.Subscribewe call, we will get an object subscriptionthat implements the interface as a result IDisposable. Calling a method Disposeon this object will result in a reply that needs to be implemented in the method IObserver<DiagnosticListener>.OnCompleted.

Let's implement IObserver<DiagnosticListener>again:

publicsealedclassExampleDiagnosticObserver : IObserver<DiagnosticListener>
{
    privatereadonly List<IDisposable> _subscriptions = new List<IDisposable>();
    void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener)
    {
        if (diagnosticListener.Name == "SqlClientDiagnosticListener")
        {
            var subscription = diagnosticListener.Subscribe(this);
            _subscriptions.Add(subscription);
        }
    }
    void IObserver<DiagnosticListener>.OnError(Exception error)
    { }
    void IObserver<DiagnosticListener>.OnCompleted()
    {
        _subscriptions.ForEach(x => x.Dispose());
        _subscriptions.Clear();
    }
}

Now the compiler will tell us that our class ExampleDiagnosticObservershould also implement the interface IObserver<KeyValuePair<string, object>>. Here we need to implement a method IObserver<KeyValuePair<string, object>>.OnNextthat takes as a parameter KeyValuePair<string, object>, where the key is the name of the event, and the value is an anonymous object (usually) with arbitrary parameters that we can use at our discretion. Let's add the implementation of this interfex:

publicsealedclassExampleDiagnosticObserver :
    IObserver<DiagnosticListener>,
    IObserver<KeyValuePair<string, object>>
{
    // IObserver<DiagnosticListener> implementation// ...void IObserver<KeyValuePair<string, object>>.OnNext(KeyValuePair<string, object> pair)
    {
        Write(pair.Key, pair.Value);
    }
    void IObserver<KeyValuePair<string, object>>.OnError(Exception error)
    { }
    void IObserver<KeyValuePair<string, object>>.OnCompleted()
    { }
    privatevoidWrite(string name, objectvalue)
    {
        Console.WriteLine(name);
        Console.WriteLine(value);
        Console.WriteLine();
    }
}

If we now run the resulting code, then the following will be displayed in the console:

System.Data.SqlClient.WriteConnectionOpenBefore
{ OperationId = 3da1b5d4-9ce1-4f28-b1ff-6a5bfc9d64b8, Operation = OpenAsync, Connection = System.Data.SqlClient.SqlConnection, Timestamp = 26978341062 }
System.Data.SqlClient.WriteConnectionOpenAfter
{ OperationId = 3da1b5d4-9ce1-4f28-b1ff-6a5bfc9d64b8, Operation = OpenAsync, ConnectionId = 84bd0095-9831-456b-8ebc-cb9dc2017368, Connection = System.Data.SqlClient.SqlConnection,
Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 26978631500 }
System.Data.SqlClient.WriteCommandBefore
{ OperationId = 5c6d300c-bc49-4f80-9211-693fa1e2497c, Operation = ExecuteReaderAsync, ConnectionId = 84bd0095-9831-456b-8ebc-cb9dc2017368, Command = System.Data.SqlClient.SqlComman
d }
System.Data.SqlClient.WriteCommandAfter
{ OperationId = 5c6d300c-bc49-4f80-9211-693fa1e2497c, Operation = ExecuteReaderAsync, ConnectionId = 84bd0095-9831-456b-8ebc-cb9dc2017368, Command = System.Data.SqlClient.SqlComman
d, Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 26978709490 }
System.Data.SqlClient.WriteConnectionCloseBefore
{ OperationId = 3f6bfd8f-e5f6-48b7-82c7-41aeab881142, Operation = Close, ConnectionId = 84bd0095-9831-456b-8ebc-cb9dc2017368, Connection = System.Data.SqlClient.SqlConnection, Stat
istics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 26978760625 }
System.Data.SqlClient.WriteConnectionCloseAfter
{ OperationId = 3f6bfd8f-e5f6-48b7-82c7-41aeab881142, Operation = Close, ConnectionId = 84bd0095-9831-456b-8ebc-cb9dc2017368, Connection = System.Data.SqlClient.SqlConnection, Stat
istics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 26978772888 }
42

In total we will see six events. Two of them are performed before and after opening a connection to the database, two before and after the command is executed, and two more before and after closing the connection to the database.

Each event includes a set of parameters such as OperationId, ConnectionId, Connection, Command, which are typically transmitted as an anonymous object properties. You can get the typed values ​​of these properties, for example, by using reflection. (In practice, using reflection may not be very desirable. We use DynamicMethod to get event parameters.)

Now everything is ready for us to solve the original problem - measure the execution time of all queries in the database and output it to the console along with the original query.

Change the implementation of the method Writeas follows:

publicsealedclassExampleDiagnosticObserver :
    IObserver<DiagnosticListener>,
    IObserver<KeyValuePair<string, object>>
{
    // IObserver<DiagnosticListener> implementation// ...// IObserver<KeyValuePair<string, object>> implementation// ...privatereadonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>();
    privatevoidWrite(string name, objectvalue)
    {
        switch (name)
        {
            case"System.Data.SqlClient.WriteCommandBefore":
            {
                // Этот код будет выполняться до выполнения запроса в базу данных
                _stopwatch.Value = Stopwatch.StartNew();
                break;
            }
            case"System.Data.SqlClient.WriteCommandAfter":
            {
                // Этот код будет выполняться после выполнения запроса в базу данныхvar stopwatch = _stopwatch.Value;
                stopwatch.Stop();
                var command = GetProperty<SqlCommand>(value, "Command");
                Console.WriteLine($"CommandText: {command.CommandText}");
                Console.WriteLine($"Elapsed: {stopwatch.Elapsed}");
                Console.WriteLine();
                break;
            }
        }
    }
    privatestatic T GetProperty<T>(objectvalue, string name)
    {
        return (T) value.GetType()
            .GetProperty(name)
            .GetValue(value);
    }
}

Here we intercept the start and end events of the query in the database. Before executing the request, we create and start a stopwatch, storing it in a type variable AsyncLocal<Stopwatch>, to get it back later. After the request is completed, we get the previously started stopwatch, stop it, get the executed command from the parameter valuethrough reflection and output the result to the console.

If we now run the resulting code, then the following will be displayed in the console:

CommandText: SELECT 42;
Elapsed: 00:00:00.0341357
42

It would seem that we have already solved our problem, but one small detail remains. The fact is that when we subscribe to events DiagnosticListenerwe start to receive from it even those events that are not interesting to us, and since sending each event creates an anonymous object with parameters, this can create an extra load on the GC.

To avoid this situation and to inform which events from DiagnosticListenerwe are going to handle, we can specify a special delegate of the type Predicate<string>that subscribes to the name of the event and returns trueif this event should be processed.

Let's slightly change the method IObserver<DiagnosticListener>.OnNextin our class:

void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener)
{
    if (diagnosticListener.Name == "SqlClientDiagnosticListener")
    {
        var subscription = diagnosticListener.Subscribe(this, IsEnabled);
        _subscriptions.Add(subscription);
    }
}
privateboolIsEnabled(string name)
{
    return name == "System.Data.SqlClient.WriteCommandBefore"
        || name == "System.Data.SqlClient.WriteCommandAfter";
}

Now our method Writewill be called only for events "System.Data.SqlClient.WriteCommandBefore"and "System.Data.SqlClient.WriteCommandAfter".

Using NuGet Microsoft.Extensions.DiagnosticAdapter

Since the event parameters that we receive from DiagnosticListenerare usually passed as an anonymous object, it can be too expensive to retrieve them through reflection. Fortunately, there is a NuGet Microsoft.Extensions.DiagnosticAdapter package that can do this for us, using runtime code generation from the namespace System.Reflection.Emit.

In order to use this package when subscribing to events from an instance DiagnosticListener, Subscribeyou must use an extension method instead of a method SubscribeWithAdapter. Implementing an interface IObserver<KeyValuePair<string, object>>in this case is no longer required. Instead, for each event that we want to handle, we need to declare a separate method, marking it with an attribute DiagnosticNameAttribute(from the namespace Microsoft.Extensions.DiagnosticAdapter). The parameters of these methods are the parameters of the event being processed.

If we rewrite our class ExampleDiagnosticObserverusing this NuGet package, we get the following code:

publicsealedclassExampleDiagnosticObserver : IObserver<DiagnosticListener>
{
    privatereadonly List<IDisposable> _subscriptions = new List<IDisposable>();
    void IObserver<DiagnosticListener>.OnNext(DiagnosticListener diagnosticListener)
    {
        if (diagnosticListener.Name == "SqlClientDiagnosticListener")
        {
            var subscription = diagnosticListener.SubscribeWithAdapter(this);
            _subscriptions.Add(subscription);
        }
    }
    void IObserver<DiagnosticListener>.OnError(Exception error)
    { }
    void IObserver<DiagnosticListener>.OnCompleted()
    {
        _subscriptions.ForEach(x => x.Dispose());
        _subscriptions.Clear();
    }
    privatereadonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>();
    [DiagnosticName("System.Data.SqlClient.WriteCommandBefore")]
    publicvoidOnCommandBefore()
    {
        _stopwatch.Value = Stopwatch.StartNew();
    }
    [DiagnosticName("System.Data.SqlClient.WriteCommandAfter")]
    publicvoidOnCommandAfter(DbCommand command)
    {
        var stopwatch = _stopwatch.Value;
        stopwatch.Stop();
        Console.WriteLine($"CommandText: {command.CommandText}");
        Console.WriteLine($"Elapsed: {stopwatch.Elapsed}");
        Console.WriteLine();
    }
}

Thus, we can now measure the execution time of all queries to the database from our application, with virtually no change to the code of the application itself.

Creating Your Own Instances of a DiagnosticListener

When you use the DiagnosticSource in practice, in most cases you will subscribe to already existing events. You DiagnosticListenerprobably don’t have to create your own instances and send your own events (only if you don’t develop any library), so I won’t dwell on this section for long.

To create your own instance, DiagnosticListeneryou will need to declare it as a static variable somewhere in the code:

privatestaticreadonly DiagnosticSource _myDiagnosticSource =
    new DiagnosticListener("MyLibraty");

After that, to send an event, you can use the following construction:

if (_myDiagnosticSource.IsEnabled("MyEvent"))
    _myDiagnosticSource.Write("MyEvent", new { /* parameters */ });

More information about creating your own instances DiagnosticListenercan be found in the DiagnosticSource User's Guide , which describes in detail Best Practices for using the DiagnosticSource.

Conclusion

The example that we considered is definitely very abstract and is hardly useful in a real project. But it perfectly shows how this mechanism can be used to monitor and diagnose your applications.

In the next article, I will provide a list of events known to me that can be processed through the DiagnosticSource, and I will show several practical examples of its use.