From d378561e896cb2e79007f06bff43f25a0028a701 Mon Sep 17 00:00:00 2001 From: Dmytro Bohdanov Date: Fri, 21 Nov 2025 16:37:44 +0100 Subject: [PATCH] potential fix using a latency snapshot, wip --- .../Internal/HttpClientLatencyLogEnricher.cs | 182 ++++++++++-------- .../Internal/HttpLatencyTelemetryHandler.cs | 15 +- .../HttpRequestLatencySnapshotStore.cs | 37 ++++ .../Latency/Internal/LatencySnapshot.cs | 52 +++++ 4 files changed, 208 insertions(+), 78 deletions(-) create mode 100644 src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencySnapshotStore.cs create mode 100644 src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/LatencySnapshot.cs diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs index 753b5b9a9f6..d06c3af23f2 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpClientLatencyLogEnricher.cs @@ -23,140 +23,168 @@ internal sealed class HttpClientLatencyLogEnricher : IHttpClientLogEnricher { private static readonly ObjectPool _builderPool = PoolFactory.SharedStringBuilderPool; private readonly HttpClientLatencyContext _latencyContext; - private readonly HttpLatencyMediator _httpLatencyMediator; private readonly CheckpointToken _enricherInvoked; public HttpClientLatencyLogEnricher( HttpClientLatencyContext latencyContext, ILatencyContextTokenIssuer tokenIssuer, - HttpLatencyMediator httpLatencyMediator) + HttpLatencyMediator _ /* mediator no longer needed for record end here */) { _latencyContext = latencyContext; - _httpLatencyMediator = httpLatencyMediator; _enricherInvoked = tokenIssuer.GetCheckpointToken(HttpCheckpoints.EnricherInvoked); } public void Enrich(IEnrichmentTagCollector collector, HttpRequestMessage? request, HttpResponseMessage? response, Exception? exception) { - if (response != null) + if (response == null) { - var lc = _latencyContext.Get(); - - if (lc != null) - { - // Add the checkpoint - lc.AddCheckpoint(_enricherInvoked); - - // Use the mediator to record all metrics - _httpLatencyMediator.RecordEnd(lc, response); - } - - StringBuilder stringBuilder = _builderPool.Get(); - - try - { - /* Add version, serverName, checkpoints, and measures to outgoing http logs. - * Schemas: 1) ServerName,CheckpointName,CheckpointValue - * 2) v1.0,ServerName,TagName,TagValue,CheckpointName,CheckpointValue,MetricName,MetricValue - */ - - // Add version - _ = stringBuilder.Append("v1.0"); - _ = stringBuilder.Append(','); + return; + } - // Add server name - AppendServerName(response.Headers, stringBuilder); - _ = stringBuilder.Append(','); + var live = _latencyContext.Get(); + LatencySnapshot? snapshot = null; - // Add tags, checkpoints, and measures - if (lc != null) - { - AppendTags(lc, stringBuilder); - _ = stringBuilder.Append(','); + if (live == null && request != null) + { + _ = HttpRequestLatencySnapshotStore.TryGet(request, out snapshot); + } - AppendCheckpoints(lc, stringBuilder); - _ = stringBuilder.Append(','); + if (live != null) + { + // Final checkpoint for the logging enrichment only (no record-end here). + live.AddCheckpoint(_enricherInvoked); + } - AppendMeasures(lc, stringBuilder); - } + var sb = _builderPool.Get(); + try + { + _ = sb.Append("v1.0").Append(','); + AppendServerName(response.Headers, sb); + _ = sb.Append(','); - collector.Add("LatencyInfo", stringBuilder.ToString()); + if (live != null) + { + AppendTags(live.LatencyData, sb); _ = sb.Append(','); + AppendCheckpoints(live.LatencyData, sb); _ = sb.Append(','); + AppendMeasures(live.LatencyData, sb); } - finally + else if (snapshot != null) { - _builderPool.Return(stringBuilder); + AppendTags(snapshot, sb); _ = sb.Append(','); + AppendCheckpoints(snapshot, sb); _ = sb.Append(','); + AppendMeasures(snapshot, sb); } + + collector.Add("LatencyInfo", sb.ToString()); + } + finally + { + _builderPool.Return(sb); } } - private static void AppendServerName(HttpHeaders headers, StringBuilder stringBuilder) + private static void AppendServerName(HttpHeaders headers, StringBuilder sb) { if (headers.TryGetValues(TelemetryConstants.ServerApplicationNameHeader, out var values)) { - _ = stringBuilder.Append(values.First()); + _ = sb.Append(values.First()); } } - private static void AppendCheckpoints(ILatencyContext latencyContext, StringBuilder stringBuilder) + private static void AppendTags(in LatencyData data, StringBuilder sb) { - const int MillisecondsPerSecond = 1000; - - var latencyData = latencyContext.LatencyData; - var checkpointCount = latencyData.Checkpoints.Length; + var span = data.Tags; + for (int i = 0; i < span.Length; i++) + { + _ = sb.Append(span[i].Name).Append('/'); + } - for (int i = 0; i < checkpointCount; i++) + _ = sb.Append(','); + for (int i = 0; i < span.Length; i++) { - _ = stringBuilder.Append(latencyData.Checkpoints[i].Name); - _ = stringBuilder.Append('/'); + _ = sb.Append(span[i].Value).Append('/'); } + } - _ = stringBuilder.Append(','); + private static void AppendCheckpoints(in LatencyData data, StringBuilder sb) + { + const int MsPerSec = 1000; + var span = data.Checkpoints; + for (int i = 0; i < span.Length; i++) + { + _ = sb.Append(span[i].Name).Append('/'); + } - for (int i = 0; i < checkpointCount; i++) + _ = sb.Append(','); + for (int i = 0; i < span.Length; i++) { - var cp = latencyData.Checkpoints[i]; - _ = stringBuilder.Append((long)Math.Round(((double)cp.Elapsed / cp.Frequency) * MillisecondsPerSecond)); - _ = stringBuilder.Append('/'); + var cp = span[i]; + var ms = (long)Math.Round(((double)cp.Elapsed / cp.Frequency) * MsPerSec); + _ = sb.Append(ms).Append('/'); } } - private static void AppendMeasures(ILatencyContext latencyContext, StringBuilder stringBuilder) + private static void AppendMeasures(in LatencyData data, StringBuilder sb) { - var latencyData = latencyContext.LatencyData; - var measureCount = latencyData.Measures.Length; + var span = data.Measures; + for (int i = 0; i < span.Length; i++) + { + _ = sb.Append(span[i].Name).Append('/'); + } - for (int i = 0; i < measureCount; i++) + _ = sb.Append(','); + for (int i = 0; i < span.Length; i++) { - _ = stringBuilder.Append(latencyData.Measures[i].Name); - _ = stringBuilder.Append('/'); + _ = sb.Append(span[i].Value).Append('/'); } + } - _ = stringBuilder.Append(','); + // Snapshot overloads + private static void AppendTags(LatencySnapshot snapshot, StringBuilder sb) + { + var arr = snapshot.Tags; + for (int i = 0; i < arr.Length; i++) + { + _ = sb.Append(arr[i].Name).Append('/'); + } - for (int i = 0; i < measureCount; i++) + _ = sb.Append(','); + for (int i = 0; i < arr.Length; i++) { - _ = stringBuilder.Append(latencyData.Measures[i].Value); - _ = stringBuilder.Append('/'); + _ = sb.Append(arr[i].Value).Append('/'); } } - private static void AppendTags(ILatencyContext latencyContext, StringBuilder stringBuilder) + private static void AppendCheckpoints(LatencySnapshot snapshot, StringBuilder sb) { - var latencyData = latencyContext.LatencyData; - var tagCount = latencyData.Tags.Length; + const int MsPerSec = 1000; + var arr = snapshot.Checkpoints; + for (int i = 0; i < arr.Length; i++) + { + _ = sb.Append(arr[i].Name).Append('/'); + } - for (int i = 0; i < tagCount; i++) + _ = sb.Append(','); + for (int i = 0; i < arr.Length; i++) { - _ = stringBuilder.Append(latencyData.Tags[i].Name); - _ = stringBuilder.Append('/'); + var cp = arr[i]; + var ms = (long)Math.Round(((double)cp.Elapsed / cp.Frequency) * MsPerSec); + _ = sb.Append(ms).Append('/'); } + } - _ = stringBuilder.Append(','); + private static void AppendMeasures(LatencySnapshot snapshot, StringBuilder sb) + { + var arr = snapshot.Measures; + foreach (var t in arr) + { + _ = sb.Append(t.Name).Append('/'); + } - for (int i = 0; i < tagCount; i++) + _ = sb.Append(','); + foreach (var t in arr) { - _ = stringBuilder.Append(latencyData.Tags[i].Value); - _ = stringBuilder.Append('/'); + _ = sb.Append(t.Value).Append('/'); } } } \ No newline at end of file diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs index 81a0878b3f5..d8b92c986e6 100644 --- a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpLatencyTelemetryHandler.cs @@ -54,6 +54,19 @@ protected async override Task SendAsync(HttpRequestMessage _ = request.Headers.TryAddWithoutValidation(TelemetryConstants.ClientApplicationNameHeader, _applicationName); - return await base.SendAsync(request, cancellationToken).ConfigureAwait(false); + var response = await base.SendAsync(request, cancellationToken).ConfigureAwait(false); + + // End metrics (only once, here) then snapshot. +#if NET + _latencyMediator.RecordEnd(context, response); +#endif + var data = context.LatencyData; + if (data.Tags.Length > 0 || data.Checkpoints.Length > 0 || data.Measures.Length > 0) + { + var snapshot = new LatencySnapshot(in data); + HttpRequestLatencySnapshotStore.Set(request, snapshot); + } + + return response; } } diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencySnapshotStore.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencySnapshotStore.cs new file mode 100644 index 00000000000..3e5a46c79f4 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/HttpRequestLatencySnapshotStore.cs @@ -0,0 +1,37 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Net.Http; + +namespace Microsoft.Extensions.Http.Latency.Internal; + +/// +/// Internal helper to persist an immutable latency snapshot on the request. +/// +internal static class HttpRequestLatencySnapshotStore +{ +#if NET6_0_OR_GREATER + private static readonly HttpRequestOptionsKey _key = new("LatencySnapshot"); + public static void Set(HttpRequestMessage request, LatencySnapshot snapshot) + => request.Options.Set(_key, snapshot); + + public static bool TryGet(HttpRequestMessage request, out LatencySnapshot? snapshot) + => request.Options.TryGetValue(_key, out snapshot); +#else + private const string Key = "LatencySnapshot"; + public static void Set(HttpRequestMessage request, LatencySnapshot snapshot) + => request.Properties[Key] = snapshot; + + public static bool TryGet(HttpRequestMessage request, out LatencySnapshot? snapshot) + { + if (request.Properties.TryGetValue(Key, out var obj) && obj is LatencySnapshot s) + { + snapshot = s; + return true; + } + + snapshot = null; + return false; + } +#endif +} diff --git a/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/LatencySnapshot.cs b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/LatencySnapshot.cs new file mode 100644 index 00000000000..49ceafac32c --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Http.Diagnostics/Latency/Internal/LatencySnapshot.cs @@ -0,0 +1,52 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using Microsoft.Extensions.Diagnostics.Latency; + +namespace Microsoft.Extensions.Http.Latency.Internal; + +internal sealed class LatencySnapshot(in LatencyData data) +{ + public Tag[] Tags { get; } = CopyTags(data.Tags); + public Checkpoint[] Checkpoints { get; } = CopyCheckpoints(data.Checkpoints); + public Measure[] Measures { get; } = CopyMeasures(data.Measures); + public long DurationTimestamp { get; } = data.DurationTimestamp; + public long DurationTimestampFrequency { get; } = data.DurationTimestampFrequency; + + private static Tag[] CopyTags(ReadOnlySpan src) + { + if (src.IsEmpty) + { + return []; + } + + var arr = new Tag[src.Length]; + src.CopyTo(arr); + return arr; + } + + private static Checkpoint[] CopyCheckpoints(ReadOnlySpan src) + { + if (src.IsEmpty) + { + return []; + } + + var arr = new Checkpoint[src.Length]; + src.CopyTo(arr); + return arr; + } + + private static Measure[] CopyMeasures(ReadOnlySpan src) + { + if (src.IsEmpty) + { + return []; + } + + var arr = new Measure[src.Length]; + src.CopyTo(arr); + return arr; + } +} \ No newline at end of file