Utilisation de DiagnosticSource dans .NET Core: théorie

DiagnosticSource est un ensemble d'API simple mais très utile (disponible dans le package NuGet System.Diagnostics.DiagnosticSource ), qui, d'une part, permet à diverses bibliothèques d'envoyer des événements nommés à propos de leur travail, et d'autre part, permet aux applications de s'abonner à ces événements et processus eux.

Chacun de ces événements contient des informations supplémentaires (charge utile), et puisque les événements sont traités dans le même processus que l'envoi, ces informations peuvent contenir presque tous les objets sans avoir besoin de sérialisation / désérialisation.

DiagnosticSource est déjà utilisé dans AspNetCore, EntityFrameworkCore, HttpClient et SqlClient, ce qui donne aux développeurs la possibilité d'intercepter les requêtes http entrantes / sortantes, les requêtes de base de données, les objets d'accès tels que HttpContext , DbConnection , DbCommand , HttpRequestMessage et bien d'autres objets si nécessaire.

J'ai décidé de diviser mon histoire sur DiagnosticSource en deux articles. Dans cet article, nous analyserons le principe de fonctionnement du mécanisme avec un exemple simple, et dans le prochain, je parlerai des événements qui existent dans .NET qui peuvent être traités à l'aide de celui-ci et montrer quelques exemples de son utilisation dans OZON.ru.

Exemple

Pour mieux comprendre le fonctionnement de DiagnosticSource, considérons un petit exemple d'interception de requêtes de base de données. Imaginez que nous ayons une application console simple qui fait une demande à la base de données et affiche le résultat dans la 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;"); } } } 

Par souci de simplicité, j'ai élevé SQL Server dans un conteneur Docker.

 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 

Imaginez maintenant que nous avons une tâche: nous devons mesurer le temps d'exécution de toutes les requêtes vers la base de données à l'aide de Stopwatch et afficher les paires «Request» - «Runtime» dans la console.

Bien sûr, vous pouvez simplement QuerySingleAsync appel QuerySingleAsync code qui crée et démarre l'instance Stopwatch , l'arrête après l'exécution de la requête et affiche le résultat, mais il y a plusieurs difficultés à la fois:

• Que faire si la demande contient plusieurs demandes?
• Que se passe-t-il si le code qui exécute la demande est déjà compilé, est connecté à l'application en tant que package NuGet et que nous n'avons aucun moyen de le modifier?
• Que se passe-t-il si la requête vers la base de données n'est pas effectuée via Dapper, mais via EntityFramework, par exemple, et que nous n'avons pas accès à l'objet DbCommand ou au texte de requête généré qui sera réellement exécuté?

Essayons de résoudre ce problème en utilisant DiagnosticSource.

Utilisation du package NuGet System.Diagnostics.DiagnosticSource

La première chose à faire après avoir connecté le package NuGet de System.Diagnostics.DiagnosticSource est de créer une classe qui gérera les événements qui nous intéressent:

 public sealed class ExampleDiagnosticObserver { } 

Pour démarrer le traitement des événements, vous devez créer une instance de cette classe et l'enregistrer en tant qu'observateur dans l'objet statique DiagnosticListener.AllListeners (situé dans l'espace de noms System.Diagnostics ). Nous le faisons au tout début de la fonction Main :

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

Dans ce cas, le compilateur nous indiquera à juste titre que la classe ExampleDiagnosticObserver doit implémenter l' IObserver<DiagnosticListener> . Implémentons-le:

 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() { } } 

Si nous exécutons ce code maintenant, nous verrons que ce qui suit sera affiché dans la console:

 SqlClientDiagnosticListener SqlClientDiagnosticListener 42 

Cela signifie que quelque part dans .NET deux objets de type DiagnosticListener sont enregistrés avec le nom "SqlClientDiagnosticListener" qui fonctionnait lorsque ce code a été exécuté.

La IObserver<DiagnosticListener>.OnNext sera appelée une fois lors de la première utilisation pour chaque instance de DiagnosticListener créée dans l'application (généralement, elles sont créées en tant que propriétés statiques). Maintenant, nous venons d'afficher le nom des instances de DiagnosticListener dans la console, mais en pratique, cette méthode doit vérifier ce nom et, si nous sommes intéressés par le traitement des événements de cette instance, abonnez-vous en utilisant la méthode Subscribe .

Je tiens également à noter que lorsque nous appelons DiagnosticListener.AllListeners.Subscribe nous obtiendrons un objet d' subscription en conséquence, qui implémente l'interface IDisposable . L'appel de la méthode Dispose sur cet objet entraînera la désinscription, qui doit être implémentée dans la IObserver<DiagnosticListener>.OnCompleted .

IObserver<DiagnosticListener> nouveau IObserver<DiagnosticListener> :

 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(); } } 

Le compilateur va maintenant nous dire que notre classe ExampleDiagnosticObserver devrait également implémenter l' IObserver<KeyValuePair<string, object>> . Ici, nous devons implémenter IObserver<KeyValuePair<string, object>>.OnNext , qui en tant que paramètre accepte KeyValuePair<string, object> , où la clé est le nom de l'événement, et la valeur est un objet anonyme (généralement) avec des paramètres arbitraires que nous pouvons utiliser à sa discrétion. Ajoutons une implémentation de cette interface:

 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(); } } 

Si nous exécutons maintenant le code résultant, les éléments suivants seront affichés dans la 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 

Au total, nous verrons six événements. Deux d'entre eux sont exécutés avant et après l'ouverture de la connexion à la base de données, deux - avant et après l'exécution de la commande, et deux autres - avant et après la fermeture de la connexion à la base de données.

Chaque événement contient un ensemble de paramètres, tels que OperationId , ConnectionId , Connection , Command , qui sont généralement transmis en tant que propriétés d'un objet anonyme. Vous pouvez obtenir des valeurs saisies pour ces propriétés, par exemple, en utilisant la réflexion. (En pratique, l'utilisation de la réflexion peut ne pas être très souhaitable. Nous utilisons DynamicMethod pour obtenir les paramètres d'événement.)

Nous sommes maintenant prêts à résoudre le problème initial - à mesurer le temps d'exécution de toutes les demandes à la base de données et à l'afficher dans la console avec la demande d'origine.

Modifiez l'implémentation de la méthode Write comme suit:

 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); } } 

Ici, nous interceptons les événements de début et de fin de la demande vers la base de données. Avant d'exécuter la requête, nous créons et démarrons le chronomètre, en l'enregistrant dans une variable de type AsyncLocal<Stopwatch> , afin de le récupérer plus tard. Après avoir exécuté la demande, nous obtenons le chronomètre précédemment lancé, l'arrêtons, obtenons la commande exécutée à partir du paramètre de value via la réflexion et imprimons le résultat sur la console.

Si nous exécutons maintenant le code résultant, les éléments suivants seront affichés dans la console:

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

Il semblerait que nous ayons déjà résolu notre problème, mais un petit détail demeure. Le fait est que lorsque nous nous abonnons aux événements DiagnosticListener , nous commençons à en recevoir même les événements qui ne nous intéressent pas, et puisque chaque événement est envoyé, un objet anonyme avec des paramètres est créé, cela peut créer une charge supplémentaire sur le GC.

Pour éviter cette situation et vous dire quels événements de DiagnosticListener nous allons traiter, nous pouvons spécifier un délégué spécial du type Predicate<string> lors de la souscription, qui prend le nom de l'événement comme paramètre et renvoie true si cet événement doit être traité.

IObserver<DiagnosticListener>.OnNext dans notre classe:

 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"; } 

Désormais, notre méthode Write sera appelée uniquement pour les événements "System.Data.SqlClient.WriteCommandBefore" et "System.Data.SqlClient.WriteCommandAfter" .

Utilisation de NuGet Package.Extensions.DiagnosticAdapter de Microsoft

Étant donné que les paramètres d'événement que nous recevons de DiagnosticListener sont généralement passés comme un objet anonyme, les récupérer par réflexion peut être trop coûteux. Heureusement, il existe un package NuGet Microsoft.Extensions.DiagnosticAdapter qui peut le faire pour nous, en utilisant la génération de code d'exécution à partir de l' System.Reflection.Emit .

Pour utiliser ce package lors de la souscription à des événements d'une instance de DiagnosticListener au lieu de la méthode Subscribe , vous devez utiliser la méthode d'extension SubscribeWithAdapter . L'implémentation de l' IObserver<KeyValuePair<string, object>> dans ce cas n'est plus nécessaire. Au lieu de cela, pour chaque événement que nous voulons gérer, nous devons déclarer une méthode distincte, en la marquant avec l'attribut DiagnosticNameAttribute (à partir de l'espace de noms Microsoft.Extensions.DiagnosticAdapter ). Les paramètres de ces méthodes seront les paramètres de l'événement en cours de traitement.

Si nous ExampleDiagnosticObserver notre classe ExampleDiagnosticObserver aide de ce package NuGet, nous obtenons le code suivant:

 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(); } } 

Ainsi, nous pouvons désormais mesurer le temps d'exécution de toutes les requêtes vers la base de données depuis notre application, pratiquement sans changer le code de l'application elle-même.

Création de vos propres instances DiagnosticListener

Lorsque vous utilisez DiagnosticSource dans la pratique, dans la plupart des cas, vous vous abonnez à des événements existants. Vous n'aurez probablement pas à créer vos propres instances de DiagnosticListener et à envoyer vos propres événements (uniquement si vous ne développez aucune bibliothèque), donc je ne m'attarderai pas sur cette section pendant longtemps.

Pour créer votre propre instance de DiagnosticListener vous devrez la déclarer en tant que variable statique quelque part dans le code:

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

Après cela, pour envoyer un événement, vous pouvez utiliser un design du formulaire:

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

Pour plus d'informations sur la création de vos propres instances de DiagnosticListener , consultez le Guide de l'utilisateur de DiagnosticSource , qui détaille les meilleures pratiques d'utilisation de DiagnosticSource.

Conclusion

L'exemple que nous avons examiné est certainement très abstrait et il est peu probable qu'il soit utile dans un vrai projet. Mais il montre parfaitement comment ce mécanisme peut être utilisé pour surveiller et diagnostiquer vos applications.

Dans le prochain article, je donnerai une liste des événements connus qui peuvent être traités via DiagnosticSource et montrer quelques exemples pratiques de son utilisation.