Freqüentemente, é necessário coletar estatísticas sobre o desempenho dos métodos de aplicativo em tempo real (quando o aplicativo já está sendo executado) para identificar seus gargalos e ver qual parte do aplicativo está desacelerando.
Além disso, seria bom, além dos próprios dados de desempenho (tempo de desenvolvimento do método, data de início e término da chamada) armazenar um contexto de chamada no qual o desempenho é monitorado (como argumentos de chamada de método e dados arbitrários adicionados pelo desenvolvedor).
Bem, a "cereja no bolo" pode ser considerada a conveniência e simplicidade da ferramenta utilizada, o que também é importante.
Para resolver esses problemas, foi desenvolvida uma biblioteca .NET de código aberto de plataforma cruzada, Unchase.FluentPerformanceMeter .
1. Introdução
Portanto, este artigo é uma descrição do trabalho com o Unchase Fluent Performance Meter , uma biblioteca .Net Standard 2.0 de código aberto de plataforma cruzada, projetada para calcular o desempenho dos métodos.
A biblioteca pode ser usada em aplicativos .NET Core e .NET Framework compatíveis com o .Net Standard 2.0 e permite:
- Faça medições precisas do desempenho de métodos públicos para classes públicas , tanto do seu código quanto do código das bibliotecas usadas (com a fixação da hora exata do início e do final da medição);
- Adicione dados adicionais ( dados personalizados) aos resultados da medição. Por exemplo, os valores dos parâmetros de entrada do método e o resultado; ou dados de contexto de execução do método; ou corellationId , pelo qual será possível vincular várias medições do desempenho dos métodos;
- Divida a medição de desempenho do método em etapas separadas (etapas) com a fixação de dados próprios para cada etapa. Além disso, você pode definir o tempo de execução mínimo , a partir do qual a etapa será levada em consideração na medição (se a etapa for concluída mais rapidamente, ela não será medida);
- Excluir partes individuais do código da medição de desempenho (por exemplo, chamadas para métodos individuais cujo tempo de execução não precisa ser levado em consideração na medição);
- Adicione seus próprios comandos (comandos), que são garantidos para serem executados imediatamente após o final da medição de desempenho do método (por exemplo, para adicionar processamento adicional dos resultados obtidos, como registrar ou gravar dados no armazenamento);
- Adicione seu próprio manipulador de exceção para o código executado no contexto da medição do desempenho do método (comum para todas as medições e para cada medição separadamente);
- Defina o tempo para armazenar os resultados das medições da produtividade dos métodos, após os quais os resultados serão excluídos;
- Adicione dados sobre quem chama o método (Chamador) via IHttpContextAccesor ou a tarefa do Chamador no código aos resultados da medição (por exemplo, você pode especificar o nome do serviço externo que chamou o método);
- Adicione aos dados dos resultados da medição o local onde a medição de desempenho foi iniciada (nome do arquivo e número da linha com o local da chamada no código);
- Interromper a medição do desempenho do método antes do final de sua execução .
Os dados obtidos como resultado da medição do desempenho dos métodos podem ser usados para analisar o desempenho do aplicativo (suas partes individuais, tanto interna - código nativo quanto externo - o código das bibliotecas utilizadas) e exibidos em uma forma gráfica conveniente para você.
Conteúdo
Introdução
Para usar a biblioteca, instale o pacote NuGet no seu projeto:
Usando manualmente o NuGet Package Manager:
Install-Package Unchase.FluentPerformanceMeter
Usando a CLI do .NET:
dotnet add package Unchase.FluentPerformanceMeter --version {version}
Onde {version} é a versão do pacote que você deseja instalar.
Por exemplo, o dotnet add package Unchase.FluentPerformanceMeter --version 1.0.0
Exemplos de uso
Método de Medição de Desempenho
A seguir, é apresentado um exemplo simples de uso da biblioteca (sem configuração e configurações adicionais) para medir o desempenho do SimpleWatchingMethodStart (Action) SimpleWatchingMethodStart controller (Controller) PerformanceMeterController Asp.Net Core 2.2 WebAPI . Para fazer isso, você pode usar o método de extensão .WatchingMethod().Start() ou uma funcionalidade semelhante .StartWatching() .
Desde a v1.0.5, você também pode usar .WatchingMethod().Start(SimpleWatchingMethodStart) ou .StartWatching(SimpleWatchingMethodStart) com o nome do método.
Todos os exemplos de uso da biblioteca podem ser encontrados nos projetos Unchase.FluentPerformanceMeter.Test* deste repositório .
/// <summary> /// Test GET method with simple performance watching. /// </summary> [HttpGet("SimpleWatchingMethodStart")] public ActionResult SimpleWatchingMethodStart() { // for C# 8 you can use: //using var pm = PerformanceMeter<PerformanceMeterController>.StartWatching(); using (PerformanceMeter<PerformanceMeterController>.WatchingMethod().Start()) { // put your code with some logic here return Ok(); } }
Para obter os resultados das medições de desempenho de métodos públicos da classe de controlador PerformanceMeterController , você pode chamar o seguinte método:
/// <summary> /// Get methods performance info for this controller. /// </summary> /// <returns>Returns methods performance info.</returns> [HttpGet("GetPerformanceInfo")] [IgnoreMethodPerformance] public ActionResult<IPerformanceInfo> GetPerformanceInfo() { return Ok(PerformanceMeter<PerformanceMeterController>.PerformanceInfo); }
Depois de chamar o método SimpleWatchingMethodStart ao chamar GetPerformanceInfo , obtemos:
{ "methodCalls": [ { "methodName": "SimpleWatchingMethodStart", "elapsed": "00:00:00.0016350", "caller": "unknown", "startTime": "2019-12-06T10:27:27.3385385Z", "endTime": "2019-12-06T10:27:27.3401735Z", "customData": {}, "steps": [] } ], "totalActivity": [ { "methodName": "SimpleWatchingMethodStart", "callsCount": 1 } ], "currentActivity": [ { "methodName": "SimpleWatchingMethodStart", "callsCount": 0 } ], "uptimeSince": "2019-12-06T10:27:27.3370183Z", "className": "Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController", "methodNames": [ "SimpleWatchingMethodStart" ], "customData": {}, "timerFrequency": 10000000 }
A partir da versão v1.1.0 , tornou-se possível medir o desempenho dos métodos em um aplicativo AspNetCore MVC usando o DiagnosticSource e o atributo WatchingWithDiagnosticSourceAttribute especial.
Para fazer isso, adicione o pacote Unchase.FluentPerformanceMeter.AspNetCore.Mvc ao projeto NuGet e adicione o seguinte código ao Startap.cs :
public void ConfigureServices(IServiceCollection services) { // ... // allows to measure methods performance for class "MeasurableClass" and "MeasurableSecondClass" services.AddPerformanceDiagnosticObserver<MeasurableClass>(); services.AddPerformanceDiagnosticObserver<MeasurableSecondClass>(); // ... the same for another classes services.AddMvc(); // ... } public void Configure(IApplicationBuilder app, IHostingEnvironment env) { // ... app.UsePerformanceDiagnosticObserver(); app.UseMvc(); }
Em seguida, marque com o atributo WatchingWithDiagnosticSourceAttribute ou métodos individuais:
[HttpGet("SimpleWatchingMethodStart")] [WatchingWithDiagnosticSource] public ActionResult SimpleWatchingMethodStart() { return Ok(); }
ou toda a classe:
[ApiController] [Route("api/v1/[controller]")] [Produces("application/json")] [SwaggerTag("Unchase.PerformanceMeter Test WebAPI Controller")] [WatchingWithDiagnosticSource] public class PerformanceMeterController : ControllerBase { // measurable methods }
A partir da versão v1.2.0 , tornou-se possível incluir argumentos de chamada nos dados de medição de desempenho do método do usuário em um aplicativo AspNetCore MVC usando o atributo especial AddMethodArgumentsToCustomDataAttribute em conjunto com o atributo WatchingWithDiagnosticSourceAttribute :
[HttpPost("SimpleWatchingMethodStartWithArgs")] [WatchingWithDiagnosticSource] [AddMethodArgumentsToCustomData("actionArguments")] public ActionResult SimpleWatchingMethodStartWithArgs(DTOArgument arg) { return Ok(); }
Depois de chamar o método SimpleWatchingMethodStartWithArgs ao chamar GetPerformanceInfo , obtemos:
{ "methodCalls": [ { "methodName": "SimpleWatchingMethodStartWithArgs", "elapsed": "00:00:00.0016350", "caller": "unknown", "startTime": "2019-12-06T10:27:27.3385385Z", "endTime": "2019-12-06T10:27:27.3401735Z", "customData": { "actionArguments": { "arg": { "data": "<string_in_DTOArgument>" } } }, "steps": [] } ], "totalActivity": [ { "methodName": "SimpleWatchingMethodStartWithArgs", "callsCount": 1 } ], "currentActivity": [ { "methodName": "SimpleWatchingMethodStartWithArgs", "callsCount": 0 } ], "uptimeSince": "2019-12-06T10:27:27.3370183Z", "className": "Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController", "methodNames": [ "SimpleWatchingMethodStartWithArgs" ], "customData": {}, "timerFrequency": 10000000 }
Medindo o desempenho do método usado pela biblioteca
Para medir o desempenho do método público da classe pública da biblioteca de terceiros usada, você deve definir explicitamente a própria classe e seu nome do método:
[HttpGet("GetThreadSleepPerformance")] public ActionResult<string> GetThreadSleepPerformance() { using (PerformanceMeter<Thread>.WatchingMethod(nameof(Thread.Sleep)).Start()) { Thread.Sleep(1000); } return Ok(PerformanceMeter<Thread>.PerformanceInfo.MethodCalls.FirstOrDefault(ta => ta.MethodName == nameof(Thread.Sleep))?.Elapsed); }
O método executado retornará:
"00:00:01.0033040"
Você pode obter dados sobre como chamar esse método por meio de uma chamada:
/// <summary> /// Get methods performance info for Thread class. /// </summary> /// <returns>Returns Thread methods performance info.</returns> [HttpGet("GetThreadPerformanceInfo")] [IgnoreMethodPerformance] public ActionResult<IPerformanceInfo> GetThreadPerformanceInfo() { return Ok(PerformanceMeter<Thread>.PerformanceInfo); }
O atributo IgnoreMethodPerformance projetado para que o método que ele IgnoreMethodPerformance não seja levado em consideração ao medir o desempenho.
Em resposta à chamada para este método será:
{ "methodCalls": [ { "methodName": "Sleep", "elapsed": "00:00:01.0033040", "caller": "unknown", "startTime": "2019-12-06T13:08:09.336624Z", "endTime": "2019-12-06T13:08:10.339928Z", "customData": {}, "steps": [] } ], "totalActivity": [ { "methodName": "Abort", "callsCount": 0 }, // ... { "methodName": "Sleep", "callsCount": 1 } // ... ], "currentActivity": [ { "methodName": "Abort", "callsCount": 0 }, // ... { "methodName": "Sleep", "callsCount": 1 } // ... ], "uptimeSince": "2019-12-06T13:08:09.3357028Z", "className": "System.Threading.Thread", "methodNames": [ "Abort", // ... "Sleep", // ... ], "customData": {}, "timerFrequency": 10000000 }
Adicionando dados adicionais (dados personalizados) e paginação (etapas)
Você pode adicionar dados adicionais (dados personalizados) para todas as medidas de desempenho dos métodos de uma classe específica. Por exemplo, no construtor estático da classe do controlador PerformanceMeterController :
[ApiController] [Route("api/v1/[controller]")] public class PerformanceMeterController : ControllerBase { /// <summary> /// Static constructor. /// </summary> static PerformanceMeterController() { // add common custom data (string) to class performance information PerformanceMeter<PerformanceMeterController>.AddCustomData("Tag", "CustomTag"); // add common custom data (anonymous class) to class performance information PerformanceMeter<PerformanceMeterController>.AddCustomData("Custom anonymous class", new { Name = "Custom Name", Value = 1 }); } // ... actions }
Além disso, você pode adicionar dados adicionais (Dados Customizados) para uma medida específica usando o método de extensão .WithSettingData.CustomData("<key>", <value>) (inclusive por meio de um atributo especial do método MethodCustomDataAttribute ) e para cada etapa (Etapa ) dessa medida, adicionada usando o .Step("<step_name>") extensão .Step("<step_name>") , usando o .AddCustomData("<key>", <value>) extensão .AddCustomData("<key>", <value>) :
/// <summary> /// Test GET method with simple performance watching (with steps). /// </summary> [HttpGet("SimpleStartWatchingWithSteps")] [MethodCustomData("Custom data from attribute", "Attr")] public ActionResult SimpleStartWatchingWithSteps() { using (var pm = PerformanceMeter<PerformanceMeterController> .WatchingMethod() .WithSettingData .CustomData("coins", 1) .CustomData("Coins sets", new { Gold = "Many", Silver = 5 }) .Start()) { // put your code with some logic here // add "Step 1" using (pm.Step("Step 1")) { Thread.Sleep(1000); } // add "Step 2" with custom data using (var pmStep = pm.Step("Step 2").AddCustomData("step2 custom data", "data!")) { // add "Step 3 in Step 2" using (pm.Step("Step 3 in Step 2")) { Thread.Sleep(1000); } // add custom data to "Step 2" pmStep.AddCustomData("step2 another custom data", "data2!"); // get and remove custom data from "Step 2" var customData = pmStep.GetAndRemoveCustomData<string>("step2 custom data"); // get custom data from "Step 2" (without removing) var anotherCustomData = pmStep.GetCustomData<string>("step2 another custom data"); // ... } } }
Como resultado, ao chamar GetPerformanceInfo , obtemos:
{ "methodCalls": [ { "methodName": "SimpleStartWatchingWithSteps", "elapsed": "00:00:02.0083031", "caller": "unknown", "startTime": "2019-12-06T11:58:18.9006891Z", "endTime": "2019-12-06T11:58:20.9089922Z", "customData": { "Coins sets": { "gold": "Many", "silver": 5 }, "coins": 1, "Custom data from attribute": "Attr" }, "steps": [ { "stepName": "Step 1", "elapsed": "00:00:01.0009758", "startTime": "2019-12-06T11:58:18.9018272Z", "endTime": "2019-12-06T11:58:19.902803Z", "customData": {} }, { "stepName": "Step 3 in Step 2", "elapsed": "00:00:01.0004549", "startTime": "2019-12-06T11:58:19.9046523Z", "endTime": "2019-12-06T11:58:20.9051072Z", "customData": {} }, { "stepName": "Step 2", "elapsed": "00:00:01.0029596", "startTime": "2019-12-06T11:58:19.904534Z", "endTime": "2019-12-06T11:58:20.9074936Z", "customData": { "step2 another custom data": "data2!" } } ] } ], "totalActivity": [ { "methodName": "SimpleStartWatchingWithSteps", "callsCount": 1 } ], "currentActivity": [ { "methodName": "SimpleStartWatchingWithSteps", "callsCount": 0 } ], "uptimeSince": "2019-12-06T11:58:18.8801249Z", "className": "Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController", "methodNames": [ "SimpleStartWatchingWithSteps" ], "customData": { "Tag": "CustomTag", "Custom anonymous class": { "name": "Custom Name", "value": 1 } }, "timerFrequency": 10000000 }
Exceção da medição (Ignorar)
Você pode ignorar partes individuais do método na medição de desempenho (usando .Ignore() ou .Executing().WithoutWatching().Start(<Action>) ) e também não salva etapas individuais (método de extensão .StepIf("<step_name>", <minSaveMs>) ) se eles não .StepIf("<step_name>", <minSaveMs>) à condição (o tempo de execução da etapa será levado em consideração no tempo de execução do método):
using (var pm = PerformanceMeter<PerformanceMeterController>.WatchingMethod().Start()) { // put your code with some logic here // sleep 1 sec Thread.Sleep(1000); // ignore this block in performance watching using (pm.Ignore()) { Thread.Sleep(5000); } // skip this step with minSaveMs (not save, but consider duration in method performance watching) using (pm.StepIf("Skipped step", minSaveMs: 1000)) { Thread.Sleep(500); } // execute action without performance watching pm.Executing().WithoutWatching().Start(() => { Thread.Sleep(2000); }); return Ok(); }
Como resultado, obtemos:
{ "methodCalls": [ { "methodName": "SimpleStartWatchingWithIgnored", "elapsed": "00:00:01.5080227", "caller": "unknown", "startTime": "2019-12-06T12:34:36.9187359Z", "endTime": "2019-12-06T12:34:38.4267586Z", "customData": {}, "steps": [] } ], "totalActivity": [ { "methodName": "SimpleStartWatchingWithIgnored", "callsCount": 1 } ], "currentActivity": [ { "methodName": "SimpleStartWatchingWithIgnored", "callsCount": 0 } ], "uptimeSince": "2019-12-06T12:34:36.9035129Z", "className": "Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController", "methodNames": [ "SimpleStartWatchingWithIgnored" ], "customData": { }, "timerFrequency": 10000000 }
Adicionando comandos e ações
Para adicionar um comando que será garantido para ser executado após a conclusão da medição do desempenho de um método, você deve criar uma classe de comando que implementará a interface IPerformanceCommand .
Ao mesmo tempo, você pode transferir dados arbitrários através do construtor do comando criado que será usado durante sua execução. Por exemplo:
/// <summary> /// Custom executed command. /// </summary> public class ExecutedCommand : IPerformanceCommand { /// <summary> /// Executed commad name. /// </summary> public string CommandName => this.GetType().Name; private string _customString { get; } internal bool IsCommandExecuted { get; private set; } /// <summary> /// Constructor. /// </summary> /// <remarks> /// You can pass any data through the command constructor. /// </remarks> /// <param name="customString"></param> public ExecutedCommand(string customString) { this._customString = customString; } /// <summary> /// Execute command. /// </summary> /// <param name="performanceInfo"><see cref="IPerformanceInfo"/>.</param> public void Execute(IPerformanceInfo performanceInfo) { // for example, write to the debug console some information Debug.WriteLine(this.CommandName); Debug.WriteLine(this._customString); Debug.WriteLine($"Method names count: {performanceInfo.MethodNames.Count}"); this.IsCommandExecuted = true; } }
Você pode adicionar um comando (IPerformanceCommand) e uma ação (Action) para que eles sejam executados no final da medição, da seguinte maneira:
// custom "ExecutedCommand" will be executed after performance watching is completed using (PerformanceMeter<PerformanceMeterController> .WatchingMethod() .WithExecutingOnComplete .Command(new ExecutedCommand("bla-bla-bla")) .Action((pi) => { Debug.WriteLine($"Class name: {pi.ClassName}"); }) .Start()) { return Ok(); }
Como resultado, ao final da medição do desempenho do método no console de depuração , ele exibirá:
ExecutedCommand bla-bla-bla Method names count: 13 Class name: Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController
Adicionando manipuladores de exceção
Se você precisar manipular exceções que possam ocorrer durante a execução de uma parte do método para a qual o desempenho é monitorado, adicione um manipulador de Exceção da seguinte maneira:
using (var pm = PerformanceMeter<PerformanceMeterController>.StartWatching()) { // execute action throws Exception with exception handler pm.Executing() .WithExceptionHandler((ex) => Debug.WriteLine(ex.Message)) .Start(() => throw new Exception("Exception")); // execute action throws custom Exception with exception handler pm.Executing<CustomException>() .WithExceptionHandler((ex) => { Debug.WriteLine(ex.Message); }) .Start(() => { throw new CustomException("Custom exception was occured!"); }); return Ok(); }
Onde está a classe CustomException , por exemplo:
/// <summary> /// Custom exception. /// </summary> public class CustomException : Exception { public CustomException(string message) : base(message) { } public CustomException(string message, Exception innerException) : base(message, innerException) { } public CustomException() { } }
Como resultado, o console Debug exibirá:
Exception Custom exception was occured!
Além disso, você pode especificar um manipulador de exceção que será usado por padrão para medir o desempenho de qualquer método dessa classe, por exemplo, através do construtor estático da classe do controlador PerformanceMeterController :
[ApiController] [Route("api/v1/[controller]")] public class PerformanceMeterController : ControllerBase { /// <summary> /// Static constructor. /// </summary> static PerformanceMeterController() { // set default exception handler for PerformanceMeterController class PerformanceMeter<PerformanceMeterController>.SetDefaultExceptionHandler((ex) => Debug.WriteLine(ex.Message)); } // ... actions }
Definindo o tempo de armazenamento de dados (Definir tempo de cache)
Você pode definir o tempo de armazenamento para os dados das medidas de desempenho dos métodos, após os quais esses dados serão excluídos. Para cada classe para a qual a medição é feita, esse tempo é definido separadamente. Por exemplo, o tempo pode ser definido através do construtor estático da classe do controlador PerformanceMeterController :
[ApiController] [Route("api/v1/[controller]")] public class PerformanceMeterController : ControllerBase { /// <summary> /// Static constructor. /// </summary> static PerformanceMeterController() { // set cache time for PerformanceMeterController class PerformanceMeter<PerformanceMeterController>.SetMethodCallsCacheTime(5); } // ... actions }
Adicionando dados sobre o método de chamada e o local da chamada (e interrompendo a medição do desempenho)
Você pode especificar quem está chamando o método usando o método de extensão .CallerFrom("<caller_name>") (uma cadeia ou IHttpContextAccessor é passada a ele ) ou um atributo especial do método [MethodCaller("<caller_name>")] . Além disso, se o atributo e o método de extensão forem usados, o valor será obtido deste último.
O método de extensão .WithSettingData.CallerSourceData() usado para adicionar um ponto de chamada para medir o desempenho.
Para parar de medir o desempenho dentro do bloco using , use o método de extensão .StopWatching() ou o método Dispose() diretamente:
[HttpPost("StartWatchingWithCallerName")] [MethodCaller("testCaller")] public ActionResult<string> StartWatchingWithCallerName([FromBody] string value) { // method performance info will reach with caller name (if internal HttpContextAccessor is null) using (var pm = PerformanceMeter<PerformanceMeterController> .WatchingMethod() .WithSettingData .CallerSourceData() .CallerFrom("Test caller") .Start()) { pm.StopWatching(); // stop watching here (or you can use "pm.Dispose();") Thread.Sleep(2000); return Ok(value); } }
Como resultado da chamada do método GetPerformanceInfo , GetPerformanceInfo obtém:
{ "methodCalls": [ { "methodName": "StartWatchingWithCallerName", "elapsed": "00:00:00.0019172", "caller": "Test caller", "startTime": "2019-12-06T13:35:45.3164507Z", "endTime": "2019-12-06T13:35:45.3183679Z", "customData": { "customData123": 123, "callerSourceLineNumber": 525, "callerSource": "D:\\GitHub\\Unchase.FluentPerformanceMeter\\Unchase.FluentPerformanceMeter.TestWebAPI\\Controllers\\PerformanceMeterController.cs" }, "steps": [] } ], "totalActivity": [ { "methodName": "StartWatchingWithCallerName", "callsCount": 1 } ], "currentActivity": [ { "methodName": "StartWatchingWithCallerName", "callsCount": 0 } ], "uptimeSince": "2019-12-06T13:35:45.2601668Z", "className": "Unchase.FluentPerformanceMeter.TestWebAPI.Controllers.PerformanceMeterController", "methodNames": [ "StartWatchingWithCallerName" ], "customData": { }, "timerFrequency": 10000000 }
Conclusão
Assim, a solução apresentada nos permite automatizar parcialmente a coleta de informações sobre o desempenho dos métodos de aplicativos .NET de uma maneira bastante conveniente. Os dados coletados podem ser visualizados de uma maneira mais adequada para cada desenvolvedor específico.
Obviamente, a biblioteca não resolve todos os problemas associados à coleta de dados sobre o desempenho dos métodos, mas procura simplificar os mais comuns.
A biblioteca é uma solução de código aberto, todas as sugestões e sugestões para o seu desenvolvimento são bem-vindas, assim como os relatórios de erros (todos podem seguir o link ; o autor agradece por qualquer ajuda!).