Udostępnij za pośrednictwem

Wysokowydajne rejestrowanie w .NET

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. LoggerMessageAttribute obsługuje logowanie generacji źródłowej, co zostało zaprojektowane z myślą o dostarczeniu wysoce użytecznego i wydajnego rozwiązania do rejestrowania dla nowoczesnych aplikacji .NET. Aby uzyskać więcej informacji, zobacz Generowanie źródła logowania w czasie kompilacji (.NET - Podstawy).

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

Wskazówka

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 funkcji Define(LogLevel, EventId, String), aby zdefiniować delegata Action w celu rejestrowania komunikatów. 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 zgodnie z kolejnością typów. 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 notację Pascal dla nazw 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 logowania.
  • 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 rejestrowania do LogLevel.Critical.
  • Identyfikator zdarzenia 13 z nazwą metody FailedToProcessWorkItem.
  • Konwersja szablonu komunikatu (określonego ciągu formatu) na ciąg.
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.

Miejsca przechowywania z ustrukturyzowanym rejestrowaniem mogą używać nazwy zdarzenia, gdy jest ona dostarczana wraz z identyfikatorem zdarzenia, w celu wzbogacenia 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, 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 elementów roboczych podczas ich przetwarzania, definiując typ WorkItem dla pola Action.

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

Szablon komunikatu dziennika delegata otrzymuje wartości dla 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 rozszerzająca do rejestrowania informacji o przetwarzaniu elementu roboczego, PriorityItemProcessed, odbiera wartość argumentu tego elementu i przekazuje ją do delegata Action.

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

W metodzie ExecuteAsync serwisu roboczego wywołana jest PriorityItemProcessed w 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 zdefiniowania zakresu logowania. 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 zgodnie z kolejnością typów. 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 notację Pascal dla nazw 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 loggera 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, 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 przyjmuje DateTime jako niestandardowy znacznik czasu do rejestrowania i zwraca _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 logów w konsoli aplikacji. Poniższy wynik pokazuje priorytetową kolejność komunikatów logu z dołączoną wiadomością zakresu logu.

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 kontrolowane na poziomie dziennika

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

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

Więcej informacji:

Zobacz także