.Net: Telemetry improvements for Plan and SKFunction

dotnet/samples/ApplicationInsightsExample/Program.cs

@@ -174,14 +174,22 @@ private static void ConfigureMetering(MeterListener meterListener, TelemetryClie
             }
         };
 
-        MeasurementCallback<double> measurementCallback = (instrument, measurement, tags, state) =>
+        meterListener.SetMeasurementEventCallback(GetMeasurementCallback<int>(telemetryClient));
+        meterListener.SetMeasurementEventCallback(GetMeasurementCallback<double>(telemetryClient));
+
+        meterListener.Start();
+    }
+
+    /// <summary>
+    /// The callback which can be used to get measurement recording.
+    /// </summary>
+    /// <param name="telemetryClient">Instance of Application Insights <see cref="TelemetryClient"/>.</param>
+    private static MeasurementCallback<T> GetMeasurementCallback<T>(TelemetryClient telemetryClient) where T : struct
+    {
+        return (instrument, measurement, tags, state) =>
         {
             telemetryClient.GetMetric(instrument.Name).TrackValue(measurement);
         };
-
-        meterListener.SetMeasurementEventCallback(measurementCallback);
-
-        meterListener.Start();
     }
 
     /// <summary>

dotnet/src/SemanticKernel/Planning/IPlan.cs

@@ -0,0 +1,12 @@
+// Copyright (c) Microsoft. All rights reserved.
+
+using Microsoft.SemanticKernel.SkillDefinition;
+
+namespace Microsoft.SemanticKernel.Planning;
+
+/// <summary>
+/// Interface for standard Semantic Kernel callable plan.
+/// </summary>
+public interface IPlan : ISKFunction
+{
+}

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;
+
+/// <summary>
+/// Standard Semantic Kernel callable plan with instrumentation.
+/// </summary>
+public sealed class InstrumentedPlan : IPlan
+{
+    /// <inheritdoc/>
+    public string Name => this._plan.Name;
+
+    /// <inheritdoc/>
+    public string SkillName => this._plan.SkillName;
+
+    /// <inheritdoc/>
+    public string Description => this._plan.Description;
+
+    /// <inheritdoc/>
+    public bool IsSemantic => this._plan.IsSemantic;
+
+    /// <inheritdoc/>
+    public CompleteRequestSettings RequestSettings => this._plan.RequestSettings;
+
+    /// <summary>
+    /// Initialize a new instance of the <see cref="InstrumentedPlan"/> class.
+    /// </summary>
+    /// <param name="plan">Instance of <see cref="IPlan"/> to decorate.</param>
+    /// <param name="logger">Optional logger.</param>
+    public InstrumentedPlan(
+        IPlan plan,
+        ILogger? logger = null)
+    {
+        this._plan = plan;
+        this._logger = logger ?? NullLogger.Instance;
+    }
+
+    /// <inheritdoc/>
+    public FunctionView Describe()
+    {
+        return this._plan.Describe();
+    }
+
+    /// <inheritdoc/>
+    public async Task<SKContext> InvokeAsync(
+        SKContext context,
+        CompleteRequestSettings? settings = null,
+        CancellationToken cancellationToken = default)
+    {
+        return await this.InvokeWithInstrumentationAsync(() =>
+            this._plan.InvokeAsync(context, settings, cancellationToken)).ConfigureAwait(false);
+    }
+
+    /// <inheritdoc/>
+    public async Task<SKContext> 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);
+    }
+
+    /// <inheritdoc/>
+    public ISKFunction SetAIConfiguration(CompleteRequestSettings settings) =>
+        this._plan.SetAIConfiguration(settings);
+
+    /// <inheritdoc/>
+    public ISKFunction SetAIService(Func<ITextCompletion> serviceFactory) =>
+        this._plan.SetAIService(serviceFactory);
+
+    /// <inheritdoc/>
+    public ISKFunction SetDefaultSkillCollection(IReadOnlySkillCollection skills) =>
+        this._plan.SetDefaultSkillCollection(skills);
+
+    #region private ================================================================================
+
+    private readonly IPlan _plan;
+    private readonly ILogger _logger;
+
+    /// <summary>
+    /// Instance of <see cref="Meter"/> for plan-related metrics.
+    /// </summary>
+    private static Meter s_meter = new(typeof(Plan).FullName);
+
+    /// <summary>
+    /// Instance of <see cref="Histogram{T}"/> to measure and track the time of plan execution.
+    /// </summary>
+    private static Histogram<double> s_executionTimeHistogram =
+        s_meter.CreateHistogram<double>(
+            name: "SK.Plan.Execution.ExecutionTime",
+            unit: "ms",
+            description: "Duration of plan execution");
+
+    /// <summary>
+    /// Instance of <see cref="Counter{T}"/> to keep track of the total number of plan executions.
+    /// </summary>
+    private static Counter<int> s_executionTotalCounter =
+        s_meter.CreateCounter<int>(
+            name: "SK.Plan.Execution.ExecutionTotal",
+            description: "Total number of plan executions");
+
+    /// <summary>
+    /// Instance of <see cref="Counter{T}"/> to keep track of the number of successful plan executions.
+    /// </summary>
+    private static Counter<int> s_executionSuccessCounter =
+        s_meter.CreateCounter<int>(
+            name: "SK.Plan.Execution.ExecutionSuccess",
+            description: "Number of successful plan executions");
+
+    /// <summary>
+    /// Instance of <see cref="Counter{T}"/> to keep track of the number of failed plan executions.
+    /// </summary>
+    private static Counter<int> s_executionFailureCounter =
+        s_meter.CreateCounter<int>(
+            name: "SK.Plan.Execution.ExecutionFailure",
+            description: "Number of failed plan executions");
+
+    /// <summary>
+    /// Wrapper for instrumentation to be used in multiple invocation places.
+    /// </summary>
+    /// <param name="func">Delegate to instrument.</param>
+    private async Task<SKContext> InvokeWithInstrumentationAsync(Func<Task<SKContext>> 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
+}

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 <see cref="ISKFunction"/>s.
 /// </summary>
 [DebuggerDisplay("{DebuggerDisplay,nq}")]
-public sealed class Plan : ISKFunction
+public sealed class Plan : IPlan
 {
     /// <summary>
     /// State of the plan
@@ -328,7 +326,10 @@ public async Task<SKContext> 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<SKContext> 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<double>(
-            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";
-
-    /// <summary>
-    /// Instance of <see cref="ActivitySource"/> for plan-related activities.
-    /// </summary>
-    private static ActivitySource s_activitySource = new(typeof(Plan).FullName);
-
-    /// <summary>
-    /// Instance of <see cref="Meter"/> for planner-related metrics.
-    /// </summary>
-    private static Meter s_meter = new(typeof(Plan).FullName);
-
-    #endregion
 }

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;
     }
+
+    /// <summary>
+    /// Returns decorated instance of <see cref="IPlan"/> with enabled instrumentation.
+    /// </summary>
+    /// <param name="plan">Instance of <see cref="IPlan"/> to decorate.</param>
+    /// <param name="logger">Optional logger.</param>
+    public static IPlan WithInstrumentation(this IPlan plan, ILogger? logger = null)
+    {
+        return new InstrumentedPlan(plan, logger);
+    }
 }