diff --git a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs index da702dcf32a..a466fe65ff5 100644 --- a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs +++ b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/FunctionInvokingChatClient.cs @@ -5,6 +5,7 @@ using System.Collections.Generic; using System.Diagnostics; using System.Diagnostics.CodeAnalysis; +using System.Diagnostics.Metrics; using System.Linq; using System.Runtime.CompilerServices; using System.Runtime.ExceptionServices; @@ -79,6 +80,10 @@ public class FunctionInvokingChatClient : DelegatingChatClient /// This component does not own the instance and should not dispose it. private readonly ActivitySource? _activitySource; + /// The gen_ai.execute_tool.duration histogram, or if no is available. + /// This component does not own the underlying and should not dispose it. + private readonly Histogram? _executeToolDurationHistogram; + /// /// Initializes a new instance of the class. /// @@ -90,6 +95,11 @@ public FunctionInvokingChatClient(IChatClient innerClient, ILoggerFactory? logge { _logger = (ILogger?)loggerFactory?.CreateLogger() ?? NullLogger.Instance; _activitySource = innerClient.GetService(); + if (innerClient.GetService() is Meter meter) + { + _executeToolDurationHistogram = OtelMetricHelpers.CreateGenAIExecuteToolDurationHistogram(meter); + } + FunctionInvocationServices = functionInvocationServices; } @@ -101,7 +111,8 @@ public FunctionInvokingChatClient(IChatClient innerClient, ILoggerFactory? logge invokeAgentActivity => invokeAgentActivity is not null ? invokeAgentActivity.GetCustomProperty(OpenTelemetryChatClient.SensitiveDataEnabledCustomKey) as string is OpenTelemetryChatClient.SensitiveDataEnabledTrueValue - : InnerClient.GetService()?.EnableSensitiveData is true); + : InnerClient.GetService()?.EnableSensitiveData is true, + _executeToolDurationHistogram); /// /// Gets or sets the for the current function invocation. diff --git a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs index 326503bc04d..99f9b4d0642 100644 --- a/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs +++ b/src/Libraries/Microsoft.Extensions.AI/ChatCompletion/OpenTelemetryChatClient.cs @@ -129,6 +129,7 @@ protected override void Dispose(bool disposing) /// public override object? GetService(Type serviceType, object? serviceKey = null) => serviceType == typeof(ActivitySource) ? _activitySource : + serviceType == typeof(Meter) ? _meter : base.GetService(serviceType, serviceKey); /// @@ -328,6 +329,24 @@ public override async IAsyncEnumerable GetStreamingResponseA _ = activity.AddTag(OpenTelemetryConsts.GenAI.Request.PresencePenalty, presencePenalty); } + if (options.Reasoning?.Effort is ReasoningEffort reasoningEffort) + { + // The spec recommends emitting the exact string sent to the provider; the provider-agnostic + // layer only has the abstract ReasoningEffort, so emit a normalized token for it. A provider + // package can override with its exact wire value (e.g. OpenAI sends "xhigh" for ExtraHigh). + string reasoningLevel = reasoningEffort switch + { + ReasoningEffort.None => "none", + ReasoningEffort.Low => "low", + ReasoningEffort.Medium => "medium", + ReasoningEffort.High => "high", + ReasoningEffort.ExtraHigh => "extra_high", + _ => reasoningEffort.ToString().ToLowerInvariant(), + }; + + _ = activity.AddTag(OpenTelemetryConsts.GenAI.Request.ReasoningLevel, reasoningLevel); + } + if (options.Seed is long seed) { _ = activity.AddTag(OpenTelemetryConsts.GenAI.Request.Seed, seed); diff --git a/src/Libraries/Microsoft.Extensions.AI/Common/FunctionInvocationProcessor.cs b/src/Libraries/Microsoft.Extensions.AI/Common/FunctionInvocationProcessor.cs index c4a1d2448e4..0e2678902d2 100644 --- a/src/Libraries/Microsoft.Extensions.AI/Common/FunctionInvocationProcessor.cs +++ b/src/Libraries/Microsoft.Extensions.AI/Common/FunctionInvocationProcessor.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.Metrics; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -22,6 +23,7 @@ internal sealed class FunctionInvocationProcessor { private readonly ILogger _logger; private readonly ActivitySource? _activitySource; + private readonly Histogram? _executeToolDurationHistogram; private readonly Func> _invokeFunction; private readonly Func _isSensitiveDataEnabled; @@ -36,16 +38,19 @@ internal sealed class FunctionInvocationProcessor /// Receives the invoke agent activity (or null if not in agent context). /// Returns true if sensitive data should be logged/tagged, false otherwise. /// + /// The optional gen_ai.execute_tool.duration histogram to record tool execution durations on. public FunctionInvocationProcessor( ILogger logger, ActivitySource? activitySource, Func> invokeFunction, - Func? isSensitiveDataEnabled = null) + Func? isSensitiveDataEnabled = null, + Histogram? executeToolDurationHistogram = null) { _logger = logger; _activitySource = activitySource; _invokeFunction = invokeFunction; _isSensitiveDataEnabled = isSensitiveDataEnabled ?? (_ => false); + _executeToolDurationHistogram = executeToolDurationHistogram; } /// @@ -199,15 +204,18 @@ private async Task ProcessSingleFunctionCallAsync( } object? result = null; + string? errorType = null; try { result = await _invokeFunction(context, cancellationToken).ConfigureAwait(false); } catch (Exception e) { + errorType = e.GetType().FullName; + if (activity is not null) { - _ = activity.SetTag(OpenTelemetryConsts.Error.Type, e.GetType().FullName) + _ = activity.SetTag(OpenTelemetryConsts.Error.Type, errorType) .SetStatus(ActivityStatusCode.Error, e.Message); } @@ -224,6 +232,19 @@ private async Task ProcessSingleFunctionCallAsync( } finally { + if (_executeToolDurationHistogram is { Enabled: true } executeToolDurationHistogram) + { + TagList tags = default; + tags.Add(OpenTelemetryConsts.GenAI.Tool.Name, context.Function.Name); + tags.Add(OpenTelemetryConsts.GenAI.Tool.Type, OpenTelemetryConsts.ToolTypeFunction); + if (errorType is not null) + { + tags.Add(OpenTelemetryConsts.Error.Type, errorType); + } + + executeToolDurationHistogram.Record(FunctionInvocationHelpers.GetElapsedTime(startingTimestamp).TotalSeconds, tags); + } + bool loggedResult = false; if (enableSensitiveData || traceLoggingEnabled) { diff --git a/src/Libraries/Microsoft.Extensions.AI/Common/OtelMetricHelpers.cs b/src/Libraries/Microsoft.Extensions.AI/Common/OtelMetricHelpers.cs index ca572ca515a..61ba6efa32f 100644 --- a/src/Libraries/Microsoft.Extensions.AI/Common/OtelMetricHelpers.cs +++ b/src/Libraries/Microsoft.Extensions.AI/Common/OtelMetricHelpers.cs @@ -23,4 +23,12 @@ public static Histogram CreateGenAIOperationDurationHistogram(Meter mete OpenTelemetryConsts.SecondsUnit, OpenTelemetryConsts.GenAI.Client.OperationDuration.Description, advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.Client.OperationDuration.ExplicitBucketBoundaries }); + + /// Creates the standard gen_ai.execute_tool.duration histogram on . + public static Histogram CreateGenAIExecuteToolDurationHistogram(Meter meter) => + meter.CreateHistogram( + OpenTelemetryConsts.GenAI.ExecuteTool.Duration.Name, + OpenTelemetryConsts.SecondsUnit, + OpenTelemetryConsts.GenAI.ExecuteTool.Duration.Description, + advice: new() { HistogramBucketBoundaries = OpenTelemetryConsts.GenAI.ExecuteTool.Duration.ExplicitBucketBoundaries }); } diff --git a/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs b/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs index 804d0d9f684..afc59f00de6 100644 --- a/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs +++ b/src/Libraries/Microsoft.Extensions.AI/OpenTelemetryConsts.cs @@ -126,6 +126,7 @@ public static class Request public const string Model = "gen_ai.request.model"; public const string MaxTokens = "gen_ai.request.max_tokens"; public const string PresencePenalty = "gen_ai.request.presence_penalty"; + public const string ReasoningLevel = "gen_ai.request.reasoning.level"; public const string Seed = "gen_ai.request.seed"; public const string StopSequences = "gen_ai.request.stop_sequences"; public const string Stream = "gen_ai.request.stream"; @@ -163,6 +164,16 @@ public static class Call } } + public static class ExecuteTool + { + public static class Duration + { + public const string Description = "Measures the duration of a tool execution."; + public const string Name = "gen_ai.execute_tool.duration"; + public static readonly double[] ExplicitBucketBoundaries = [0.01, 0.02, 0.04, 0.08, 0.16, 0.32, 0.64, 1.28, 2.56, 5.12, 10.24, 20.48, 40.96, 81.92]; + } + } + public static class Usage { public const string InputTokens = "gen_ai.usage.input_tokens"; diff --git a/src/Libraries/Microsoft.Extensions.AI/Realtime/FunctionInvokingRealtimeClientSession.cs b/src/Libraries/Microsoft.Extensions.AI/Realtime/FunctionInvokingRealtimeClientSession.cs index 7c79bc449fb..594dd02f0fd 100644 --- a/src/Libraries/Microsoft.Extensions.AI/Realtime/FunctionInvokingRealtimeClientSession.cs +++ b/src/Libraries/Microsoft.Extensions.AI/Realtime/FunctionInvokingRealtimeClientSession.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.Metrics; using System.Runtime.CompilerServices; using System.Threading; using System.Threading.Tasks; @@ -67,6 +68,10 @@ internal sealed class FunctionInvokingRealtimeClientSession : IRealtimeClientSes /// This component does not own the instance and should not dispose it. private readonly ActivitySource? _activitySource; + /// The gen_ai.execute_tool.duration histogram, or if no is available. + /// This component does not own the underlying and should not dispose it. + private readonly Histogram? _executeToolDurationHistogram; + /// The inner session to delegate to. private readonly IRealtimeClientSession _innerSession; @@ -86,6 +91,11 @@ public FunctionInvokingRealtimeClientSession(IRealtimeClientSession innerSession _client = Throw.IfNull(client); _logger = (ILogger?)loggerFactory?.CreateLogger() ?? NullLogger.Instance; _activitySource = innerSession.GetService(); + if (innerSession.GetService() is Meter meter) + { + _executeToolDurationHistogram = OtelMetricHelpers.CreateGenAIExecuteToolDurationHistogram(meter); + } + FunctionInvocationServices = functionInvocationServices; } @@ -93,7 +103,8 @@ public FunctionInvokingRealtimeClientSession(IRealtimeClientSession innerSession private FunctionInvocationProcessor Processor => field ??= new FunctionInvocationProcessor( _logger, _activitySource, - InvokeFunctionAsync); + InvokeFunctionAsync, + executeToolDurationHistogram: _executeToolDurationHistogram); /// /// Gets or sets the for the current function invocation. diff --git a/src/Libraries/Microsoft.Extensions.AI/Realtime/OpenTelemetryRealtimeClientSession.cs b/src/Libraries/Microsoft.Extensions.AI/Realtime/OpenTelemetryRealtimeClientSession.cs index a7f78f9e9a6..ef6416225e6 100644 --- a/src/Libraries/Microsoft.Extensions.AI/Realtime/OpenTelemetryRealtimeClientSession.cs +++ b/src/Libraries/Microsoft.Extensions.AI/Realtime/OpenTelemetryRealtimeClientSession.cs @@ -168,6 +168,7 @@ public async ValueTask DisposeAsync() return serviceType == typeof(ActivitySource) ? _activitySource : + serviceType == typeof(Meter) ? _meter : serviceKey is null && serviceType.IsInstanceOfType(this) ? this : _innerSession.GetService(serviceType, serviceKey); } diff --git a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs index 4a88883cdbf..ffdeb4adefc 100644 --- a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs +++ b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/FunctionInvokingChatClientTests.cs @@ -9,6 +9,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Metrics.Testing; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Testing; using OpenTelemetry.Trace; @@ -1164,6 +1165,39 @@ async Task InvokeAsync(Func work) } } + [Fact] + public async Task ExecuteToolDurationMetricRecorded() + { + string sourceName = Guid.NewGuid().ToString(); + + List plan = + [ + new ChatMessage(ChatRole.User, "hello"), + new ChatMessage(ChatRole.Assistant, [new FunctionCallContent("callId1", "Func1", new Dictionary { ["arg1"] = "value1" })]), + new ChatMessage(ChatRole.Tool, [new FunctionResultContent("callId1", result: "Result 1")]), + new ChatMessage(ChatRole.Assistant, "world"), + ]; + + ChatOptions options = new() + { + Tools = [AIFunctionFactory.Create(() => "Result 1", "Func1")] + }; + + Func configure = b => b.Use(c => + new FunctionInvokingChatClient(new OpenTelemetryChatClient(c, sourceName: sourceName))); + + using var executeToolDurationCollector = new MetricCollector(null, sourceName, "gen_ai.execute_tool.duration"); + + await InvokeAndAssertAsync(options, plan, configurePipeline: configure); + + var measurement = Assert.Single(executeToolDurationCollector.GetMeasurementSnapshot()); + Assert.True(measurement.Value >= 0); + Assert.True(measurement.ContainsTags( + new KeyValuePair("gen_ai.tool.name", "Func1"), + new KeyValuePair("gen_ai.tool.type", "function"))); + Assert.False(measurement.Tags.ContainsKey("error.type")); + } + [Fact] public async Task SupportsConsecutiveStreamingUpdatesWithFunctionCalls() { diff --git a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs index 6ef724f7c66..7a8e16894d1 100644 --- a/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs +++ b/test/Libraries/Microsoft.Extensions.AI.Tests/ChatCompletion/OpenTelemetryChatClientTests.cs @@ -130,6 +130,7 @@ async static IAsyncEnumerable CallbackAsync( ResponseFormat = ChatResponseFormat.Json, Temperature = 6.0f, Seed = 42, + Reasoning = new() { Effort = ReasoningEffort.High }, StopSequences = ["hello", "world"], AdditionalProperties = new() { @@ -178,6 +179,7 @@ async static IAsyncEnumerable CallbackAsync( Assert.Equal(5.0f, activity.GetTagItem("gen_ai.request.presence_penalty")); Assert.Equal(6.0f, activity.GetTagItem("gen_ai.request.temperature")); Assert.Equal(7, activity.GetTagItem("gen_ai.request.top_k")); + Assert.Equal("high", activity.GetTagItem("gen_ai.request.reasoning.level")); Assert.Equal(123, activity.GetTagItem("gen_ai.request.max_tokens")); Assert.Equal("""["hello", "world"]""", activity.GetTagItem("gen_ai.request.stop_sequences")); Assert.Equal(enableSensitiveData ? "value1" : null, activity.GetTagItem("service_tier"));