diff --git a/dotnet/samples/ApplicationInsightsExample/Program.cs b/dotnet/samples/ApplicationInsightsExample/Program.cs index 53850e9f95eb..e90cea2e1aa8 100644 --- a/dotnet/samples/ApplicationInsightsExample/Program.cs +++ b/dotnet/samples/ApplicationInsightsExample/Program.cs @@ -174,14 +174,22 @@ private static void ConfigureMetering(MeterListener meterListener, TelemetryClie } }; - MeasurementCallback measurementCallback = (instrument, measurement, tags, state) => + meterListener.SetMeasurementEventCallback(GetMeasurementCallback(telemetryClient)); + meterListener.SetMeasurementEventCallback(GetMeasurementCallback(telemetryClient)); + + meterListener.Start(); + } + + /// + /// The callback which can be used to get measurement recording. + /// + /// Instance of Application Insights . + private static MeasurementCallback GetMeasurementCallback(TelemetryClient telemetryClient) where T : struct + { + return (instrument, measurement, tags, state) => { telemetryClient.GetMetric(instrument.Name).TrackValue(measurement); }; - - meterListener.SetMeasurementEventCallback(measurementCallback); - - meterListener.Start(); } /// diff --git a/dotnet/src/SemanticKernel/Planning/IPlan.cs b/dotnet/src/SemanticKernel/Planning/IPlan.cs new file mode 100644 index 000000000000..da1005c25b16 --- /dev/null +++ b/dotnet/src/SemanticKernel/Planning/IPlan.cs @@ -0,0 +1,12 @@ +// Copyright (c) Microsoft. All rights reserved. + +using Microsoft.SemanticKernel.SkillDefinition; + +namespace Microsoft.SemanticKernel.Planning; + +/// +/// Interface for standard Semantic Kernel callable plan. +/// +public interface IPlan : ISKFunction +{ +} diff --git a/dotnet/src/SemanticKernel/Planning/InstrumentedPlan.cs b/dotnet/src/SemanticKernel/Planning/InstrumentedPlan.cs new file mode 100644 index 000000000000..8eeeb54a24ad --- /dev/null +++ b/dotnet/src/SemanticKernel/Planning/InstrumentedPlan.cs @@ -0,0 +1,169 @@ +// Copyright (c) Microsoft. All rights reserved. + +using System; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.SemanticKernel.AI.TextCompletion; +using Microsoft.SemanticKernel.Orchestration; +using Microsoft.SemanticKernel.SkillDefinition; + +namespace Microsoft.SemanticKernel.Planning; + +/// +/// Standard Semantic Kernel callable plan with instrumentation. +/// +public sealed class InstrumentedPlan : IPlan +{ + /// + public string Name => this._plan.Name; + + /// + public string SkillName => this._plan.SkillName; + + /// + public string Description => this._plan.Description; + + /// + public bool IsSemantic => this._plan.IsSemantic; + + /// + public CompleteRequestSettings RequestSettings => this._plan.RequestSettings; + + /// + /// Initialize a new instance of the class. + /// + /// Instance of to decorate. + /// Optional logger. + public InstrumentedPlan( + IPlan plan, + ILogger? logger = null) + { + this._plan = plan; + this._logger = logger ?? NullLogger.Instance; + } + + /// + public FunctionView Describe() + { + return this._plan.Describe(); + } + + /// + public async Task InvokeAsync( + SKContext context, + CompleteRequestSettings? settings = null, + CancellationToken cancellationToken = default) + { + return await this.InvokeWithInstrumentationAsync(() => + this._plan.InvokeAsync(context, settings, cancellationToken)).ConfigureAwait(false); + } + + /// + public async Task InvokeAsync( + string? input = null, + CompleteRequestSettings? settings = null, + ILogger? logger = null, + CancellationToken cancellationToken = default) + { + return await this.InvokeWithInstrumentationAsync(() => + this._plan.InvokeAsync(input, settings, logger ?? this._logger, cancellationToken)).ConfigureAwait(false); + } + + /// + public ISKFunction SetAIConfiguration(CompleteRequestSettings settings) => + this._plan.SetAIConfiguration(settings); + + /// + public ISKFunction SetAIService(Func serviceFactory) => + this._plan.SetAIService(serviceFactory); + + /// + public ISKFunction SetDefaultSkillCollection(IReadOnlySkillCollection skills) => + this._plan.SetDefaultSkillCollection(skills); + + #region private ================================================================================ + + private readonly IPlan _plan; + private readonly ILogger _logger; + + /// + /// Instance of for plan-related metrics. + /// + private static Meter s_meter = new(typeof(Plan).FullName); + + /// + /// Instance of to measure and track the time of plan execution. + /// + private static Histogram s_executionTimeHistogram = + s_meter.CreateHistogram( + name: "SK.Plan.Execution.ExecutionTime", + unit: "ms", + description: "Duration of plan execution"); + + /// + /// Instance of to keep track of the total number of plan executions. + /// + private static Counter s_executionTotalCounter = + s_meter.CreateCounter( + name: "SK.Plan.Execution.ExecutionTotal", + description: "Total number of plan executions"); + + /// + /// Instance of to keep track of the number of successful plan executions. + /// + private static Counter s_executionSuccessCounter = + s_meter.CreateCounter( + name: "SK.Plan.Execution.ExecutionSuccess", + description: "Number of successful plan executions"); + + /// + /// Instance of to keep track of the number of failed plan executions. + /// + private static Counter s_executionFailureCounter = + s_meter.CreateCounter( + name: "SK.Plan.Execution.ExecutionFailure", + description: "Number of failed plan executions"); + + /// + /// Wrapper for instrumentation to be used in multiple invocation places. + /// + /// Delegate to instrument. + private async Task InvokeWithInstrumentationAsync(Func> func) + { + this._logger.LogInformation("Plan execution started."); + + var stopwatch = new Stopwatch(); + + stopwatch.Start(); + + var result = await func().ConfigureAwait(false); + + stopwatch.Stop(); + + if (result.ErrorOccurred) + { + this._logger.LogWarning("Plan execution status: {Status}", "Failed"); + this._logger.LogError(result.LastException, "Plan execution exception details: {Message}", result.LastErrorDescription); + + s_executionFailureCounter.Add(1); + } + else + { + this._logger.LogInformation("Plan execution status: {Status}", "Success"); + this._logger.LogInformation("Plan execution finished in {ExecutionTime}ms", stopwatch.ElapsedMilliseconds); + + s_executionSuccessCounter.Add(1); + } + + s_executionTotalCounter.Add(1); + s_executionTimeHistogram.Record(stopwatch.ElapsedMilliseconds); + + return result; + } + + #endregion +} diff --git a/dotnet/src/SemanticKernel/Planning/Plan.cs b/dotnet/src/SemanticKernel/Planning/Plan.cs index b3b5ee0337d2..32a7fea6b0c3 100644 --- a/dotnet/src/SemanticKernel/Planning/Plan.cs +++ b/dotnet/src/SemanticKernel/Planning/Plan.cs @@ -3,8 +3,6 @@ using System; using System.Collections.Generic; using System.Diagnostics; -using System.Diagnostics.Metrics; -using System.Globalization; using System.Linq; using System.Text.Json; using System.Text.Json.Serialization; @@ -23,7 +21,7 @@ namespace Microsoft.SemanticKernel.Planning; /// Plan is used to create trees of s. /// [DebuggerDisplay("{DebuggerDisplay,nq}")] -public sealed class Plan : ISKFunction +public sealed class Plan : IPlan { /// /// State of the plan @@ -328,7 +326,10 @@ public async Task InvokeAsync( { if (this.Function is not null) { - var result = await this.InstrumentedInvokeAsync(this.Function, context, settings, cancellationToken).ConfigureAwait(false); + var result = await this.Function + .WithInstrumentation(context.Logger) + .InvokeAsync(context, settings, cancellationToken) + .ConfigureAwait(false); if (result.ErrorOccurred) { @@ -584,58 +585,6 @@ private ContextVariables GetNextStepVariables(ContextVariables variables, Plan s return stepVariables; } - private async Task InstrumentedInvokeAsync( - ISKFunction function, - SKContext context, - CompleteRequestSettings? settings = null, - CancellationToken cancellationToken = default) - { - using var activity = s_activitySource.StartActivity($"{this.SkillName}.{this.Name}"); - - context.Logger.LogInformation("{SkillName}.{StepName}: Step execution started.", this.SkillName, this.Name); - - var stopwatch = new Stopwatch(); - - stopwatch.Start(); - - var result = await function.InvokeAsync(context, settings, cancellationToken).ConfigureAwait(false); - - stopwatch.Stop(); - - if (!result.ErrorOccurred) - { - context.Logger.LogInformation( - "{SkillName}.{StepName}: Step execution status: {Status}.", - this.SkillName, this.Name, "Success"); - } - else - { - context.Logger.LogInformation( - "{SkillName}.{StepName}: Step execution status: {Status}.", - this.SkillName, this.Name, "Failed"); - - context.Logger.LogError( - result.LastException, - "Something went wrong in plan step {SkillName}.{StepName}:'{ErrorDescription}'", - this.SkillName, this.Name, context.LastErrorDescription); - } - - context.Logger.LogInformation( - "{SkillName}.{StepName}: Step execution finished in {ExecutionTime}ms.", - this.SkillName, this.Name, stopwatch.ElapsedMilliseconds); - - var stepExecutionTimeMetricName = string.Format(CultureInfo.InvariantCulture, StepExecutionTimeMetricFormat, this.SkillName, this.Name); - - var stepExecutionTimeHistogram = s_meter.CreateHistogram( - name: stepExecutionTimeMetricName, - unit: "ms", - description: "Plan step execution time"); - - stepExecutionTimeHistogram.Record(stopwatch.ElapsedMilliseconds); - - return result; - } - private void SetFunction(ISKFunction function) { this.Function = function; @@ -674,20 +623,4 @@ private string DebuggerDisplay return display; } } - - #region Instrumentation - - private const string StepExecutionTimeMetricFormat = "SK.{0}.{1}.ExecutionTime"; - - /// - /// Instance of for plan-related activities. - /// - private static ActivitySource s_activitySource = new(typeof(Plan).FullName); - - /// - /// Instance of for planner-related metrics. - /// - private static Meter s_meter = new(typeof(Plan).FullName); - - #endregion } diff --git a/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs b/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs index c2b134577ae5..485a1a22e806 100644 --- a/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs +++ b/dotnet/src/SemanticKernel/Planning/PlanExtensions.cs @@ -1,6 +1,7 @@ // Copyright (c) Microsoft. All rights reserved. using System.Linq; +using Microsoft.Extensions.Logging; namespace Microsoft.SemanticKernel.Planning; @@ -66,4 +67,14 @@ public static string ToPlanString(this Plan plan, string indent = " ") return planString; } + + /// + /// Returns decorated instance of with enabled instrumentation. + /// + /// Instance of to decorate. + /// Optional logger. + public static IPlan WithInstrumentation(this IPlan plan, ILogger? logger = null) + { + return new InstrumentedPlan(plan, logger); + } } diff --git a/dotnet/src/SemanticKernel/SkillDefinition/InstrumentedSKFunction.cs b/dotnet/src/SemanticKernel/SkillDefinition/InstrumentedSKFunction.cs new file mode 100644 index 000000000000..003e7a9e8614 --- /dev/null +++ b/dotnet/src/SemanticKernel/SkillDefinition/InstrumentedSKFunction.cs @@ -0,0 +1,183 @@ +// Copyright (c) Microsoft. All rights reserved. + +using System; +using System.Diagnostics; +using System.Diagnostics.Metrics; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.SemanticKernel.AI.TextCompletion; +using Microsoft.SemanticKernel.Orchestration; + +namespace Microsoft.SemanticKernel.SkillDefinition; + +/// +/// Standard Semantic Kernel callable function with instrumentation. +/// +public sealed class InstrumentedSKFunction : ISKFunction +{ + /// + public string Name => this._function.Name; + + /// + public string SkillName => this._function.SkillName; + + /// + public string Description => this._function.Description; + + /// + public bool IsSemantic => this._function.IsSemantic; + + /// + public CompleteRequestSettings RequestSettings => this._function.RequestSettings; + + /// + /// Initialize a new instance of the class. + /// + /// Instance of to decorate. + /// Optional logger. + public InstrumentedSKFunction( + ISKFunction function, + ILogger? logger = null) + { + this._function = function; + this._logger = logger ?? NullLogger.Instance; + + this._executionTimeHistogram = s_meter.CreateHistogram( + name: $"SK.{this.SkillName}.{this.Name}.ExecutionTime", + unit: "ms", + description: "Duration of function execution"); + + this._executionTotalCounter = s_meter.CreateCounter( + name: $"SK.{this.SkillName}.{this.Name}.ExecutionTotal", + description: "Total number of function executions"); + + this._executionSuccessCounter = s_meter.CreateCounter( + name: $"SK.{this.SkillName}.{this.Name}.ExecutionSuccess", + description: "Number of successful function executions"); + + this._executionFailureCounter = s_meter.CreateCounter( + name: $"SK.{this.SkillName}.{this.Name}.ExecutionFailure", + description: "Number of failed function executions"); + } + + /// + public FunctionView Describe() => + this._function.Describe(); + + /// + public async Task InvokeAsync( + SKContext context, + CompleteRequestSettings? settings = null, + CancellationToken cancellationToken = default) + { + return await this.InvokeWithInstrumentationAsync(() => + this._function.InvokeAsync(context, settings, cancellationToken)).ConfigureAwait(false); + } + + /// + public async Task InvokeAsync( + string? input = null, + CompleteRequestSettings? settings = null, + ILogger? logger = null, + CancellationToken cancellationToken = default) + { + return await this.InvokeWithInstrumentationAsync(() => + this._function.InvokeAsync(input, settings, logger ?? this._logger, cancellationToken)).ConfigureAwait(false); + } + + /// + public ISKFunction SetAIConfiguration(CompleteRequestSettings settings) => + this._function.SetAIConfiguration(settings); + + /// + public ISKFunction SetAIService(Func serviceFactory) => + this._function.SetAIService(serviceFactory); + + /// + public ISKFunction SetDefaultSkillCollection(IReadOnlySkillCollection skills) => + this._function.SetDefaultSkillCollection(skills); + + #region private ================================================================================ + + private readonly ISKFunction _function; + private readonly ILogger _logger; + + /// + /// Instance of for function-related activities. + /// + private static ActivitySource s_activitySource = new(typeof(SKFunction).FullName); + + /// + /// Instance of for function-related metrics. + /// + private static Meter s_meter = new(typeof(SKFunction).FullName); + + /// + /// Instance of to measure and track the time of function execution. + /// + private Histogram _executionTimeHistogram; + + /// + /// Instance of to keep track of the total number of function executions. + /// + private Counter _executionTotalCounter; + + /// + /// Instance of to keep track of the number of successful function executions. + /// + private Counter _executionSuccessCounter; + + /// + /// Instance of to keep track of the number of failed function executions. + /// + private Counter _executionFailureCounter; + + /// + /// Wrapper for instrumentation to be used in multiple invocation places. + /// + /// Delegate to instrument. + private async Task InvokeWithInstrumentationAsync(Func> func) + { + using var activity = s_activitySource.StartActivity($"{this.SkillName}.{this.Name}"); + + this._logger.LogInformation("{SkillName}.{FunctionName}: Function execution started.", this.SkillName, this.Name); + + var stopwatch = new Stopwatch(); + + stopwatch.Start(); + + var result = await func().ConfigureAwait(false); + + stopwatch.Stop(); + + if (result.ErrorOccurred) + { + this._logger.LogWarning("{SkillName}.{FunctionName}: Function execution status: {Status}", + this.SkillName, this.Name, "Failed"); + + this._logger.LogError(result.LastException, "{SkillName}.{FunctionName}: Function execution exception details: {Message}", + this.SkillName, this.Name, result.LastErrorDescription); + + this._executionFailureCounter.Add(1); + } + else + { + this._logger.LogInformation("{SkillName}.{FunctionName}: Function execution status: {Status}", + this.SkillName, this.Name, "Success"); + + this._logger.LogInformation("{SkillName}.{FunctionName}: Function execution finished in {ExecutionTime}ms", + this.SkillName, this.Name, stopwatch.ElapsedMilliseconds); + + this._executionSuccessCounter.Add(1); + } + + this._executionTotalCounter.Add(1); + this._executionTimeHistogram.Record(stopwatch.ElapsedMilliseconds); + + return result; + } + + #endregion +} diff --git a/dotnet/src/SemanticKernel/SkillDefinition/SKFunctionExtensions.cs b/dotnet/src/SemanticKernel/SkillDefinition/SKFunctionExtensions.cs index 83643bc56385..2b3577d1a1a5 100644 --- a/dotnet/src/SemanticKernel/SkillDefinition/SKFunctionExtensions.cs +++ b/dotnet/src/SemanticKernel/SkillDefinition/SKFunctionExtensions.cs @@ -135,4 +135,14 @@ public static Task InvokeAsync(this ISKFunction function, context.Variables.Update(input); return function.InvokeAsync(context, settings); } + + /// + /// Returns decorated instance of with enabled instrumentation. + /// + /// Instance of to decorate. + /// Optional logger. + public static ISKFunction WithInstrumentation(this ISKFunction function, ILogger? logger = null) + { + return new InstrumentedSKFunction(function, logger); + } }