Usando DiagnosticSource no .NET Core: Teoria

DiagnosticSource é um conjunto de APIs simples, mas muito útil (disponível no pacote NuGet System.Diagnostics.DiagnosticSource ), que, por um lado, permite que várias bibliotecas enviem eventos nomeados sobre seu trabalho e, por outro lado, permite que aplicativos se inscrevam nesses eventos e processos eles.


Cada um desses eventos contém informações adicionais (carga útil) e, como os eventos são processados ​​no mesmo processo do envio, essas informações podem conter quase todos os objetos sem a necessidade de serialização / desserialização.


DiagnosticSource já é usado no AspNetCore, EntityFrameworkCore, HttpClient e SqlClient, o que realmente oferece aos desenvolvedores a capacidade de interceptar solicitações HTTP de entrada / saída, solicitações de banco de dados, objetos de acesso como HttpContext , DbConnection , DbCommand , HttpRequestMessage e muitos outros objetos, se necessário.


Decidi dividir minha história sobre o DiagnosticSource em dois artigos. Neste artigo, analisaremos o princípio da operação do mecanismo com um exemplo simples e, a seguir , falarei sobre eventos existentes no .NET que podem ser processados ​​usando-o e mostraremos alguns exemplos de seu uso no OZON.ru.


Exemplo


Para entender melhor como o DiagnosticSource funciona, considere um pequeno exemplo de interceptação de consultas ao banco de dados. Imagine que temos um aplicativo de console simples que faz uma solicitação ao banco de dados e exibe o resultado no 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;"); } } } 

Para simplificar, criei o SQL Server em um contêiner de docker.


docker run
 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 

Agora imagine que temos uma tarefa: precisamos medir o tempo de execução de todas as consultas no banco de dados usando o Stopwatch e exibir os pares "Request" - "Runtime" no console.


Obviamente, você pode simplesmente QuerySingleAsync chamada QuerySingleAsync código que cria e inicia a instância do Stopwatch , para após a execução da consulta e exibe o resultado, mas existem várias dificuldades ao mesmo tempo:


  • E se o aplicativo tiver mais de uma solicitação?
  • E se o código que executa a solicitação já estiver compilado, estiver conectado ao aplicativo como um pacote NuGet e não tivermos como alterá-lo?
  • E se a consulta ao banco de dados não for feita pelo Dapper, mas pelo EntityFramework, por exemplo, e não tivermos acesso ao objeto DbCommand ou ao texto da consulta gerado que será realmente executado?

Vamos tentar resolver esse problema usando o DiagnosticSource.


Usando o pacote NuGet System.Diagnostics.DiagnosticSource


A primeira coisa a fazer depois de conectar o pacote NuGet do System.Diagnostics.DiagnosticSource é criar uma classe que manipulará os eventos de seu interesse:


 public sealed class ExampleDiagnosticObserver { } 

Para iniciar o processamento de eventos, é necessário criar uma instância dessa classe e registrá-la como um observador no objeto estático DiagnosticListener.AllListeners (localizado no espaço para nome System.Diagnostics ). Fazemos isso no início da função Main :


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

Nesse caso, o compilador nos dirá com razão que a classe ExampleDiagnosticObserver deve implementar a interface IObserver<DiagnosticListener> . Vamos implementá-lo:


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

Se executarmos este código agora, veremos que o seguinte será exibido no console:


 SqlClientDiagnosticListener SqlClientDiagnosticListener 42 

Isso significa que em algum lugar do .NET são registrados dois objetos do tipo DiagnosticListener com o nome "SqlClientDiagnosticListener" que funcionaram quando esse código foi executado.



O IObserver<DiagnosticListener>.OnNext será chamado uma vez no primeiro uso para cada instância do DiagnosticListener criada no aplicativo (geralmente elas são criadas como propriedades estáticas). Agora, apenas exibimos o nome das instâncias DiagnosticListener no console, mas, na prática, esse método precisa verificar esse nome e, se estivermos interessados ​​em processar eventos a partir dessa instância, assine-o usando o método Subscribe .


Também quero observar que, quando chamamos DiagnosticListener.AllListeners.Subscribe obteremos um objeto de subscription como resultado, o que implementa a interface IDisposable . Chamar o método Dispose nesse objeto levará à remoção da assinatura, que deve ser implementada no IObserver<DiagnosticListener>.OnCompleted .


Vamos implementar o IObserver<DiagnosticListener> novamente:


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

Agora o compilador nos dirá que nossa classe ExampleDiagnosticObserver também deve implementar a IObserver<KeyValuePair<string, object>> . Aqui precisamos implementar o IObserver<KeyValuePair<string, object>>.OnNext , que como parâmetro aceita KeyValuePair<string, object> , em que a chave é o nome do evento e o valor é um objeto anônimo (geralmente) com parâmetros arbitrários que podemos usar a seu critério. Vamos adicionar uma implementação desta 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(); } } 

Se agora executarmos o código resultante, o seguinte será exibido no 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 

No total, veremos seis eventos. Dois deles são executados antes e depois de abrir a conexão com o banco de dados, dois - antes e depois da execução do comando e mais dois - antes e depois de fechar a conexão com o banco de dados.


Cada evento contém um conjunto de parâmetros, como OperationId , ConnectionId , Connection , Command , que geralmente são passados ​​como propriedades de um objeto anônimo. Você pode obter valores digitados para essas propriedades, por exemplo, usando reflexão. (Na prática, o uso de reflexão pode não ser muito desejável. Usamos DynamicMethod para obter parâmetros de evento.)


Agora estamos prontos para resolver o problema inicial - para medir o tempo de execução de todas as solicitações ao banco de dados e exibi-lo no console junto com a solicitação original.


Altere a implementação do método Write seguinte maneira:


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

Aqui, interceptamos os eventos de início e fim da solicitação no banco de dados. Antes de executar a solicitação, criamos e iniciamos o cronômetro, salvando-o em uma variável do tipo AsyncLocal<Stopwatch> , para recuperá-lo mais tarde. Após executar a solicitação, obtemos o cronômetro lançado anteriormente, paramos, obtemos o comando executado a partir do parâmetro value via reflexão e imprimimos o resultado no console.


Se agora executarmos o código resultante, o seguinte será exibido no console:


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

Parece que já resolvemos nosso problema, mas resta um pequeno detalhe. O fato é que, quando DiagnosticListener eventos DiagnosticListener , começamos a receber dele mesmo os eventos que não são interessantes para nós e, como cada evento é enviado, um objeto anônimo com parâmetros é criado, isso pode criar uma carga extra no GC.


Para evitar essa situação e informar quais eventos do DiagnosticListener vamos processar, podemos especificar um delegado especial do tipo Predicate<string> ao se inscrever, que aceita o nome do evento como parâmetro e retorna true se esse evento for processado.


IObserver<DiagnosticListener>.OnNext em nossa 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"; } 

Agora, nosso método Write será chamado apenas para os eventos "System.Data.SqlClient.WriteCommandBefore" e "System.Data.SqlClient.WriteCommandAfter" .


Usando o NuGet Package.Extensions.DiagnosticAdapter da Microsoft


Como os parâmetros de evento que recebemos do DiagnosticListener geralmente são passados ​​como um objeto anônimo, recuperá-los através da reflexão pode ser muito caro. Felizmente, existe um pacote NuGet do Microsoft.Extensions.DiagnosticAdapter que pode fazer isso por nós, usando a geração de código de tempo de execução no System.Reflection.Emit .


Para usar este pacote ao assinar eventos de uma instância do DiagnosticListener vez do método Subscribe , você deve usar o método de extensão SubscribeWithAdapter . A implementação da IObserver<KeyValuePair<string, object>> nesse caso não é mais necessária. Em vez disso, para cada evento que desejamos manipular, precisamos declarar um método separado, marcando-o com o atributo DiagnosticNameAttribute (no espaço de nome Microsoft.Extensions.DiagnosticAdapter ). Os parâmetros desses métodos serão os parâmetros do evento que está sendo processado.


Se reescrevermos a nossa classe ExampleDiagnosticObserver usando este pacote NuGet, obteremos o seguinte código:


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

Assim, agora podemos medir o tempo de execução de todas as consultas ao banco de dados de nosso aplicativo, praticamente sem alterar o código do próprio aplicativo.


Criando suas próprias instâncias DiagnosticListener


Ao usar o DiagnosticSource na prática, na maioria dos casos, você se inscreverá nos eventos existentes. Provavelmente, você não precisará criar suas próprias instâncias do DiagnosticListener e enviar seus próprios eventos (apenas se você não estiver desenvolvendo nenhuma biblioteca); portanto, não vou me deter nesta seção por muito tempo.


Para criar sua própria instância do DiagnosticListener será necessário declará-la como uma variável estática em algum lugar do código:


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

Depois disso, para enviar um evento, você pode usar um design do formulário:


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

Para obter mais informações sobre como criar suas próprias instâncias do DiagnosticListener , consulte o Guia do usuário do DiagnosticSource , que detalha as práticas recomendadas para usar o DiagnosticSource.


Conclusão


O exemplo que examinamos é certamente muito abstrato e dificilmente será útil em um projeto real. Mas mostra perfeitamente como esse mecanismo pode ser usado para monitorar e diagnosticar seus aplicativos.


No próximo artigo, darei uma lista de eventos conhecidos por mim que podem ser processados ​​por meio do DiagnosticSource e mostrarei alguns exemplos práticos de seu uso.

Source: https://habr.com/ru/post/pt435896/


All Articles