diff --git a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs index b8c5407da6d..3c09dde5eda 100644 --- a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs +++ b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs @@ -39,6 +39,8 @@ public sealed partial class OpenTelemetryChatClient : DelegatingChatClient private readonly Histogram _tokenUsageHistogram; private readonly Histogram _operationDurationHistogram; + private readonly Histogram _timeToFirstChunkHistogram; + private readonly Histogram _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( + OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.Name, + OpenTelemetryConsts.SecondsUnit, + OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.Description, + advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.Client.TimeToFirstChunk.ExplicitBucketBoundaries } + ); + + _timePerOutputChunkHistogram = _meter.CreateHistogram( + 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 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 GetStreamingResponseA var responseEnumerator = updates.GetAsyncEnumerator(cancellationToken); List 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 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); } } diff --git a/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs b/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs index dc914fca427..04a33a75be5 100644 --- a/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs +++ b/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 diff --git a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs index 3f1c9f59bce..d78912ee8fb 100644 --- a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs +++ b/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(); + 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 CallbackAsync( + IEnumerable 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(null, sourceName, "gen_ai.client.operation.time_to_first_chunk"); + using var timePerOutputChunkCollector = new MetricCollector(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("gen_ai.operation.name", "chat"), + new KeyValuePair("gen_ai.request.model", "mymodel"), + new KeyValuePair("gen_ai.response.model", "responsemodel"), + new KeyValuePair("gen_ai.provider.name", "testprovider"), + new KeyValuePair("server.address", "localhost"), + new KeyValuePair("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("gen_ai.operation.name", "chat"), + new KeyValuePair("gen_ai.request.model", "mymodel"), + new KeyValuePair("gen_ai.response.model", "responsemodel"), + new KeyValuePair("gen_ai.provider.name", "testprovider"), + new KeyValuePair("server.address", "localhost"), + new KeyValuePair("server.port", 5000))); + } + } + + [Fact] + public async Task StreamingChunkMetrics_NotRecordedForNonStreamingCalls() + { + var sourceName = Guid.NewGuid().ToString(); + var activities = new List(); + 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(null, sourceName, "gen_ai.client.operation.time_to_first_chunk"); + using var timePerOutputChunkCollector = new MetricCollector(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();