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 the processing of events occurs in the same process as sending, this information can contain almost any objects without the need for serialization / deserialization.

DiagnosticSource is already used in AspNetCore, EntityFrameworkCore, HttpClient, and SqlClient, which in fact allows developers to intercept incoming / outgoing http requests, database requests, access objects such as HttpContext , DbConnection , DbCommand , HttpRequestMessage and access objects, such as HttpContext , DbConnection , DbCommand , HttpRequestMessage and they are not available. 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 discuss existing events in .NET that can be processed with its help and show several examples of its use in OZON.ru.

Example

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

 public static class Program { public const string ConnectionString = @"Data Source=localhost;Initial Catalog=master;User ID=sa;Password=Password12!;"; public static async Task Main() { var answer = await GetAnswerAsync(); Console.WriteLine(answer); } public static async Task<int> GetAnswerAsync() { using (var connection = new SqlConnection(ConnectionString)) { // using Dapper return await 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 imagine that we have a task: you need to measure the execution time of all queries to the database using Stopwatch and output the "Request" - "Runtime" pairs to the console.

Of course, you can simply wrap the call to QuerySingleAsync code that creates and starts the Stopwatch instance, stops it after the query is executed, and displays 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 query is not done via Dapper, but for example via EntityFramework, and we do not have access to either the DbCommand object or the generated query text that will actually be executed?

Let's try to solve this problem using the 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:

 public sealed class ExampleDiagnosticObserver { } 

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

 public static async 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 ExampleDiagnosticObserver class should implement the IObserver<DiagnosticListener> interface. Let's implement it:

 public sealed class ExampleDiagnosticObserver : 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 objects of type DiagnosticListener with the name "SqlClientDiagnosticListener" that worked when executing this code.

The IObserver<DiagnosticListener>.OnNext will be called once for the first use for each DiagnosticListener instance that is created in the application (they are usually created as static properties). Now we just brought the name of the DiagnosticListener instances to the console, 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 Subscribe method.

I also want to note that when we call DiagnosticListener.AllListeners.Subscribe we will get a subscription object that implements the IDisposable interface as a result. Calling the Dispose method on this object will result in a reply that needs to be implemented in the IObserver<DiagnosticListener>.OnCompleted .

Let's implement the IObserver<DiagnosticListener> again:

 public sealed class ExampleDiagnosticObserver : IObserver<DiagnosticListener> { private readonly 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 ExampleDiagnosticObserver should also implement the interface IObserver<KeyValuePair<string, object>> . Here we need to implement the IObserver<KeyValuePair<string, object>>.OnNext , which as a parameter takes 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 on your own. Let's add the implementation of this interfex:

 public sealed class ExampleDiagnosticObserver : 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() { } private void Write(string name, object value) { Console.WriteLine(name); Console.WriteLine(value); Console.WriteLine(); } } 

If we now run the received 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 contains a set of parameters, such as OperationId , ConnectionId , Connection , Command , which are usually passed as properties of the anonymous object. 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 we have everything ready 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 Write method as follows:

 public sealed class ExampleDiagnosticObserver : IObserver<DiagnosticListener>, IObserver<KeyValuePair<string, object>> { // IObserver<DiagnosticListener> implementation // ... // IObserver<KeyValuePair<string, object>> implementation // ... private readonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>(); private void Write(string name, object value) { 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; } } } private static T GetProperty<T>(object value, 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 variable of type AsyncLocal<Stopwatch> , in order to get it back later. After the request is completed, we get the previously started stopwatch, stop it, get the executed command from the value parameter through reflection and output the result to the console.

If we now run the received 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 a DiagnosticListener event, we start receiving 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 the DiagnosticListener we are going to process, we can specify a special delegate of the Predicate<string> which subscribes the name of the event as a parameter and returns true if this event should be processed.

IObserver<DiagnosticListener>.OnNext in our class:

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

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

Using NuGet Microsoft.Extensions.DiagnosticAdapter

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

In order to use this package when subscribing to events from the DiagnosticListener instance, the Subscribe extension method must be used instead of the Subscribe method. Implement the IObserver<KeyValuePair<string, object>> 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 the DiagnosticNameAttribute attribute (from the Microsoft.Extensions.DiagnosticAdapter namespace). The parameters of these methods are the parameters of the event being processed.

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

 public sealed class ExampleDiagnosticObserver : IObserver<DiagnosticListener> { private readonly 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(); } private readonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>(); [DiagnosticName("System.Data.SqlClient.WriteCommandBefore")] public void OnCommandBefore() { _stopwatch.Value = Stopwatch.StartNew(); } [DiagnosticName("System.Data.SqlClient.WriteCommandAfter")] public void OnCommandAfter(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 using the DiagnosticSource in practice, in most cases you will subscribe to already existing events. You probably won't have to create your own instances of the DiagnosticListener and send your own events (only if you are not developing any library), so I will not dwell on this section for a long time.

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

 private static readonly DiagnosticSource _myDiagnosticSource = new DiagnosticListener("MyLibraty"); 

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

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

More information about creating your own instances of the DiagnosticListener can 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 certainly 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 give a list of events known to me that can be processed through the DiagnosticSource, and I will show several practical examples of its use.