Tutorial: Medición del rendimiento mediante EventCounters en .NET Core

  • Artículo

Este artículo se aplica a: ✔️ SDK de .NET Core 3.0 y versiones posteriores

En este tutorial se aprende a usar un EventCounter para medir el rendimiento con una alta frecuencia de eventos. Puede usar los contadores disponibles publicados por diversos paquetes oficiales de .NET Core, proveedores de terceros o crear sus propias métricas para la supervisión.

En este tutorial va a:

Requisitos previos

En el tutorial se usa:

Obtención del origen

Se va a usar la aplicación de ejemplo como base para la supervisión. El repositorio de ASP.NET Core de ejemplo está disponible en el explorador de ejemplos. Descargue el archivo zip, extráigalo una vez descargado y ábralo en el IDE que prefiera. Compile y ejecute la aplicación para asegurarse de que funciona correctamente y luego deténgala.

Implementación de un EventSource

En el caso de los eventos que se producen cada pocos milisegundos, se recomienda que la sobrecarga por evento sea baja (menos de un milisegundo). De lo contrario, el impacto sobre el rendimiento es considerable. El registro de un evento significa que se va a escribir algo en el disco. Si el disco no es lo suficientemente rápido, se pierden eventos. Necesita una solución que no sea el registro del propio evento.

Al trabajar con un gran número de eventos, conocer la medida por evento tampoco es útil. La mayor parte del tiempo, todo lo que se necesita son algunas estadísticas. Por lo tanto, podría obtener las estadísticas dentro del propio proceso y luego escribir un evento de vez en cuando para comunicar las estadísticas, que es lo que hace EventCounter.

A continuación se muestra un ejemplo de cómo implementar un System.Diagnostics.Tracing.EventSource. Cree un nuevo archivo denominado MinimalEventCounterSource.cs y use el fragmento de código como su origen:

using System.Diagnostics.Tracing;

[EventSource(Name = "Sample.EventCounter.Minimal")]
public sealed class MinimalEventCounterSource : EventSource
{
    public static readonly MinimalEventCounterSource Log = new MinimalEventCounterSource();

    private EventCounter _requestCounter;

    private MinimalEventCounterSource() =>
        _requestCounter = new EventCounter("request-time", this)
        {
            DisplayName = "Request Processing Time",
            DisplayUnits = "ms"
        };

    public void Request(string url, long elapsedMilliseconds)
    {
        WriteEvent(1, url, elapsedMilliseconds);
        _requestCounter?.WriteMetric(elapsedMilliseconds);
    }

    protected override void Dispose(bool disposing)
    {
        _requestCounter?.Dispose();
        _requestCounter = null;

        base.Dispose(disposing);
    }
}

La línea EventSource.WriteEvent es la parte EventSource y no forma parte de EventCounter, se ha escrito para mostrar que se puede registrar un mensaje junto con el contador de eventos.

Incorporación de un filtro de acción

El código fuente de ejemplo es un proyecto de ASP.NET Core. Puede agregar un filtro de acción globalmente que registre el tiempo total de las solicitudes. Cree un nuevo archivo denominado LogRequestTimeFilterAttribute.cs y use el código siguiente:

using System.Diagnostics;
using Microsoft.AspNetCore.Http.Extensions;
using Microsoft.AspNetCore.Mvc.Filters;

namespace DiagnosticScenarios
{
    public class LogRequestTimeFilterAttribute : ActionFilterAttribute
    {
        readonly Stopwatch _stopwatch = new Stopwatch();

        public override void OnActionExecuting(ActionExecutingContext context) => _stopwatch.Start();

        public override void OnActionExecuted(ActionExecutedContext context)
        {
            _stopwatch.Stop();

            MinimalEventCounterSource.Log.Request(
                context.HttpContext.Request.GetDisplayUrl(), _stopwatch.ElapsedMilliseconds);
        }
    }
}

El filtro de acción inicia Stopwatch cuando comienza la solicitud y se detiene cuando termina, capturando el tiempo transcurrido. Los milisegundos totales se registran en la instancia singleton MinimalEventCounterSource. Para aplicar este filtro, debe agregarlo a la colección de filtros. En el archivo Startup.cs, actualice el método ConfigureServices al incluir este filtro.

public void ConfigureServices(IServiceCollection services) =>
    services.AddControllers(options => options.Filters.Add<LogRequestTimeFilterAttribute>())
            .AddNewtonsoftJson();

Supervisión del contador de eventos

Con la implementación en un EventSource y el filtro de acción personalizado, compile e inicie la aplicación. Ha registrado la métrica en el EventCounter, pero a menos que acceda a las estadísticas de este, esto no es útil. Para obtener las estadísticas, debe habilitar el EventCounter mediante la creación de un temporizador que se active con la frecuencia con que quiera que los eventos,así como una escucha, capturen los eventos. Para ello, puede usar dotnet-counters.

Use el comando dotnet-counters ps para mostrar una lista de procesos de .NET que se pueden supervisar.

dotnet-counters ps

Con el identificador de proceso de la salida del comando dotnet-counters ps, puede empezar a supervisar el contador de eventos con el siguiente comando dotnet-counters monitor:

dotnet-counters monitor --process-id 2196 --counters Sample.EventCounter.Minimal,Microsoft.AspNetCore.Hosting[total-requests,requests-per-second],System.Runtime[cpu-usage]

Mientras se ejecuta el comando dotnet-counters monitor, mantenga presionada la tecla F5 en el explorador para iniciar la emisión de solicitudes continuas al punto de conexión https://localhost:5001/api/values. Tras unos segundos, detenga al presionar q.

Press p to pause, r to resume, q to quit.
    Status: Running

[Microsoft.AspNetCore.Hosting]
    Request Rate / 1 sec                               9
    Total Requests                                   134
[System.Runtime]
    CPU Usage (%)                                     13
[Sample.EventCounter.Minimal]
    Request Processing Time (ms)                      34.5

El comando dotnet-counters monitor es excelente para la supervisión activa. Pero se recomienda recopilar estas métricas de diagnóstico para el procesamiento y el análisis posteriores. Para ello,use el comando dotnet-counters collect. El comando modificador collect es similar al comando monitor, pero acepta algunos parámetros adicionales. Puede especificar el nombre de archivo de salida y el formato que quiera. En el caso de un archivo JSON denominado diagnostics.json, use el siguiente comando:

dotnet-counters collect --process-id 2196 --format json -o diagnostics.json --counters Sample.EventCounter.Minimal,Microsoft.AspNetCore.Hosting[total-requests,requests-per-second],System.Runtime[cpu-usage]

Una vez más, mientras se ejecuta el comando, mantenga presionada la tecla F5 en el explorador para iniciar la emisión de solicitudes continuas al punto de conexión https://localhost:5001/api/values. Tras unos segundos, detenga al presionar q. Se escribe el archivo diagnostics.json. Pero no se aplica sangría al archivo JSON escrito; para mejorar la legibilidad, la sangría se aplica aquí.

{
  "TargetProcess": "DiagnosticScenarios",
  "StartTime": "8/5/2020 3:02:45 PM",
  "Events": [
    {
      "timestamp": "2020-08-05 15:02:47Z",
      "provider": "System.Runtime",
      "name": "CPU Usage (%)",
      "counterType": "Metric",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:47Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Request Rate / 1 sec",
      "counterType": "Rate",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:47Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Total Requests",
      "counterType": "Metric",
      "value": 134
    },
    {
      "timestamp": "2020-08-05 15:02:47Z",
      "provider": "Sample.EventCounter.Minimal",
      "name": "Request Processing Time (ms)",
      "counterType": "Metric",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:47Z",
      "provider": "System.Runtime",
      "name": "CPU Usage (%)",
      "counterType": "Metric",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:48Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Request Rate / 1 sec",
      "counterType": "Rate",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:48Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Total Requests",
      "counterType": "Metric",
      "value": 134
    },
    {
      "timestamp": "2020-08-05 15:02:48Z",
      "provider": "Sample.EventCounter.Minimal",
      "name": "Request Processing Time (ms)",
      "counterType": "Metric",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:48Z",
      "provider": "System.Runtime",
      "name": "CPU Usage (%)",
      "counterType": "Metric",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:50Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Request Rate / 1 sec",
      "counterType": "Rate",
      "value": 0
    },
    {
      "timestamp": "2020-08-05 15:02:50Z",
      "provider": "Microsoft.AspNetCore.Hosting",
      "name": "Total Requests",
      "counterType": "Metric",
      "value": 134
    },
    {
      "timestamp": "2020-08-05 15:02:50Z",
      "provider": "Sample.EventCounter.Minimal",
      "name": "Request Processing Time (ms)",
      "counterType": "Metric",
      "value": 0
    }
  ]
}

Pasos siguientes

EventCounters