.NET의 네트워킹 이벤트

이벤트는 다음 항목에 대한 액세스 권한을 제공합니다.

• 작업의 수명 동안 정확한 타임스탬프. 예를 들어 서버에 연결하는 데 걸린 시간과 HTTP 요청이 응답 헤더를 받는 데 걸린 시간 등이 있습니다.
• 다른 방법으로 얻을 수 없는 디버그/추적 정보. 예를 들어 연결 풀에서 어떤 종류의 결정을 내렸는지와 그 이유가 있습니다.

계측은 EventSource를 기준으로 하므로 프로세스 내부 및 외부에서 이 정보를 수집할 수 있습니다.

이벤트 공급자

네트워킹 정보는 다음 이벤트 공급자 간에 분할됩니다.

• System.Net.Http(HttpClient 및 SocketsHttpHandler)
• System.Net.NameResolution, ,
• System.Net.Security, ,
• System.Net.Sockets
• Microsoft.AspNetCore.Hosting
• Microsoft-AspNetCore-Server-Kestrel

원격 분석에 사용하도록 설정할 때는 일부 성능 오버헤드가 있으므로 실제로 관심이 있는 이벤트 공급자만 구독해야 합니다.

in-process 이벤트 사용

보다 쉬운 이벤트 상관 관계 파악 및 분석을 위해 가능한 경우 In-Process 수집을 선호합니다.

EventListener

EventListener는 EventSource 이벤트를 생성한 동일한 프로세스 내에서 이 이벤트를 수신 대기할 수 있는 API입니다.

using System.Diagnostics.Tracing;

using var listener = new MyListener();

using var client = new HttpClient();
await client.GetStringAsync("https://httpbin.org/get");

public sealed class MyListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name == "System.Net.Http")
        {
            EnableEvents(eventSource, EventLevel.Informational);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        Console.WriteLine($"{DateTime.UtcNow:ss:fff} {eventData.EventName}: " +
            string.Join(' ', eventData.PayloadNames!.Zip(eventData.Payload!).Select(pair => $"{pair.First}={pair.Second}")));
    }
}

앞의 코드는 다음과 유사한 출력을 표시합니다.

00:598 RequestStart: scheme=https host=httpbin.org port=443 pathAndQuery=/get versionMajor=1 versionMinor=1 versionPolicy=0
01:470 ConnectionEstablished: versionMajor=1 versionMinor=1
01:474 RequestLeftQueue: timeOnQueueMilliseconds=470,6214 versionMajor=1 versionMinor=1
01:476 RequestHeadersStart:
01:477 RequestHeadersStop:
01:592 ResponseHeadersStart:
01:593 ResponseHeadersStop:
01:633 ResponseContentStart:
01:635 ResponseContentStop:
01:635 RequestStop:
01:637 ConnectionClosed: versionMajor=1 versionMinor=1

Yarp.Telemetry.Consumption

위에서 설명한 EventListener 접근 방식은 빠른 실험 및 디버깅에 유용하지만 API는 강력한 형식이 지정되지 않았으며 계측된 라이브러리의 구현 세부 정보를 강제로 사용하도록 합니다.

이 문제를 해결하기 위해 .NET은 In Process에서 네트워킹 이벤트를 쉽게 사용할 수 있는 라이브러리 Yarp.Telemetry.Consumption을 만들었습니다. 패키지는 현재 YARP 프로젝트의 일부로 유지 관리되지만 모든 .NET 애플리케이션에서 사용할 수 있습니다.

이를 사용하려면 관심 있는 인터페이스 및 메서드(이벤트)를 구현합니다.

public sealed class MyTelemetryConsumer : IHttpTelemetryConsumer, INetSecurityTelemetryConsumer
{
    public void OnRequestStart(DateTime timestamp, string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor, HttpVersionPolicy versionPolicy)
    {
        Console.WriteLine($"Request to {host} started at {timestamp}");
    }

    public void OnHandshakeStart(DateTime timestamp, bool isServer, string targetHost)
    {
        Console.WriteLine($"Starting TLS handshake with {targetHost}");
    }
}

그런 후 DI 컨테이너에 구현을 등록합니다.

services.AddTelemetryConsumer<MyTelemetryConsumer>();

라이브러리는 다음과 같은 강력한 형식의 인터페이스를 제공합니다.

• IHttpTelemetryConsumer
• INameResolutionTelemetryConsumer
• INetSecurityTelemetryConsumer
• ISocketsTelemetryConsumer
• IKestrelTelemetryConsumer

이러한 콜백은 계측된 작업의 일부로 호출되므로 일반 로깅 지침이 적용됩니다. 비용이 많이 드는 계산을 콜백의 일부로 차단하거나 수행하지 않아야 합니다. 기본 작업에 대기 시간을 추가하지 않도록 사후 처리 작업을 다른 스레드로 오프로드합니다.

프로세스 외부에서 이벤트 사용

dotnet-trace

dotnet-trace는 네이티브 프로파일러 없이 실행 중인 프로세스의 .NET Core 추적을 수집할 수 있도록 하는 플랫폼 간 도구입니다.

dotnet tool install --global dotnet-trace

dotnet-trace collect --providers System.Net.Http,System.Net.Security,System.Threading.Tasks.TplEventSource:0x80:4 --process-id 1234

사용 가능한 모든 명령 및 매개 변수는 dotnet-trace 문서를 참조하세요.

Visual Studio 또는 PerfView에서 캡처된 .nettrace 파일을 분석할 수 있습니다. 자세한 내용은 dotnet-trace 분석 문서를 참조하세요.

PerfView

PerfView는 무료 고급 성능 분석 도구입니다. Windows에서 실행되지만 Linux에서 캡처된 추적도 분석할 수 있습니다.

캡처할 이벤트 목록을 구성하려면 Advanced Options / Additional Providers 아래에 지정합니다.

*System.Net.Sockets,*System.Net.NameResolution,*System.Net.Http,*System.Net.Security

TraceEvent

TraceEvent는 다양한 프로세스의 이벤트를 실시간으로 사용할 수 있는 라이브러리입니다. dotnet-trace 및 PerfView 둘 다 이 라이브러리를 사용합니다.

이벤트를 프로그래밍 방식으로 실시간으로 처리하려면 TraceEvent 문서를 참조하세요.

이벤트 시작 및 중지

더 큰 작업은 종종 Start 이벤트로 시작하고 Stop 이벤트로 끝납니다. 예를 들어 System.Net.Http의 RequestStart/RequestStop 이벤트 또는 System.Net.Sockets의 ConnectStart/ConnectStop 이벤트를 볼 수 있습니다.

이와 같은 대규모 작업은 종종 Stop 이벤트가 항상 존재한다고 보장하지만 항상 존재하는 것은 아닙니다. 예를 들어 System.Net.Http의 RequestHeadersStart 이벤트는 RequestHeadersStop도 기록될 것으로 보장하지 않습니다.

이벤트 상관 관계

이제 이러한 이벤트를 관찰하는 방법을 알게 되었으므로 이벤트를 함께, 일반적으로는 원래 HTTP 요청과 상호 연결해야 하는 경우가 많습니다.

보다 쉬운 이벤트 상관 관계 파악 및 분석을 위해 가능한 경우 In-Process 수집을 선호합니다.

In-Process 상관 관계

네트워킹에서 비동기 I/O를 사용하므로 지정된 요청을 완료한 스레드가 해당 요청을 시작한 스레드이기도 하다고 가정할 수 없습니다. 즉, [ThreadLocal] 정적 변수를 사용하여 이벤트를 상호 연결할 수는 없지만 AsyncLocal을 사용할 수 있습니다. AsyncLocal 형식은 여러 스레드에서 작업을 상호 연결하는 데 핵심적이므로 숙지하도록 합니다.

AsyncLocal을 사용하면 작업의 비동기 흐름에 따라 동일한 상태에 더 깊이 액세스할 수 있습니다. AsyncLocal 값은 아래로만 흐르고(비동기 호출 스택까지 깊게) 변경 내용을 호출자에게 전파하지 않습니다.

다음과 같은 예제를 참조하세요.

AsyncLocal<int> asyncLocal = new();
asyncLocal.Value = 1;

await WorkAsync();
Console.WriteLine($"Value after WorkAsync: {asyncLocal.Value}");

async Task WorkAsync()
{
    Console.WriteLine($"Value in WorkAsync: {asyncLocal.Value}");
    asyncLocal.Value = 2;
    Console.WriteLine($"Value in WorkAsync: {asyncLocal.Value}");
}

이 코드는 다음 출력을 생성합니다.

Value in WorkAsync: 1
Value in WorkAsync: 2
Value after WorkAsync: 1

1 값은 호출자에서 WorkAsync로 전달되었지만 WorkAsync(2)의 수정 내용은 호출자에게 다시 전달되지 않았습니다.

원격 분석 이벤트(및 해당 콜백)는 기본 작업의 일부로 발생하므로 요청을 시작한 호출자와 동일한 비동기 범위 내에서 발생합니다. 즉, 콜백 내에서 asyncLocal.Value를 관찰할 수 있지만 콜백에서 값을 설정하면 스택까지 더 자세히 관찰할 수 없습니다.

다음 단계에서는 일반적인 패턴을 보여 줍니다.

1. 이벤트 콜백 내부에서 업데이트할 수 있는 변경 가능한 클래스를 만듭니다.

   public sealed class RequestInfo
   {
       public DateTime StartTime, HeadersSent;
   }
   

2. 상태가 작업으로 이동되도록 주 작업 이전에 AsyncLocal.Value를 설정합니다.

   private static readonly AsyncLocal<RequestInfo> _requestInfo = new();
   
   public async Task SendRequestAsync(string url)
   {
       var info = new RequestInfo();
       _requestInfo.Value = info;
   
       info.StartTime = DateTime.UtcNow;
       await _client.GetStringAsync(url);
   

3. 이벤트 콜백 내에서 공유 상태를 사용할 수 있는지 확인하고 업데이트합니다. AsyncLocal.Value는 첫 번째 위치에서 AsyncLocal.Value를 설정하지 않은 구성 요소에서 요청을 보낸 경우 null입니다.

   public void OnRequestHeadersStop(DateTime timestamp)
   {
       if (_requestInfo.Value is { } info) info.HeadersSent = timestamp;
   }
   

4. 작업을 완료한 후 수집된 정보를 처리합니다.

   await _client.GetStringAsync(url);
   
   Log($"Time until headers were sent {url} was {info.HeadersSent - info.StartTime}");
   

이 작업을 수행하는 방법에 대한 자세한 내용은 샘플 섹션을 참조하세요.

프로세스 외부의 상관 관계

모든 이벤트에는 ActivityID라는 데이터가 연결되어 있습니다. 이 ID는 이벤트가 생성될 때 비동기 계층 구조를 인코딩합니다.

PerfView에서 추적 파일을 보면 다음과 같은 이벤트가 표시됩니다.

System.Net.Http/Request/Start           ActivityID="/#14396/1/1/"
System.Net.Http/RequestHeaders/Start    ActivityID="/#14396/1/1/2/"
System.Net.Http/RequestHeaders/Stop     ActivityID="/#14396/1/1/2/"
System.Net.Http/ResponseHeaders/Start   ActivityID="/#14396/1/1/3/"
System.Net.Http/ResponseHeaders/Stop    ActivityID="/#14396/1/1/3/"
System.Net.Http/Request/Stop            ActivityID="/#14396/1/1/"

이러한 이벤트는 /#14396/1/1/ 접두사를 공유하기 때문에 동일한 요청에 속한다는 것을 알 수 있습니다.

수동 조사를 수행할 때 유용한 방법은 관심 있는 요청의 System.Net.Http/Request/Start 이벤트를 찾은 다음, ActivityID를 Text Filter 텍스트 상자에 붙여넣는 것입니다. 이제 사용 가능한 모든 공급자를 선택하면 해당 요청의 일부로 생성된 모든 이벤트 목록이 표시됩니다.

PerfView는 자동으로 ActivityID를 수집하지만 dotnet-trace와 같은 도구를 사용하는 경우 System.Threading.Tasks.TplEventSource:0x80:4 공급자를 명시적으로 사용하도록 설정해야 합니다(위의 dotnet-trace 예제 참조).

HttpClient 요청 및 연결 수명

.NET 6 이후부터 HTTP 요청은 더 이상 특정 연결에 연결되지 않습니다. 대신, 모든 연결을 사용할 수 있게 되는 즉시, 요청이 처리됩니다.

즉, 다음과 같은 이벤트 순서가 표시될 수 있습니다.

1. 요청 시작
2. Dns 시작
3. 요청 중지
4. Dns 중지

이것은 요청이 DNS 확인을 트리거했지만 DNS 호출이 완료되기 전에 다른 연결에 의해 처리되었음을 나타냅니다. 소켓 연결 또는 TLS 핸드셰이크도 마찬가지입니다. 이러한 작업을 수행하기 전에 원래 요청이 완료될 수 있습니다.

이러한 이벤트는 별도로 고려해야 합니다. 특정 요청의 타임라인에 연결하지 않고 DNS 확인 또는 TLS 핸드셰이크를 자체적으로 모니터링합니다.

내부 진단

.NET의 일부 구성 요소는 내부적으로 발생하는 상황에 대한 자세한 인사이트를 제공하는 추가 디버그 수준 이벤트로 계측됩니다. 이러한 이벤트는 고성능 오버헤드를 유발하며 해당 상황은 지속적으로 변경됩니다. 이름에서 알 수 있듯이 퍼블릭 API의 일부가 아니므로 해당 동작이나 존재에 의존하지 않아야 합니다.

그럼에도 불구하고 이러한 이벤트는 다른 모든 것이 실패할 때 많은 인사이트를 제공할 수 있습니다. System.Net 스택은 Private.InternalDiagnostics.System.Net.* 네임스페이스에서 이러한 이벤트를 내보냅니다.

위 EventListener 예제의 조건을 eventSource.Name.Contains("System.Net")으로 변경하면 스택의 여러 계층에서 100개 이상의 이벤트가 표시됩니다. 자세한 내용은 전체 예제를 참조하세요.

샘플

• 지정된 엔드포인트에 대한 DNS 확인 측정
• HttpClient를 사용하는 경우 헤더까지의 시간 측정
• Kestrel을 실행하는 ASP.NET Core에서 요청을 처리하는 시간
• .NET 역방향 프록시의 대기 시간 측정

지정된 엔드포인트에 대한 DNS 확인 측정

services.AddTelemetryConsumer(new DnsMonitor("httpbin.org"));

public sealed class DnsMonitor : INameResolutionTelemetryConsumer
{
    private static readonly AsyncLocal<DateTime?> _startTimestamp = new();
    private readonly string _hostname;

    public DnsMonitor(string hostname) => _hostname = hostname;

    public void OnResolutionStart(DateTime timestamp, string hostNameOrAddress)
    {
        if (hostNameOrAddress.Equals(_hostname, StringComparison.OrdinalIgnoreCase))
        {
            _startTimestamp.Value = timestamp;
        }
    }

    public void OnResolutionStop(DateTime timestamp)
    {
        if (_startTimestamp.Value is { } start)
        {
            Console.WriteLine($"DNS resolution for {_hostname} took {(timestamp - start).TotalMilliseconds} ms");
        }
    }
}

HttpClient를 사용하는 경우 헤더까지의 시간 측정

var info = RequestState.Current; // Initialize the AsyncLocal's value ahead of time

var response = await client.GetStringAsync("http://httpbin.org/get");

var requestTime = (info.RequestStop - info.RequestStart).TotalMilliseconds;
var serverLatency = (info.HeadersReceived - info.HeadersSent).TotalMilliseconds;
Console.WriteLine($"Request took {requestTime:N2} ms, server request latency was {serverLatency:N2} ms");

public sealed class RequestState
{
    private static readonly AsyncLocal<RequestState> _asyncLocal = new();
    public static RequestState Current => _asyncLocal.Value ??= new();

    public DateTime RequestStart;
    public DateTime HeadersSent;
    public DateTime HeadersReceived;
    public DateTime RequestStop;
}

public sealed class TelemetryConsumer : IHttpTelemetryConsumer
{
    public void OnRequestStart(DateTime timestamp, string scheme, string host, int port, string pathAndQuery, int versionMajor, int versionMinor, HttpVersionPolicy versionPolicy) =>
        RequestState.Current.RequestStart = timestamp;

    public void OnRequestStop(DateTime timestamp) =>
        RequestState.Current.RequestStop = timestamp;

    public void OnRequestHeadersStop(DateTime timestamp) =>
        RequestState.Current.HeadersSent = timestamp;

    public void OnResponseHeadersStop(DateTime timestamp) =>
        RequestState.Current.HeadersReceived = timestamp;
}

Kestrel을 실행하는 ASP.NET Core에서 요청을 처리하는 시간

이것은 현재, 지정된 요청의 기간을 측정하는 가장 정확한 방법입니다.

public sealed class KestrelTelemetryConsumer : IKestrelTelemetryConsumer
{
    private static readonly AsyncLocal<DateTime?> _startTimestamp = new();
    private readonly ILogger<KestrelTelemetryConsumer> _logger;

    public KestrelTelemetryConsumer(ILogger<KestrelTelemetryConsumer> logger) => _logger = logger;

    public void OnRequestStart(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        _startTimestamp.Value = timestamp;
    }

    public void OnRequestStop(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        if (_startTimestamp.Value is { } startTime)
        {
            var elapsed = timestamp - startTime;
            _logger.LogInformation("Request {requestId} to {path} took {elapsedMs} ms", requestId, path, elapsed.TotalMilliseconds);
        }
    }
}

.NET 역방향 프록시의 대기 시간 측정

이 샘플은 Kestrel을 통해 인바운드 요청을 수신하고 HttpClient를 통해 아웃바운드 요청을 수행하는 역방향 프록시가 있는 경우에 적용됩니다(예: YARP).

이 샘플은 요청 헤더를 수신할 때부터 요청 헤더가 백 엔드 서버로 전송될 때까지의 시간을 측정합니다.

public sealed class InternalLatencyMonitor : IKestrelTelemetryConsumer, IHttpTelemetryConsumer
{
    private record RequestInfo(DateTime StartTimestamp, string RequestId, string Path);

    private static readonly AsyncLocal<RequestInfo> _requestInfo = new();
    private readonly ILogger<InternalLatencyMonitor> _logger;

    public InternalLatencyMonitor(ILogger<InternalLatencyMonitor> logger) => _logger = logger;

    public void OnRequestStart(DateTime timestamp, string connectionId, string requestId, string httpVersion, string path, string method)
    {
        _requestInfo.Value = new RequestInfo(timestamp, requestId, path);
    }

    public void OnRequestHeadersStop(DateTime timestamp)
    {
        if (_requestInfo.Value is { } requestInfo)
        {
            var elapsed = (timestamp - requestInfo.StartTimestamp).TotalMilliseconds;
            _logger.LogInformation("Internal latency for {requestId} to {path} was {duration} ms", requestInfo.RequestId, requestInfo.Path, elapsed);
        }
    }
}

더 많은 원격 분석이 필요하세요?

이벤트 또는 메트릭을 통해 노출될 수 있는 다른 유용한 정보에 대한 제안 사항이 있는 경우 dotnet/runtime 문제를 만듭니다.

Yarp.Telemetry.Consumption 라이브러리를 사용하고 있으며 제안 사항이 있는 경우 microsoft/reverse-proxy 문제를 만듭니다.