.NET의 고성능 로깅

아티클
04/21/2024

LoggerMessage 클래스는 LogInformation 및 LogDebug와 같은 로거 확장 메서드에 비해 적은 개체 할당 및 감소된 계산 오버헤드를 필요로 하는 캐시 가능한 대리자를 만드는 기능을 노출합니다. 고성능 로깅 시나리오의 경우 LoggerMessage 패턴을 사용합니다.

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

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

Important

고성능 로그를 만들기 위해 LoggerMessage 클래스를 사용하는 대신 .NET 6 이상 버전에서는 LoggerMessage 특성을 사용할 수 있습니다. 이 LoggerMessageAttribute(은)는 최신 .NET 애플리케이션에 매우 사용 가능하고 성능이 뛰어난 로깅 솔루션을 제공하도록 설계된 소스 생성 로깅 지원을 제공합니다. 자세한 내용은 컴파일 시간 로깅 원본 생성(.NET 기본 사항)을 참조하세요.

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

팁

모든 로깅 예제 소스 코드는 샘플 브라우저에서 다운로드할 수 있습니다. 자세한 내용은 코드 샘플 찾아보기: .NET의 로깅을 참조하세요.

로거 메시지 정의

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

Define 메서드에 제공된 문자열은 템플릿이며 보간된 문자열이 아닙니다. 자리 표시자는 형식이 지정된 순서로 채워집니다. 템플릿의 자리 표시자 이름은 템플릿에서 알기 쉽고 일관되어야 합니다. 구조적 로그 데이터 내에서 속성 이름으로 사용됩니다. 자리 표시자 이름으로 파스칼식 대/소문자를 권장합니다. 예: {Item}, {DateTime}

각 로그 메시지는 LoggerMessage.Define에서 만들어진 정적 필드에 보관된 Action입니다. 예를 들어 샘플 앱은 작업 항목 처리에 대한 로그 메시지를 설명하는 필드를 만듭니다.

private static readonly Action<ILogger, Exception> s_failedToProcessWorkItem;

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

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

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

로그 수준을 LogLevel.Critical으로
FailedToProcessWorkItem 메서드의 이름으로 13의 이벤트 ID입니다.
메시지 템플릿(명명된 형식 문자열)을 문자열로

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개의 형식을 정의합니다. 샘플 앱에서는 Action 필드의 WorkItem 형식을 정의하여 항목을 처리할 때 작업 항목 세부 정보를 기록합니다.

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 메서드에 제공된 문자열은 템플릿이며 보간된 문자열이 아닙니다. 자리 표시자는 형식이 지정된 순서로 채워집니다. 템플릿의 자리 표시자 이름은 템플릿에서 알기 쉽고 일관되어야 합니다. 구조적 로그 데이터 내에서 속성 이름으로 사용됩니다. 자리 표시자 이름으로 파스칼식 대/소문자를 권장합니다. 예: {Item}, {DateTime}

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

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

로그 범위를 만들려면 범위에 대한 Func<TResult> 대리자를 보유하는 필드를 추가합니다. 샘플 앱은 s_processingWorkScope(Internal/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...

로그 수준 보호 최적화

다른 성능 최적화는 해당 Log* 메서드를 호출하기 전에 ILogger.IsEnabled(LogLevel)와 LogLevel(을)를 확인하여 수행할 수 있습니다. 지정된 LogLevel에 대해 로깅이 구성되지 않은 경우에는 다음 문이 참입니다.

ILogger.Log(이)가 호출되지 않습니다.
매개 변수를 나타내는 object[]의 할당이 사용되지 않습니다.
값 형식 boxing이 사용되지 않습니다.

자세한 내용은 다음에서 확인합니다.

참고 항목

.NET의 로깅

.NET의 고성능 로깅

로거 메시지 정의

로거 메시지 범위 정의

로그 수준 보호 최적화

참고 항목

피드백

추가 리소스