Add IHttpSysRequestTimingFeature to support accessing http.sys timing info (#48218)

Author: NGloreous

src/Servers/HttpSys/src/HttpSysRequestTimingType.cs

@@ -0,0 +1,168 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+namespace Microsoft.AspNetCore.Server.HttpSys;
+
+/// <summary>
+/// Defines the types of request processing timestamps exposed via the Http.Sys HTTP_REQUEST_TIMING_INFO extensibility point.
+/// </summary>
+/// <remarks>
+/// Use <see cref="IHttpSysRequestTimingFeature"/> to access these timestamps.
+/// </remarks>
+public enum HttpSysRequestTimingType
+{
+    // IMPORTANT: Order matters and should match the order defined in HTTP_REQUEST_TIMING_TYPE
+
+    /// <summary>
+    /// Time the connection started.
+    /// </summary>
+    ConnectionStart,
+
+    /// <summary>
+    /// Time the first HTTP byte is received.
+    /// </summary>
+    DataStart,
+
+    /// <summary>
+    /// Time TLS certificate loading starts.
+    /// </summary>
+    TlsCertificateLoadStart,
+
+    /// <summary>
+    /// Time TLS certificate loading ends.
+    /// </summary>
+    TlsCertificateLoadEnd,
+
+    /// <summary>
+    /// Time TLS leg one handshake starts.
+    /// </summary>
+    TlsHandshakeLeg1Start,
+
+    /// <summary>
+    /// Time TLS leg one handshake ends.
+    /// </summary>
+    TlsHandshakeLeg1End,
+
+    /// <summary>
+    /// Time TLS leg two handshake starts.
+    /// </summary>
+    TlsHandshakeLeg2Start,
+
+    /// <summary>
+    /// Time TLS leg two handshake ends.
+    /// </summary>
+    TlsHandshakeLeg2End,
+
+    /// <summary>
+    /// Time TLS attribute query starts.
+    /// </summary>
+    TlsAttributesQueryStart,
+
+    /// <summary>
+    /// Time TLS attribute query ends.
+    /// </summary>
+    TlsAttributesQueryEnd,
+
+    /// <summary>
+    /// Time TLS client cert query starts.
+    /// </summary>
+    TlsClientCertQueryStart,
+
+    /// <summary>
+    /// Time TLS client cert query ends.
+    /// </summary>
+    TlsClientCertQueryEnd,
+
+    /// <summary>
+    /// Time HTTP2 streaming starts.
+    /// </summary>
+    Http2StreamStart,
+
+    /// <summary>
+    /// Time HTTP2 header decoding starts.
+    /// </summary>
+    Http2HeaderDecodeStart,
+
+    /// <summary>
+    /// Time HTTP2 header decoding ends.
+    /// </summary>
+    Http2HeaderDecodeEnd,
+
+    /// <summary>
+    /// Time HTTP header parsing starts.
+    /// </summary>
+    /// <remarks>
+    /// For most requests, this is a good timestamp to use as a per request starting timestamp.
+    /// </remarks>
+    RequestHeaderParseStart,
+
+    /// <summary>
+    /// Time HTTP header parsing ends.
+    /// </summary>
+    RequestHeaderParseEnd,
+
+    /// <summary>
+    /// Time Http.Sys starts to determine which request queue to route the request to.
+    /// </summary>
+    RequestRoutingStart,
+
+    /// <summary>
+    /// Time Http.Sys has determined which request queue to route the request to.
+    /// </summary>
+    RequestRoutingEnd,
+
+    /// <summary>
+    /// Time the request is queued for inspection.
+    /// </summary>
+    RequestQueuedForInspection,
+
+    /// <summary>
+    /// Time the request is delivered for inspection.
+    /// </summary>
+    RequestDeliveredForInspection,
+
+    /// <summary>
+    /// Time the request has finished being inspected.
+    /// </summary>
+    RequestReturnedAfterInspection,
+
+    /// <summary>
+    /// Time the request is queued for delegation.
+    /// </summary>
+    RequestQueuedForDelegation,
+
+    /// <summary>
+    /// Time the request is delivered for delegation.
+    /// </summary>
+    RequestDeliveredForDelegation,
+
+    /// <summary>
+    /// Time the request was delegated.
+    /// </summary>
+    RequestReturnedAfterDelegation,
+
+    /// <summary>
+    /// Time the request was queued to the final request queue for processing.
+    /// </summary>
+    RequestQueuedForIO,
+
+    /// <summary>
+    /// Time the request was delivered to the final request queue for processing.
+    /// </summary>
+    RequestDeliveredForIO,
+
+    /// <summary>
+    /// Time HTTP3 streaming starts.
+    /// </summary>
+    Http3StreamStart,
+
+    /// <summary>
+    /// Time HTTP3 header decoding starts.
+    /// </summary>
+    Http3HeaderDecodeStart,
+
+    /// <summary>
+    /// Time HTTP3 header decoding ends.
+    /// </summary>
+    Http3HeaderDecodeEnd,
+}

src/Servers/HttpSys/src/IHttpSysRequestTimingFeature.cs

@@ -0,0 +1,40 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+namespace Microsoft.AspNetCore.Server.HttpSys;
+
+/// <summary>
+/// This exposes the Http.Sys HTTP_REQUEST_TIMING_INFO extensibility point which contains request processing timestamp data from Http.Sys.
+/// </summary>
+public interface IHttpSysRequestTimingFeature
+{
+    /// <summary>
+    /// Gets all Http.Sys timing timestamps
+    /// </summary>
+    /// <remarks>
+    /// These timestamps were obtained using QueryPerformanceCounter <see href="https://learn.microsoft.com/en-us/windows/win32/api/profileapi/nf-profileapi-queryperformancecounter"/> and the timestamp frequency can be obtained via QueryPerformanceFrequency <see href="https://learn.microsoft.com/en-us/windows/win32/api/profileapi/nf-profileapi-queryperformancefrequency"/>.
+    /// The index of the timing can be cast to <see cref="HttpSysRequestTimingType"/> to know what the timing represents.
+    /// The value may be 0 if the timing is not available for the current request.
+    /// </remarks>
+    ReadOnlySpan<long> Timestamps { get; }
+
+    /// <summary>
+    /// Gets the timestamp for the given timing.
+    /// </summary>
+    /// <remarks>
+    /// These timestamps were obtained using QueryPerformanceCounter <see href="https://learn.microsoft.com/windows/win32/api/profileapi/nf-profileapi-queryperformancecounter"/> and the timestamp frequency can be obtained via QueryPerformanceFrequency <see href="https://learn.microsoft.com/windows/win32/api/profileapi/nf-profileapi-queryperformancefrequency"/>.
+    /// </remarks>
+    /// <param name="timestampType">The timestamp type to get.</param>
+    /// <param name="timestamp">The value of the timestamp if set.</param>
+    /// <returns>True if the given timing was set (i.e., non-zero).</returns>
+    bool TryGetTimestamp(HttpSysRequestTimingType timestampType, out long timestamp);
+
+    /// <summary>
+    /// Gets the elapsed time between the two given timings.
+    /// </summary>
+    /// <param name="startingTimestampType">The timestamp type marking the beginning of the time period.</param>
+    /// <param name="endingTimestampType">The timestamp type marking the end of the time period.</param>
+    /// <param name="elapsed">A <see cref="TimeSpan"/> for the elapsed time between the starting and ending timestamps.</param>
+    /// <returns>True if both given timings were set (i.e., non-zero).</returns>
+    bool TryGetElapsedTime(HttpSysRequestTimingType startingTimestampType, HttpSysRequestTimingType endingTimestampType, out TimeSpan elapsed);
+}

src/Servers/HttpSys/src/PublicAPI.Unshipped.txt

@@ -1 +1,36 @@
 #nullable enable
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.ConnectionStart = 0 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.DataStart = 1 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http2HeaderDecodeEnd = 14 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http2HeaderDecodeStart = 13 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http2StreamStart = 12 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http3HeaderDecodeEnd = 29 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http3HeaderDecodeStart = 28 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.Http3StreamStart = 27 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestDeliveredForDelegation = 23 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestDeliveredForInspection = 20 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestDeliveredForIO = 26 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestHeaderParseEnd = 16 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestHeaderParseStart = 15 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestQueuedForDelegation = 22 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestQueuedForInspection = 19 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestQueuedForIO = 25 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestReturnedAfterDelegation = 24 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestReturnedAfterInspection = 21 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestRoutingEnd = 18 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.RequestRoutingStart = 17 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsAttributesQueryEnd = 9 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsAttributesQueryStart = 8 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsCertificateLoadEnd = 3 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsCertificateLoadStart = 2 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsClientCertQueryEnd = 11 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsClientCertQueryStart = 10 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsHandshakeLeg1End = 5 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsHandshakeLeg1Start = 4 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsHandshakeLeg2End = 7 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType.TlsHandshakeLeg2Start = 6 -> Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType
+Microsoft.AspNetCore.Server.HttpSys.IHttpSysRequestTimingFeature
+Microsoft.AspNetCore.Server.HttpSys.IHttpSysRequestTimingFeature.Timestamps.get -> System.ReadOnlySpan<long>
+Microsoft.AspNetCore.Server.HttpSys.IHttpSysRequestTimingFeature.TryGetElapsedTime(Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType startingTimestampType, Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType endingTimestampType, out System.TimeSpan elapsed) -> bool
+Microsoft.AspNetCore.Server.HttpSys.IHttpSysRequestTimingFeature.TryGetTimestamp(Microsoft.AspNetCore.Server.HttpSys.HttpSysRequestTimingType timestampType, out long timestamp) -> bool

src/Servers/HttpSys/src/RequestProcessing/Request.cs

@@ -3,6 +3,8 @@
 
 using System.Globalization;
 using System.Net;
+using System.Runtime.CompilerServices;
+using System.Runtime.InteropServices;
 using System.Security;
 using System.Security.Authentication;
 using System.Security.Cryptography;
@@ -351,6 +353,37 @@ public IReadOnlyDictionary<int, ReadOnlyMemory<byte>> RequestInfo
         }
     }
 
+    public ReadOnlySpan<long> RequestTimestamps
+    {
+        get
+        {
+            /*
+                Below is the definition of the timing info structure we are accessing the memory for.
+                ULONG is 32-bit and maps to int. ULONGLONG is 64-bit and maps to long.
+
+                typedef struct _HTTP_REQUEST_TIMING_INFO
+                {
+                    ULONG RequestTimingCount;
+                    ULONGLONG RequestTiming[HttpRequestTimingTypeMax];
+
+                } HTTP_REQUEST_TIMING_INFO, *PHTTP_REQUEST_TIMING_INFO;
+            */
+
+            if (!RequestInfo.TryGetValue((int)HttpApiTypes.HTTP_REQUEST_INFO_TYPE.HttpRequestInfoTypeRequestTiming, out var timingInfo))
+            {
+                return ReadOnlySpan<long>.Empty;
+            }
+
+            var timingCount = MemoryMarshal.Read<int>(timingInfo.Span);
+
+            // Note that even though RequestTimingCount is an int, the compiler enforces alignment of data in the struct which causes 4 bytes
+            // of padding to be added after RequestTimingCount, so we need to skip 64-bits before we get to the start of the RequestTiming array
+            return MemoryMarshal.CreateReadOnlySpan(
+                ref Unsafe.As<byte, long>(ref MemoryMarshal.GetReference(timingInfo.Span.Slice(sizeof(long)))),
+                timingCount);
+        }
+    }
+
     private void GetTlsHandshakeResults()
     {
         var handshake = RequestContext.GetTlsHandshake();

src/Servers/HttpSys/src/RequestProcessing/RequestContext.FeatureCollection.cs

@@ -32,6 +32,7 @@ internal partial class RequestContext :
     IHttpMaxRequestBodySizeFeature,
     IHttpBodyControlFeature,
     IHttpSysRequestInfoFeature,
+    IHttpSysRequestTimingFeature,
     IHttpResponseTrailersFeature,
     IHttpResetFeature,
     IHttpSysRequestDelegationFeature,
@@ -588,6 +589,8 @@ bool IHttpBodyControlFeature.AllowSynchronousIO
 
     IReadOnlyDictionary<int, ReadOnlyMemory<byte>> IHttpSysRequestInfoFeature.RequestInfo => Request.RequestInfo;
 
+    ReadOnlySpan<long> IHttpSysRequestTimingFeature.Timestamps => Request.RequestTimestamps;
+
     IHeaderDictionary IHttpResponseTrailersFeature.Trailers
     {
         get => _responseTrailers ??= Response.Trailers;
@@ -598,6 +601,32 @@ IHeaderDictionary IHttpResponseTrailersFeature.Trailers
 
     CancellationToken IConnectionLifetimeNotificationFeature.ConnectionClosedRequested { get; set; }
 
+    bool IHttpSysRequestTimingFeature.TryGetTimestamp(HttpSysRequestTimingType timestampType, out long timestamp)
+    {
+        int index = (int)timestampType;
+        if (index < Request.RequestTimestamps.Length && Request.RequestTimestamps[index] > 0)
+        {
+            timestamp = Request.RequestTimestamps[index];
+            return true;
+        }
+
+        timestamp = default;
+        return false;
+    }
+
+    bool IHttpSysRequestTimingFeature.TryGetElapsedTime(HttpSysRequestTimingType startingTimestampType, HttpSysRequestTimingType endingTimestampType, out TimeSpan elapsed)
+    {
+        var timingFeature = (IHttpSysRequestTimingFeature)this;
+        if (timingFeature.TryGetTimestamp(startingTimestampType, out long startTimestamp) && timingFeature.TryGetTimestamp(endingTimestampType, out long endTimestamp))
+        {
+            elapsed = Stopwatch.GetElapsedTime(startTimestamp, endTimestamp);
+            return true;
+        }
+
+        elapsed = default;
+        return false;
+    }
+
     internal async Task OnResponseStart()
     {
         if (_responseStarted)

src/Servers/HttpSys/src/StandardFeatureCollection.cs

@@ -26,6 +26,7 @@ internal sealed class StandardFeatureCollection : IFeatureCollection
         { typeof(IHttpMaxRequestBodySizeFeature), _identityFunc },
         { typeof(IHttpBodyControlFeature), _identityFunc },
         { typeof(IHttpSysRequestInfoFeature), _identityFunc },
+        { typeof(IHttpSysRequestTimingFeature), _identityFunc },
         { typeof(IHttpResponseTrailersFeature), ctx => ctx.GetResponseTrailersFeature() },
         { typeof(IHttpResetFeature), ctx => ctx.GetResetFeature() },
         { typeof(IConnectionLifetimeNotificationFeature), ctx => ctx.GetConnectionLifetimeNotificationFeature() },

src/Servers/HttpSys/test/FunctionalTests/HttpsTests.cs

@@ -2,6 +2,7 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using System;
+using System.Diagnostics;
 using System.IO;
 using System.Net.Http;
 using System.Runtime.InteropServices;
@@ -227,6 +228,36 @@ public async Task Https_ITlsHandshakeFeature_MatchesIHttpSysExtensionInfoFeature
         }
     }
 
+    [ConditionalFact]
+    [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10_20H2)]
+    public async Task Https_SetsIHttpSysRequestTimingFeature()
+    {
+        using (Utilities.CreateDynamicHttpsServer(out var address, async httpContext =>
+        {
+            try
+            {
+                var requestTimingFeature = httpContext.Features.Get<IHttpSysRequestTimingFeature>();
+                Assert.NotNull(requestTimingFeature);
+                Assert.True(requestTimingFeature.Timestamps.Length > (int)HttpSysRequestTimingType.Http3HeaderDecodeEnd);
+                Assert.True(requestTimingFeature.TryGetTimestamp(HttpSysRequestTimingType.RequestHeaderParseStart, out var headerStart));
+                Assert.True(requestTimingFeature.TryGetTimestamp(HttpSysRequestTimingType.RequestHeaderParseEnd, out var headerEnd));
+                Assert.True(requestTimingFeature.TryGetElapsedTime(HttpSysRequestTimingType.RequestHeaderParseStart, HttpSysRequestTimingType.RequestHeaderParseEnd, out var elapsed));
+                Assert.Equal(Stopwatch.GetElapsedTime(headerStart, headerEnd), elapsed);
+                Assert.False(requestTimingFeature.TryGetTimestamp(HttpSysRequestTimingType.Http3StreamStart, out var streamStart));
+                Assert.False(requestTimingFeature.TryGetTimestamp((HttpSysRequestTimingType)int.MaxValue, out var invalid));
+                Assert.False(requestTimingFeature.TryGetElapsedTime(HttpSysRequestTimingType.Http3StreamStart, HttpSysRequestTimingType.RequestHeaderParseStart, out elapsed));
+            }
+            catch (Exception ex)
+            {
+                await httpContext.Response.WriteAsync(ex.ToString());
+            }
+        }))
+        {
+            string response = await SendRequestAsync(address);
+            Assert.Equal(string.Empty, response);
+        }
+    }
+
     private async Task<string> SendRequestAsync(string uri,
         X509Certificate cert = null)
     {