.NET의 고성능 로깅

클래스는 LoggerMessage이 객체 할당이 적고 계산 오버헤드를 줄이는 캐시 가능한 대리자를 만드는 기능을 제공합니다. 이러한 기능은 , LogInformation와 같은 LogDebug에 비해 더 효율적입니다. 고성능 로깅 시나리오의 경우 LoggerMessage 패턴을 사용합니다.

LoggerMessage 로거 확장 메서드에 비해 다음과 같은 성능 이점을 제공합니다.

• 로거 확장 메서드는 int에 대한 object와 같은 "boxing"(변환) 값 형식이 필요합니다. LoggerMessage 패턴은 강력한 형식의 매개 변수가 있는 정적 Action 필드 및 확장 메서드를 사용하여 boxing을 방지합니다.
• 로거 확장 메서드는 로그 메시지가 기록될 때마다 메시지 템플릿(명명된 형식 문자열)을 구문 분석해야 합니다. LoggerMessage는 메시지가 정의될 때 템플릿 구문 분석이 한번만 필요합니다.

샘플 앱은 우선순위 큐를 처리하는 작업자 서비스를 사용하여 LoggerMessage 기능을 보여줍니다. 앱은 작업 항목을 우선 순위에 따라 처리합니다. 이러한 작업이 수행되면 패턴을 사용하여 LoggerMessage 로그 메시지가 생성됩니다.

로거 메시지 정의

Define(LogLevel, EventId, String)를 사용하여 메시지 로깅을 위한 대리자를 Action 만듭니다. Define 오버로드는 명명된 형식 문자열(템플릿)에 최대 6개의 형식 매개 변수를 전달할 수 있습니다.

메서드에 Define 제공된 문자열은 보간된 문자열이 아니라 템플릿입니다. 자리 표시자는 형식이 지정된 순서대로 채워집니다. 템플릿의 자리 표시자 이름은 템플릿 전체에서 설명적이고 일관적이어야 합니다. 구조적 로그 데이터 내에서 속성 이름 역할을 합니다. 자리 표시자 이름에는 Pascal casing을 사용하는 것이 좋습니다. 예: {Item}, {DateTime}

각 로그 메시지는 ActionLoggerMessage.Define에서 만든 정적 필드에 저장됩니다. 예를 들어 샘플 앱은 작업 항목 처리에 대한 로그 메시지를 설명하는 필드를 만듭니다.

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

Action의 경우 다음을 지정합니다.

• 로그 수준입니다.
• 정적 확장 메서드의 이름을 가진 고유 이벤트 식별자(EventId)입니다.
• 메시지 템플릿(명명된 형식 문자열)입니다.

작업 항목이 처리를 위해 큐에서 해제되면 작업자 서비스 앱은 다음을 설정합니다.

• 로그 수준을 LogLevel.Critical로 설정합니다.
• 13의 이벤트 ID가 FailedToProcessWorkItem 메서드 이름에 해당합니다.
• 문자열에 대한 메시지 템플릿(명명된 형식 문자열)입니다.

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

이 LoggerMessage.Define 메서드는 로그 메시지를 나타내는 대리자를 Action 구성하고 정의하는 데 사용됩니다.

구조적 로깅 저장소는 이벤트 ID와 함께 제공될 때 이벤트 이름을 사용하여 로깅을 보강할 수 있습니다. 예를 들어 Serilog 는 이벤트 이름을 사용합니다.

강력한 형식의 확장 메서드를 통해 Action가 호출됩니다. 이 메서드는 PriorityItemProcessed 작업 항목이 처리될 때마다 메시지를 기록합니다. FailedToProcessWorkItem 은 예외가 발생할 경우 호출됩니다.

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

앱의 콘솔 출력을 검사합니다.

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

로그 메시지에 매개 변수를 전달하려면 정적 필드를 만들 때 최대 6개의 형식을 정의합니다. 샘플 앱은 WorkItem 필드에 대한 Action 형식을 정의하여 항목을 처리할 때 작업 항목 세부 정보를 기록합니다.

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

대리자의 로그 메시지 템플릿은 제공된 형식에서 자리 표시자 값을 받습니다. 샘플 앱은 항목 매개 변수가 다음과 같은 작업 항목을 추가하기 위한 대리자를 WorkItem정의합니다.

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

작업 항목이 처리 PriorityItemProcessed되고 있는 로깅에 대한 정적 확장 메서드는 작업 항목 인수 값을 수신하고 대리자에게 Action 전달합니다.

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

작업자 서비스의 ExecuteAsync 메서드 PriorityItemProcessed 에서 메시지를 기록하기 위해 호출됩니다.

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

앱의 콘솔 출력을 검사합니다.

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

로거 메시지 범위 정의

DefineScope(string) 메서드는 Func<TResult> 정의하기 위한 대리자를 만듭니다. DefineScope 오버로드는 명명된 형식 문자열(템플릿)에 최대 6개의 형식 매개 변수를 전달할 수 있습니다.

메서드의 Define 경우와 마찬가지로 메서드에 DefineScope 제공된 문자열은 보간된 문자열이 아닌 템플릿입니다. 자리 표시자는 형식이 지정된 순서대로 채워집니다. 템플릿의 자리 표시자 이름은 템플릿 전체에서 설명적이고 일관적이어야 합니다. 구조적 로그 데이터 내에서 속성 이름 역할을 합니다. 자리 표시자 이름에는 Pascal casing을 사용하는 것이 좋습니다. 예: {Item}, {DateTime}

메서드를 사용하여 일련의 로그 메시지에 적용할 로그 범위를 정의합니다 DefineScope . appsettings.json콘솔 로거 섹션에서 IncludeScopes.

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

로그 범위를 만들려면 범위에 대한 대리자를 보유할 Func<TResult> 필드를 추가합니다. 샘플 앱은 다음과 같은 필드 s_processingWorkScope (내부/LoggerExtensions.cs)를 만듭니다.

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

대리자를 생성하는 데 DefineScope를 사용하십시오. 대리자를 호출할 때 템플릿 인수로 사용할 수 있도록 최대 6개의 형식을 지정할 수 있습니다. 샘플 앱은 처리가 시작된 날짜 시간을 포함하는 메시지 템플릿을 사용합니다.

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

로그 메시지에 대한 정적 확장 메서드를 제공합니다. 메시지 템플릿에 표시되는 명명된 속성에 대한 형식 매개 변수를 포함합니다. 샘플 앱은 사용자 지정 타임스탬프를 DateTime 사용하여 로깅하고 다음을 반환합니다 _processingWorkScope.

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

"범위는 로깅 확장 호출을 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);
        }
    }
}

앱의 콘솔 출력에서 로그 메시지를 검사합니다. 다음 결과는 로그 범위 메시지가 포함된 로그 메시지의 우선 순위 순서를 보여줍니다.

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

로그 수준 보호 최적화

성능 최적화를 위해 LogLevel와 함께 ILogger.IsEnabled(LogLevel)을(를) 확인한 후 해당 Log* 메서드를 호출할 수 있습니다. 지정된 LogLevel에 대한 로깅이 구성되지 않은 경우 다음 진술이 사실입니다.

• ILogger.Log 가 호출되지 않습니다.
• 매개 변수를 나타내는 할당 object[] 은 방지됩니다.
• 값 형식 boxing은 방지됩니다.

자세한 내용을 원하시면:

• .NET 런타임의 마이크로 벤치마크
• 로그 수준 검사에 대한 배경 및 동기 부여

참고하십시오

• .NET의 로깅