Journalisation hautes performances dans .NET

Article
04/11/2024

La classe LoggerMessage expose la fonctionnalité permettant de créer des délégués pouvant être mis en cache qui nécessitent moins d’allocations d’objet et de charge de calcul par rapport aux méthodes d’extension d’enregistreur d’événements, telles que LogInformation et LogDebug. Pour les scénarios de journalisation hautes performances, utilisez le modèle LoggerMessage.

LoggerMessage procure les avantages suivants en termes de performances par rapport aux méthodes d’extension d’enregistreur d’événements :

Les méthodes d’extension de journaliseur nécessitent la conversion (« boxing ») de types de valeur, tels que int, en object. En utilisant des champs Action statiques et des méthodes d’extension avec des paramètres fortement typés, le modèle LoggerMessage évite le boxing.
Les méthodes d’extension de journaliseur doivent analyser le modèle de message (chaîne de format nommé) chaque fois qu’un message de journal est écrit. LoggerMessage requiert l’analyse d’un modèle une seule fois quand le message est défini.

Important

Au lieu d’utiliser la classe LoggerMessage pour créer des journaux hautes performances, vous pouvez utiliser l’attribut LoggerMessage dans .NET 6 et versions ultérieures. Le LoggerMessageAttribute fournit une prise en charge de la journalisation de génération de la source conçue pour fournir une solution de journalisation hautement utilisable et hautement performante pour les applications .NET modernes. Pour plus d’informations, consultez Génération de source de journalisation au moment de la compilation (principes fondamentaux de .NET).

L’exemple d’application illustre les fonctionnalités LoggerMessage avec un service Worker de traitement de file d’attente prioritaire. L’application traite les éléments de travail dans l’ordre de priorité. À mesure que ces opérations se produisent, des messages de journal sont générés à l’aide du modèle LoggerMessage.

Conseil

Tous les exemples de code source de journalisation sont disponibles dans l’Explorateur d’exemples pour téléchargement. Pour plus d’informations, consultez Parcourir les exemples de code : journalisation dans .NET.

Définir un message d’enregistreur d’événements

Utilisez Define(LogLevel, EventId, String) pour créer un délégué Action pour la journalisation d’un message. Les surcharges Define permettent de passer jusqu’à six paramètres de type à une chaîne de format nommée (modèle).

La chaîne fournie à la méthode Define est un modèle et non pas une chaîne interpolée. Les espaces réservés sont remplis dans l’ordre dans lequel les types sont spécifiés. Les noms d’espace réservé dans le modèle doivent être descriptifs et cohérents d’un modèle à l’autre. Ils servent de noms de propriété dans les données de journal structurées. Nous vous recommandons d’utiliser la casse Pascal pour les noms d’espace réservé. Par exemple, {Item}, {DateTime}.

Chaque message de journal est une Action contenue dans un champ statique créé par LoggerMessage.Define. Par exemple, l’exemple d’application crée un champ pour décrire un message de journal pour le traitement des éléments de travail :

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Pour l’Action, spécifiez :

Le niveau du journal
Un identificateur d’événement unique (EventId) avec le nom de la méthode d’extension statique
Le modèle de message (chaîne de format nommée)

À mesure que les éléments de travail sont supprimés de la file d’attente pour le traitement, l’application de service Worker définit les éléments suivants :

Le niveau de journal sur LogLevel.Critical
L’ID d’événement sur 13 avec le nom de la méthode FailedToProcessWorkItem.
Le modèle de message (chaîne de format nommée) sur une chaîne

s_failedToProcessWorkItem = LoggerMessage.Define(
    LogLevel.Critical,
    new EventId(13, nameof(FailedToProcessWorkItem)),
    "Epic failure processing item!");

La méthode LoggerMessage.Define est utilisée pour configurer et définir un délégué Action, qui représente un message de journal.

Des magasins de journalisation structurée peuvent utiliser le nom d’événement quand il est fourni avec l’ID d’événement pour enrichir la journalisation. Par exemple, Serilog utilise le nom d’événement.

L’Action est appelée par le biais d’une méthode d’extension fortement typée. La méthode PriorityItemProcessed journalise un message chaque fois qu’un élément de travail est traité. FailedToProcessWorkItem est appelé si et quand une exception se produit :

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

Examinez la sortie de la console de l’application :

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

Pour passer des paramètres à un message de journal, définissez jusqu’à six types au moment de la création du champ statique. L’exemple d’application journalise les détails de l’élément de travail lors du traitement des éléments en définissant un type WorkItem pour le champ Action :

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

Le modèle de message de journal du délégué reçoit ses valeurs d’espace réservé des types fournis. L’exemple d’application définit un délégué pour l’ajout d’un élément de travail, où le paramètre d’élément est un WorkItem :

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

La méthode d’extension statique pour la journalisation d’un élément de travail en cours de traitement, PriorityItemProcessed, reçoit la valeur de l’argument de l’élément de travail et la transmet au délégué Action :

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

Dans la méthode ExecuteAsync du service Worker, PriorityItemProcessed est appelé pour journaliser le message :

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

Examinez la sortie de la console de l’application :

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

Définir l’étendue du message de l’enregistreur d’événements

La méthode DefineScope(string) crée un délégué Func<TResult> pour la définition d’une étendue de journal. Les surcharges DefineScope permettent de passer jusqu’à six paramètres de type à une chaîne de format nommée (modèle).

Comme c’est le cas avec la méthode Define, la chaîne fournie à la méthode DefineScope est un modèle et non pas une chaîne interpolée. Les espaces réservés sont remplis dans l’ordre dans lequel les types sont spécifiés. Les noms d’espace réservé dans le modèle doivent être descriptifs et cohérents d’un modèle à l’autre. Ils servent de noms de propriété dans les données de journal structurées. Nous vous recommandons d’utiliser la casse Pascal pour les noms d’espace réservé. Par exemple, {Item}, {DateTime}.

Définissez une étendue de journal à appliquer à une série de messages de journal à l’aide de la méthode DefineScope. Activez IncludeScopes dans la section du journaliseur de console d’appsettings.json :

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

Pour créer une étendue de journal, ajoutez un champ destiné à contenir un délégué Func<TResult> pour l’étendue. L’exemple d’application crée un champ nommé s_processingWorkScope (Internal/LoggerExtensions.cs) :

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

Utilisez DefineScope pour créer le délégué. Vous pouvez spécifier jusqu’à six types à utiliser comme arguments de modèle quand le délégué est appelé. L’exemple d’application utilise un modèle de message qui inclut la date de début du traitement :

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

Fournissez une méthode d’extension statique pour le message de journal. Incluez tous les paramètres de type pour les propriétés nommées qui s’affichent dans le modèle de message. L’exemple d’application prend un DateTime pour un horodatage personnalisé pour journaliser et retourner _processingWorkScope :

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

L’étendue inclut les appels d’extension de journalisation dans un bloc 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);
        }
    }
}

Examinez les messages de journal dans la sortie de la console de l’application. Le résultat suivant montre l’ordre de priorité des messages de journal avec le message d’étendue du journal inclus :

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...

Optimisations surveillées au niveau du journal

Une autre optimisation des performances peut être effectuée en vérifiant le LogLevel, avec ILogger.IsEnabled(LogLevel) avant un appel à la méthode Log* correspondante. Lorsque la journalisation n’est pas configurée pour le LogLevel donné, les instructions suivantes sont vraies :

ILogger.Log n’est pas appelé.
Une allocation de object[] représentant les paramètres est évitée.
Le boxing de type valeur est évité.

Pour plus d'informations :

Voir aussi

Journalisation dans .NET

Partager via

Journalisation hautes performances dans .NET

Définir un message d’enregistreur d’événements

Définir l’étendue du message de l’enregistreur d’événements

Optimisations surveillées au niveau du journal

Voir aussi

Ressources supplémentaires