.Net: Telemetry improvements for Plan and SKFunction (#2180)

### Motivation and Context

<!-- Thank you for your contribution to the semantic-kernel repo!
Please help reviewers and future users, providing the following
information:
  1. Why is this change required?
  2. What problem does it solve?
  3. What scenario does it contribute to?
  4. If it fixes an open issue, please link to the issue here.
-->

Based on PR: #2152.
Should fix: #2151

This PR contains changes to move telemetry logic from `Plan` class to
separate class-decorator and add telemetry for `SKFunction` using
decorator pattern.

### Description

<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->

1. Added interface `IPlan` which inherits from `ISKFunction` to decouple
`Plan` and `SKFunction` instrumentation and future decorations.
2. Implemented `InstrumentedPlan` with telemetry for `InvokeAsync`
methods.
3. Implemented `InstrumentedSKFunction` with telemetry for `InvokeAsync`
methods.
4. Added extension methods to create instrumented instances of plans and
functions.
5. Added additional counters for Plan/Function to measure number of
total, successful and failed Plan/Function executions.

### Contribution Checklist

<!-- Before submitting this PR, please make sure: -->

- [x] The code builds clean without any errors or warnings
- [x] The PR follows the [SK Contribution
Guidelines](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md)
and the [pre-submission formatting
script](https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md#development-scripts)
raises no violations
- [x] All unit tests pass, and I have added new tests where possible
- [x] I didn't break anyone 😄

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);
+    }
 }