Implement time_to_first_chunk and time_per_output_chunk streaming metrics in OpenTelemetryChatClient

src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs

@@ -39,6 +39,8 @@ public sealed partial class OpenTelemetryChatClient : DelegatingChatClient
 
     private readonly Histogram<int> _tokenUsageHistogram;
     private readonly Histogram<double> _operationDurationHistogram;
+    private readonly Histogram<double> _timeToFirstChunkHistogram;
+    private readonly Histogram<double> _timePerOutputChunkHistogram;
 
     private readonly string? _defaultModelId;
     private readonly string? _providerName;
@@ -84,6 +86,20 @@ public OpenTelemetryChatClient(IChatClient innerClient, ILogger? logger = null,
             advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.Client.OperationDuration.ExplicitBucketBoundaries }
             );
 
+        _timeToFirstChunkHistogram = _meter.CreateHistogram<double>(
+            OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.Name,
+            OpenTelemetryConsts.SecondsUnit,
+            OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.Description,
+            advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.ExplicitBucketBoundaries }
+            );
+
+        _timePerOutputChunkHistogram = _meter.CreateHistogram<double>(
+            OpenTelemetryConsts.GenAI.Client.TimePerOutputChunk.Name,
+            OpenTelemetryConsts.SecondsUnit,
+            OpenTelemetryConsts.GenAI.Client.TimePerOutputChunk.Description,
+            advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.Client.TimePerOutputChunk.ExplicitBucketBoundaries }
+            );
+
         _jsonSerializerOptions = AIJsonUtilities.DefaultOptions;
     }
 
@@ -167,7 +183,8 @@ public override async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseA
         _jsonSerializerOptions.MakeReadOnly();
 
         using Activity? activity = CreateAndConfigureActivity(options);
-        Stopwatch? stopwatch = _operationDurationHistogram.Enabled ? Stopwatch.StartNew() : null;
+        bool trackChunkTimes = _timeToFirstChunkHistogram.Enabled || _timePerOutputChunkHistogram.Enabled;
+        Stopwatch? stopwatch = _operationDurationHistogram.Enabled || trackChunkTimes ? Stopwatch.StartNew() : null;
         string? requestModelId = options?.ModelId ?? _defaultModelId;
 
         AddInputMessagesTags(messages, options, activity);
@@ -185,6 +202,15 @@ public override async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseA
 
         var responseEnumerator = updates.GetAsyncEnumerator(cancellationToken);
         List<ChatResponseUpdate> trackedUpdates = [];
+        TimeSpan lastChunkElapsed = default;
+        bool isFirstChunk = true;
+        bool responseModelSet = false;
+        TagList chunkMetricTags = default;
+        if (trackChunkTimes)
+        {
+            AddMetricTags(ref chunkMetricTags, requestModelId, response: null);
+        }
+
         Exception? error = null;
         try
         {
@@ -206,6 +232,34 @@ public override async IAsyncEnumerable<ChatResponseUpdate> GetStreamingResponseA
                     throw;
                 }
 
+                if (trackChunkTimes)
+                {
+                    Debug.Assert(stopwatch is not null, "stopwatch should have been initialized when trackChunkTimes is true");
+                    TimeSpan currentElapsed = stopwatch!.Elapsed;
+                    double delta = (currentElapsed - lastChunkElapsed).TotalSeconds;
+
+                    if (!responseModelSet && update.ModelId is string modelId)
+                    {
+                        chunkMetricTags.Add(OpenTelemetryConsts.GenAI.Response.Model, modelId);
+                        responseModelSet = true;
+                    }
+
+                    if (isFirstChunk)
+                    {
+                        isFirstChunk = false;
+                        if (_timeToFirstChunkHistogram.Enabled)
+                        {
+                            _timeToFirstChunkHistogram.Record(delta, chunkMetricTags);
+                        }
+                    }
+                    else if (_timePerOutputChunkHistogram.Enabled)
+                    {
+                        _timePerOutputChunkHistogram.Record(delta, chunkMetricTags);
+                    }
+
+                    lastChunkElapsed = currentElapsed;
+                }
+
                 trackedUpdates.Add(update);
                 yield return update;
                 Activity.Current = activity; // workaround for https://github.com/dotnet/runtime/issues/47802
@@ -709,28 +763,28 @@ private void TraceResponse(
                 }
             }
         }
+    }
 
-        void AddMetricTags(ref TagList tags, string? requestModelId, ChatResponse? response)
-        {
-            tags.Add(OpenTelemetryConsts.GenAI.Operation.Name, OpenTelemetryConsts.GenAI.ChatName);
+    private void AddMetricTags(ref TagList tags, string? requestModelId, ChatResponse? response)
+    {
+        tags.Add(OpenTelemetryConsts.GenAI.Operation.Name, OpenTelemetryConsts.GenAI.ChatName);
 
-            if (requestModelId is not null)
-            {
-                tags.Add(OpenTelemetryConsts.GenAI.Request.Model, requestModelId);
-            }
+        if (requestModelId is not null)
+        {
+            tags.Add(OpenTelemetryConsts.GenAI.Request.Model, requestModelId);
+        }
 
-            tags.Add(OpenTelemetryConsts.GenAI.Provider.Name, _providerName);
+        tags.Add(OpenTelemetryConsts.GenAI.Provider.Name, _providerName);
 
-            if (_serverAddress is string endpointAddress)
-            {
-                tags.Add(OpenTelemetryConsts.Server.Address, endpointAddress);
-                tags.Add(OpenTelemetryConsts.Server.Port, _serverPort);
-            }
+        if (_serverAddress is string endpointAddress)
+        {
+            tags.Add(OpenTelemetryConsts.Server.Address, endpointAddress);
+            tags.Add(OpenTelemetryConsts.Server.Port, _serverPort);
+        }
 
-            if (response?.ModelId is string responseModel)
-            {
-                tags.Add(OpenTelemetryConsts.GenAI.Response.Model, responseModel);
-            }
+        if (response?.ModelId is string responseModel)
+        {
+            tags.Add(OpenTelemetryConsts.GenAI.Response.Model, responseModel);
         }
     }
 

src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs

@@ -56,6 +56,20 @@ public static class TokenUsage
                 public const string Name = "gen_ai.client.token.usage";
                 public static readonly int[] ExplicitBucketBoundaries = [1, 4, 16, 64, 256, 1_024, 4_096, 16_384, 65_536, 262_144, 1_048_576, 4_194_304, 16_777_216, 67_108_864];
             }
+
+            public static class TimeToFirstChunk
+            {
+                public const string Description = "Measures the time to receive the first chunk in a streaming operation";
+                public const string Name = "gen_ai.client.operation.time_to_first_chunk";
+                public static readonly double[] ExplicitBucketBoundaries = OperationDuration.ExplicitBucketBoundaries;
+            }
+
+            public static class TimePerOutputChunk
+            {
+                public const string Description = "Measures the time per output chunk in a streaming operation";
+                public const string Name = "gen_ai.client.operation.time_per_output_chunk";
+                public static readonly double[] ExplicitBucketBoundaries = OperationDuration.ExplicitBucketBoundaries;
+            }
         }
 
         public static class Conversation

test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs

@@ -9,6 +9,7 @@
 using System.Text.RegularExpressions;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Diagnostics.Metrics.Testing;
 using OpenTelemetry.Trace;
 using Xunit;
 
@@ -835,6 +836,109 @@ public async Task McpServerToolApprovalContentTypes_SerializedCorrectly()
             """), ReplaceWhitespace(inputMessages));
     }
 
+    [Fact]
+    public async Task StreamingChunkMetrics_RecordedForStreamingCalls()
+    {
+        var sourceName = Guid.NewGuid().ToString();
+        var activities = new List<Activity>();
+        using var tracerProvider = OpenTelemetry.Sdk.CreateTracerProviderBuilder()
+            .AddSource(sourceName)
+            .AddInMemoryExporter(activities)
+            .Build();
+
+        using var innerClient = new TestChatClient
+        {
+            GetStreamingResponseAsyncCallback = CallbackAsync,
+            GetServiceCallback = (serviceType, serviceKey) =>
+                serviceType == typeof(ChatClientMetadata) ? new ChatClientMetadata("testprovider", new Uri("http://localhost:5000/api"), "testmodel") :
+                null,
+        };
+
+        async static IAsyncEnumerable<ChatResponseUpdate> CallbackAsync(
+            IEnumerable<ChatMessage> messages, ChatOptions? options, [EnumeratorCancellation] CancellationToken cancellationToken)
+        {
+            await Task.Yield();
+            yield return new ChatResponseUpdate(ChatRole.Assistant, "First") { ResponseId = "id1", ModelId = "responsemodel" };
+            await Task.Yield();
+            yield return new ChatResponseUpdate(ChatRole.Assistant, "Second") { ResponseId = "id1" };
+            await Task.Yield();
+            yield return new ChatResponseUpdate(ChatRole.Assistant, "Third") { ResponseId = "id1" };
+        }
+
+        using var chatClient = innerClient
+            .AsBuilder()
+            .UseOpenTelemetry(null, sourceName)
+            .Build();
+
+        using var timeToFirstChunkCollector = new MetricCollector<double>(null, sourceName, "gen_ai.client.operation.time_to_first_chunk");
+        using var timePerOutputChunkCollector = new MetricCollector<double>(null, sourceName, "gen_ai.client.operation.time_per_output_chunk");
+
+        await foreach (var update in chatClient.GetStreamingResponseAsync([new(ChatRole.User, "Hello")], new ChatOptions { ModelId = "mymodel" }))
+        {
+            // consume all updates
+        }
+
+        // time_to_first_chunk: exactly 1 measurement for the first chunk
+        var ttfcMeasurements = timeToFirstChunkCollector.GetMeasurementSnapshot();
+        Assert.Single(ttfcMeasurements);
+        Assert.True(ttfcMeasurements[0].Value > 0);
+        Assert.True(ttfcMeasurements[0].ContainsTags(
+            new KeyValuePair<string, object?>("gen_ai.operation.name", "chat"),
+            new KeyValuePair<string, object?>("gen_ai.request.model", "mymodel"),
+            new KeyValuePair<string, object?>("gen_ai.response.model", "responsemodel"),
+            new KeyValuePair<string, object?>("gen_ai.provider.name", "testprovider"),
+            new KeyValuePair<string, object?>("server.address", "localhost"),
+            new KeyValuePair<string, object?>("server.port", 5000)));
+
+        // time_per_output_chunk: one measurement for each chunk after the first (2 chunks)
+        var tpocMeasurements = timePerOutputChunkCollector.GetMeasurementSnapshot();
+        Assert.Equal(2, tpocMeasurements.Count);
+        foreach (var measurement in tpocMeasurements)
+        {
+            Assert.True(measurement.Value > 0);
+            Assert.True(measurement.ContainsTags(
+                new KeyValuePair<string, object?>("gen_ai.operation.name", "chat"),
+                new KeyValuePair<string, object?>("gen_ai.request.model", "mymodel"),
+                new KeyValuePair<string, object?>("gen_ai.response.model", "responsemodel"),
+                new KeyValuePair<string, object?>("gen_ai.provider.name", "testprovider"),
+                new KeyValuePair<string, object?>("server.address", "localhost"),
+                new KeyValuePair<string, object?>("server.port", 5000)));
+        }
+    }
+
+    [Fact]
+    public async Task StreamingChunkMetrics_NotRecordedForNonStreamingCalls()
+    {
+        var sourceName = Guid.NewGuid().ToString();
+        var activities = new List<Activity>();
+        using var tracerProvider = OpenTelemetry.Sdk.CreateTracerProviderBuilder()
+            .AddSource(sourceName)
+            .AddInMemoryExporter(activities)
+            .Build();
+
+        using var innerClient = new TestChatClient
+        {
+            GetResponseAsyncCallback = async (messages, options, cancellationToken) =>
+            {
+                await Task.Yield();
+                return new ChatResponse(new ChatMessage(ChatRole.Assistant, "Response"));
+            },
+        };
+
+        using var chatClient = innerClient
+            .AsBuilder()
+            .UseOpenTelemetry(null, sourceName)
+            .Build();
+
+        using var timeToFirstChunkCollector = new MetricCollector<double>(null, sourceName, "gen_ai.client.operation.time_to_first_chunk");
+        using var timePerOutputChunkCollector = new MetricCollector<double>(null, sourceName, "gen_ai.client.operation.time_per_output_chunk");
+
+        await chatClient.GetResponseAsync([new(ChatRole.User, "Hello")]);
+
+        Assert.Empty(timeToFirstChunkCollector.GetMeasurementSnapshot());
+        Assert.Empty(timePerOutputChunkCollector.GetMeasurementSnapshot());
+    }
+
     private sealed class NonSerializableAIContent : AIContent;
 
     private static string ReplaceWhitespace(string? input) => Regex.Replace(input ?? "", @"\s+", " ").Trim();