Rejestrowanie o wysokiej wydajności na platformie .NET

  • Artykuł

Klasa LoggerMessage uwidacznia funkcje tworzenia delegatów z możliwością buforowania, które wymagają mniejszej liczby alokacji obiektów i mniejszego obciążenia obliczeniowego w porównaniu z metodami rozszerzenia rejestratora, takimi jak LogInformation i LogDebug. W przypadku scenariuszy rejestrowania o wysokiej wydajności użyj LoggerMessage wzorca.

LoggerMessage zapewnia następujące zalety wydajności w porównaniu z metodami rozszerzeń rejestratora:

  • Metody rozszerzenia rejestratora wymagają typów wartości typu "boxing" (konwertowanie), takich jak int, na object. Wzorzec LoggerMessage unika tworzenia pól statycznych Action i metod rozszerzeń z silnie typinymi parametrami.
  • Metody rozszerzenia rejestratora muszą analizować szablon komunikatu (nazwany ciąg formatu) za każdym razem, gdy jest zapisywany komunikat dziennika. LoggerMessage Wymaga analizowania szablonu tylko raz po zdefiniowaniu komunikatu.

Ważne

Zamiast używać klasy LoggerMessage do tworzenia dzienników o wysokiej wydajności, można użyć atrybutu LoggerMessage na platformie .NET 6 i nowszych wersjach. Zapewnia LoggerMessageAttribute obsługę rejestrowania generacji źródła przeznaczonej do dostarczania wysoce użytecznego i wysoce wydajnego rozwiązania do rejestrowania dla nowoczesnych aplikacji platformy .NET. Aby uzyskać więcej informacji, zobacz Kompilowanie generowania źródła rejestrowania czasu (Podstawy platformy .NET).

Przykładowa aplikacja demonstruje LoggerMessage funkcje z priorytetową usługą procesu roboczego przetwarzania kolejek. Aplikacja przetwarza elementy robocze w kolejności priorytetu. W miarę występowania LoggerMessage tych operacji komunikaty dziennika są generowane przy użyciu wzorca.

Napiwek

Cały przykładowy kod źródłowy rejestrowania jest dostępny w przeglądarce Samples Browser do pobrania. Aby uzyskać więcej informacji, zobacz Przeglądanie przykładów kodu: Rejestrowanie na platformie .NET.

Definiowanie komunikatu rejestratora

Użyj polecenia Define(LogLevel, EventId, String), aby utworzyć delegata Action na potrzeby rejestrowania komunikatu. Define przeciążenia umożliwiają przekazywanie maksymalnie sześciu parametrów typu do nazwanego ciągu formatu (szablonu).

Ciąg podany w metodzie Define jest szablonem, a nie ciągiem interpolowanym. Symbole zastępcze są wypełniane w kolejności określonej przez typy. Nazwy symboli zastępczych w szablonie powinny być opisowe i spójne w szablonach. Służą one jako nazwy właściwości w danych dziennika ustrukturyzowanego. Zalecamy stosowanie wielkości liter w języku Pascal dla nazw symboli zastępczych. Na przykład , {Item}. {DateTime}

Każdy komunikat dziennika jest Action przechowywany w polu statycznym utworzonym przez loggerMessage.Define. Na przykład przykładowa aplikacja tworzy pole do opisania komunikatu dziennika na potrzeby przetwarzania elementów roboczych:

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Dla parametru Actionokreśl następujące elementy:

  • Poziom dziennika.
  • Unikatowy identyfikator zdarzenia (EventId) o nazwie metody rozszerzenia statycznego.
  • Szablon wiadomości (nazwany ciąg formatu).

Ponieważ elementy robocze są w kolejce do przetwarzania, aplikacja usługi procesu roboczego ustawia następujące elementy:

  • Poziom dziennika do LogLevel.Critical.
  • Identyfikator zdarzenia do 13 z nazwą FailedToProcessWorkItem metody.
  • Szablon komunikatu (nazwany ciąg formatu) do ciągu.
s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

Metoda LoggerMessage.Define służy do konfigurowania i definiowania delegata Action , który reprezentuje komunikat dziennika.

Magazyny rejestrowania ze strukturą mogą używać nazwy zdarzenia, gdy jest dostarczany z identyfikatorem zdarzenia w celu wzbogacania rejestrowania. Na przykład serilog używa nazwy zdarzenia.

Element Action jest wywoływany za pomocą silnie typizowanej metody rozszerzenia. Metoda PriorityItemProcessed rejestruje komunikat za każdym razem, gdy element roboczy jest przetwarzany. FailedToProcessWorkItem jest wywoływana, jeśli wystąpi wyjątek i gdy wystąpi wyjątek:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

Sprawdź dane wyjściowe konsoli aplikacji:

crit: WorkerServiceOptions.Example.Worker[13]
      Epic failure processing item!
      System.Exception: Failed to verify communications.
         at WorkerServiceOptions.Example.Worker.ExecuteAsync(CancellationToken stoppingToken) in
         ..\Worker.cs:line 27

Aby przekazać parametry do komunikatu dziennika, zdefiniuj maksymalnie sześć typów podczas tworzenia pola statycznego. Przykładowa aplikacja rejestruje szczegóły elementu roboczego podczas przetwarzania elementów przez zdefiniowanie WorkItem typu pola Action :

private static readonly Action<ILogger, WorkItem, Exception> s_processingPriorityItem;

Szablon komunikatu dziennika delegata odbiera wartości symboli zastępczych z podanych typów. Przykładowa aplikacja definiuje delegata do dodawania elementu roboczego, w którym parametr elementu to WorkItem:

s_processingPriorityItem = LoggerMessage.Define<WorkItem>(
    LogLevel.Information,
    new EventId(1, nameof(PriorityItemProcessed)),
    "Processing priority item: {Item}");

Statyczna metoda rozszerzenia rejestrowania, że element roboczy jest przetwarzany, PriorityItemProcessed, odbiera wartość argumentu elementu roboczego i przekazuje go do delegata Action :

public static void PriorityItemProcessed(
    this ILogger logger, WorkItem workItem) =>
    s_processingPriorityItem(logger, workItem, default!);

W metodzie usługi ExecuteAsync procesu roboczego jest wywoływana w PriorityItemProcessed celu zarejestrowania komunikatu:

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

Sprawdź dane wyjściowe konsoli aplikacji:

info: WorkerServiceOptions.Example.Worker[1]
      Processing priority item: Priority-Extreme (50db062a-9732-4418-936d-110549ad79e4): 'Verify communications'

Definiowanie zakresu komunikatów rejestratora

Metoda DefineScope(string) tworzy delegata Func<TResult> do definiowania zakresu dziennika. DefineScope przeciążenia umożliwiają przekazywanie maksymalnie sześciu parametrów typu do nazwanego ciągu formatu (szablonu).

Podobnie jak w Define przypadku metody, ciąg dostarczony do DefineScope metody jest szablonem, a nie ciągiem interpolowanym. Symbole zastępcze są wypełniane w kolejności określonej przez typy. Nazwy symboli zastępczych w szablonie powinny być opisowe i spójne w szablonach. Służą one jako nazwy właściwości w danych dziennika ustrukturyzowanego. Zalecamy stosowanie wielkości liter w języku Pascal dla nazw symboli zastępczych. Na przykład , {Item}. {DateTime}

Zdefiniuj zakres dziennika, który ma być stosowany do serii komunikatów dziennika przy użyciu DefineScope metody . Włącz IncludeScopes w sekcji rejestratora konsoli appsettings.json:

{
    "Logging": {
        "Console": {
            "IncludeScopes": true
        },
        "LogLevel": {
            "Default": "Information",
            "Microsoft": "Warning",
            "Microsoft.Hosting.Lifetime": "Information"
        }
    }
}

Aby utworzyć zakres dziennika, dodaj pole do przechowywania delegata Func<TResult> dla zakresu. Przykładowa aplikacja tworzy pole o nazwie s_processingWorkScope (Wewnętrzne/LoggerExtensions.cs):

private static readonly Func<ILogger, DateTime, IDisposable?> s_processingWorkScope;

Użyj DefineScope polecenia , aby utworzyć delegata. W przypadku wywołania delegata można określić do użycia maksymalnie sześć typów jako argumentów szablonu. Przykładowa aplikacja używa szablonu komunikatu zawierającego godzinę rozpoczęcia przetwarzania:

s_processingWorkScope =
    LoggerMessage.DefineScope<DateTime>(
        "Processing scope, started at: {DateTime}");

Podaj statyczną metodę rozszerzenia dla komunikatu dziennika. Dołącz dowolne parametry typu dla nazwanych właściwości wyświetlanych w szablonie komunikatu. Przykładowa aplikacja pobiera DateTime znacznik czasu niestandardowego do rejestrowania i zwraca polecenie _processingWorkScope:

public static IDisposable? ProcessingWorkScope(
    this ILogger logger, DateTime time) =>
    s_processingWorkScope(logger, time);

Zakres opakowuje wywołania rozszerzenia rejestrowania w bloku using :

protected override async Task ExecuteAsync(
    CancellationToken stoppingToken)
{
    using (IDisposable? scope = logger.ProcessingWorkScope(DateTime.Now))
    {
        while (!stoppingToken.IsCancellationRequested)
        {
            try
            {
                WorkItem? nextItem = priorityQueue.ProcessNextHighestPriority();

                if (nextItem is not null)
                {
                    logger.PriorityItemProcessed(nextItem);
                }
            }
            catch (Exception ex)
            {
                logger.FailedToProcessWorkItem(ex);
            }

            await Task.Delay(1_000, stoppingToken);
        }
    }
}

Sprawdź komunikaty dziennika w danych wyjściowych konsoli aplikacji. Poniższy wynik pokazuje kolejność priorytetu komunikatów dziennika z dołączonym komunikatem zakresu dziennika:

info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Extreme (7d153ef9-8894-4282-836a-8e5e38319fb3): 'Verify communications'
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\source\repos\dotnet-docs\docs\core\extensions\snippets\logging\worker-service-options
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-High (dbad6558-60cd-4eb1-8531-231e90081f62): 'Validate collection'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1eabe213-dc64-4e3a-9920-f67fe1dfb0f6): 'Propagate selections'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Medium (1142688d-d4dc-4f78-95c5-04ec01cbfac7): 'Enter pooling [contention]'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Low (e85e0c4d-0840-476e-b8b0-22505c08e913): 'Health check network'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (07571363-d559-4e72-bc33-cd8398348786): 'Ping weather service'
info: WorkerServiceOptions.Example.Worker[1]
      => Processing scope, started at: 04/11/2024 11:27:52
      Processing priority item: Priority-Deferred (2bf74f2f-0198-4831-8138-03368e60bd6b): 'Set process state'
info: Microsoft.Hosting.Lifetime[0]
      Application is shutting down...

Optymalizacje na poziomie dziennika

Inną optymalizację wydajności można wykonać, sprawdzając metodę LogLevel, ILogger.IsEnabled(LogLevel) za pomocą polecenia przed wywołaniem odpowiedniej Log* metody. Jeśli rejestrowanie nie jest skonfigurowane dla danego LogLevelelementu , następujące instrukcje są prawdziwe:

  • ILogger.Log nie jest wywoływana.
  • Unika się alokacji reprezentującej object[] parametry.
  • Unika się tworzenia pól typu wartości.

Więcej informacji można znaleźć na stronie

Zobacz też