.Net: More telemetry for Sequential, Action and Stepwise planners (#2156

)

### 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.
-->

This is follow-up PR to the previous one regarding telemetry:
#1905

### Description

<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->
1. Added small improvements in instrumentation for `SequentialPlanner`.
2. Added instrumentation for `ActionPlanner`.
3. Added instrumentation for `StepwisePlanner`.
4. Updated log levels in `StepwisePlanner` to disable sensitive data by
default.

### 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 😄

---------

Co-authored-by: Shawn Callegari <36091529+shawncal@users.noreply.github.com>

dotnet/samples/ApplicationInsightsExample/ApplicationInsightsExample.csproj

@@ -20,8 +20,13 @@
 
   <ItemGroup>
     <ProjectReference Include="..\..\src\Extensions\Planning.SequentialPlanner\Planning.SequentialPlanner.csproj" />
+    <ProjectReference Include="..\..\src\Extensions\Planning.ActionPlanner\Planning.ActionPlanner.csproj" />
+    <ProjectReference Include="..\..\src\Extensions\Planning.StepwisePlanner\Planning.StepwisePlanner.csproj" />
     <ProjectReference Include="..\..\src\Connectors\Connectors.AI.OpenAI\Connectors.AI.OpenAI.csproj" />
     <ProjectReference Include="..\..\src\SemanticKernel\SemanticKernel.csproj" />
+    <ProjectReference Include="..\..\src\Skills\Skills.Core\Skills.Core.csproj" />
+    <ProjectReference Include="..\..\src\Skills\Skills.Web\Skills.Web.csproj" />
+    <ProjectReference Include="..\NCalcSkills\NCalcSkills.csproj" />
   </ItemGroup>
 
 </Project>

dotnet/samples/ApplicationInsightsExample/Program.cs

@@ -13,7 +13,13 @@
 using Microsoft.Extensions.Logging.ApplicationInsights;
 using Microsoft.SemanticKernel;
 using Microsoft.SemanticKernel.Planning;
+using Microsoft.SemanticKernel.Planning.Action;
 using Microsoft.SemanticKernel.Planning.Sequential;
+using Microsoft.SemanticKernel.Planning.Stepwise;
+using Microsoft.SemanticKernel.Skills.Core;
+using Microsoft.SemanticKernel.Skills.Web;
+using Microsoft.SemanticKernel.Skills.Web.Bing;
+using NCalcSkills;
 
 /// <summary>
 /// Example of telemetry in Semantic Kernel using Application Insights within console application.
@@ -43,7 +49,7 @@ public static async Task Main()
         ConfigureTracing(activityListener, telemetryClient);
 
         var kernel = GetKernel(logger);
-        var planner = GetPlanner(kernel, logger);
+        var planner = GetSequentialPlanner(kernel, logger);
 
         try
         {
@@ -98,7 +104,9 @@ private static void ConfigureApplicationInsightsTelemetry(ServiceCollection serv
 
     private static IKernel GetKernel(ILogger logger)
     {
-        string folder = RepoFiles.SampleSkillsPath();
+        var folder = RepoFiles.SampleSkillsPath();
+        var bingConnector = new BingConnector(Env.Var("Bing__ApiKey"));
+        var webSearchEngineSkill = new WebSearchEngineSkill(bingConnector);
 
         var kernel = new KernelBuilder()
             .WithLogger(logger)
@@ -110,10 +118,14 @@ private static IKernel GetKernel(ILogger logger)
 
         kernel.ImportSemanticSkillFromDirectory(folder, "SummarizeSkill", "WriterSkill");
 
+        kernel.ImportSkill(webSearchEngineSkill, "WebSearch");
+        kernel.ImportSkill(new LanguageCalculatorSkill(kernel), "advancedCalculator");
+        kernel.ImportSkill(new TimeSkill(), "time");
+
         return kernel;
     }
 
-    private static ISequentialPlanner GetPlanner(
+    private static ISequentialPlanner GetSequentialPlanner(
         IKernel kernel,
         ILogger logger,
         int maxTokens = 1024)
@@ -123,6 +135,28 @@ private static ISequentialPlanner GetPlanner(
         return new SequentialPlanner(kernel, plannerConfig).WithInstrumentation(logger);
     }
 
+    private static IActionPlanner GetActionPlanner(
+        IKernel kernel,
+        ILogger logger)
+    {
+        return new ActionPlanner(kernel).WithInstrumentation(logger);
+    }
+
+    private static IStepwisePlanner GetStepwisePlanner(
+        IKernel kernel,
+        ILogger logger,
+        int minIterationTimeMs = 1500,
+        int maxTokens = 2000)
+    {
+        var plannerConfig = new StepwisePlannerConfig
+        {
+            MinIterationTimeMs = minIterationTimeMs,
+            MaxTokens = maxTokens
+        };
+
+        return new StepwisePlanner(kernel, plannerConfig).WithInstrumentation(logger);
+    }
+
     /// <summary>
     /// Example of metering configuration in Application Insights
     /// using <see cref="MeterListener"/> to attach for <see cref="Meter"/> recordings.

dotnet/src/Extensions/Planning.ActionPlanner/ActionPlanner.cs

@@ -30,7 +30,7 @@ namespace Microsoft.SemanticKernel.Planning;
 /// The rationale is currently available only in the prompt, we might include it in
 /// the Plan object in future.
 /// </summary>
-public sealed class ActionPlanner
+public sealed class ActionPlanner : IActionPlanner
 {
     private const string StopSequence = "#END-OF-PLAN";
     private const string SkillName = "this";
@@ -78,6 +78,7 @@ public ActionPlanner(
         this._context = kernel.CreateNewContext();
     }
 
+    /// <inheritdoc />
     public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
     {
         if (string.IsNullOrEmpty(goal))

dotnet/src/Extensions/Planning.ActionPlanner/ActionPlannerExtensions.cs

@@ -0,0 +1,21 @@
+// Copyright (c) Microsoft. All rights reserved.
+
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.SemanticKernel.Planning.Action;
+
+/// <summary>
+/// Extension methods for <see cref="ActionPlanner"/> class.
+/// </summary>
+public static class ActionPlannerExtensions
+{
+    /// <summary>
+    /// Returns decorated instance of <see cref="IActionPlanner"/> with enabled instrumentation.
+    /// </summary>
+    /// <param name="planner">Instance of <see cref="IActionPlanner"/> to decorate.</param>
+    /// <param name="logger">Optional logger.</param>
+    public static IActionPlanner WithInstrumentation(this IActionPlanner planner, ILogger? logger = null)
+    {
+        return new InstrumentedActionPlanner(planner, logger);
+    }
+}

dotnet/src/Extensions/Planning.ActionPlanner/IActionPlanner.cs

@@ -0,0 +1,21 @@
+// Copyright (c) Microsoft. All rights reserved.
+
+using System.Threading;
+using System.Threading.Tasks;
+
+namespace Microsoft.SemanticKernel.Planning.Action;
+
+/// <summary>
+/// Interface for planner that uses a set of semantic functions to select one function out of many and create a plan.
+/// </summary>
+public interface IActionPlanner
+{
+    /// <summary>
+    /// Create a plan for a goal.
+    /// </summary>
+    /// <param name="goal">The goal to create a plan for.</param>
+    /// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
+    /// <returns>The plan.</returns>
+    /// <exception cref="PlanningException">Thrown when the plan cannot be created.</exception>
+    Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default);
+}

dotnet/src/Extensions/Planning.ActionPlanner/InstrumentedActionPlanner.cs

@@ -0,0 +1,103 @@
+// 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;
+
+namespace Microsoft.SemanticKernel.Planning.Action;
+
+/// <summary>
+/// Instrumented planner that uses set of semantic functions to select one function out of many and create a plan.
+/// Captures planner-related logs and metrics.
+/// </summary>
+public class InstrumentedActionPlanner : IActionPlanner
+{
+    /// <summary>
+    /// Initialize a new instance of the <see cref="InstrumentedActionPlanner"/> class.
+    /// </summary>
+    /// <param name="planner">Instance of <see cref="IActionPlanner"/> to decorate.</param>
+    /// <param name="logger">Optional logger.</param>
+    public InstrumentedActionPlanner(
+        IActionPlanner planner,
+        ILogger? logger = null)
+    {
+        this._planner = planner;
+        this._logger = logger ?? NullLogger.Instance;
+    }
+
+    /// <inheritdoc />
+    public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
+    {
+        using var activity = s_activitySource.StartActivity($"{PlannerType}.CreatePlan");
+
+        this._logger.LogInformation("{PlannerType}: Plan creation started.", PlannerType);
+
+        // Sensitive data, logging as trace, disabled by default
+        this._logger.LogTrace("{PlannerType}: Plan Goal: {Goal}", PlannerType, goal);
+
+        var stopwatch = new Stopwatch();
+
+        try
+        {
+            stopwatch.Start();
+
+            var plan = await this._planner.CreatePlanAsync(goal, cancellationToken).ConfigureAwait(false);
+
+            stopwatch.Stop();
+
+            this._logger.LogInformation("{PlannerType}: Plan creation status: {Status}", PlannerType, "Success");
+
+            this._logger.LogInformation("{PlannerType}: Created plan: \n {Plan}", PlannerType, plan.ToSafePlanString());
+
+            // Sensitive data, logging as trace, disabled by default
+            this._logger.LogTrace("{PlannerType}: Created plan with details: \n {Plan}", PlannerType, plan.ToPlanString());
+
+            return plan;
+        }
+        catch (Exception ex)
+        {
+            this._logger.LogInformation("{PlannerType}: Plan creation status: {Status}", PlannerType, "Failed");
+            this._logger.LogError(ex, "{PlannerType}: Plan creation exception details: {Message}", PlannerType, ex.Message);
+
+            throw;
+        }
+        finally
+        {
+            this._logger.LogInformation("{PlannerType}: Plan creation finished in {ExecutionTime}ms.", PlannerType, stopwatch.ElapsedMilliseconds);
+
+            s_createPlanExecutionTime.Record(stopwatch.ElapsedMilliseconds);
+        }
+    }
+
+    #region private ================================================================================
+
+    private const string PlannerType = nameof(ActionPlanner);
+
+    private readonly IActionPlanner _planner;
+    private readonly ILogger _logger;
+
+    /// <summary>
+    /// Instance of <see cref="ActivitySource"/> for planner-related activities.
+    /// </summary>
+    private static ActivitySource s_activitySource = new(typeof(InstrumentedActionPlanner).FullName);
+
+    /// <summary>
+    /// Instance of <see cref="Meter"/> for planner-related metrics.
+    /// </summary>
+    private static Meter s_meter = new(typeof(InstrumentedActionPlanner).FullName);
+
+    /// <summary>
+    /// Instance of <see cref="Histogram{T}"/> to record plan creation execution time.
+    /// </summary>
+    private static Histogram<double> s_createPlanExecutionTime =
+        s_meter.CreateHistogram<double>(
+            name: $"SK.{PlannerType}.CreatePlan.ExecutionTime",
+            unit: "ms",
+            description: "Execution time of plan creation");
+
+    #endregion
+}

dotnet/src/Extensions/Planning.SequentialPlanner/ISequentialPlanner.cs

@@ -6,7 +6,7 @@
 namespace Microsoft.SemanticKernel.Planning.Sequential;
 
 /// <summary>
-/// Interface for planner that uses semantic function to create a sequential plan.
+/// Interface for planner that uses a set of semantic functions to create a sequential plan.
 /// </summary>
 public interface ISequentialPlanner
 {

dotnet/src/Extensions/Planning.SequentialPlanner/InstrumentedSequentialPlanner.cs

@@ -32,12 +32,12 @@ public InstrumentedSequentialPlanner(
     /// <inheritdoc />
     public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
     {
-        using var activity = s_activitySource.StartActivity("SequentialPlanner.CreatePlan");
+        using var activity = s_activitySource.StartActivity($"{PlannerType}.CreatePlan");
 
-        this._logger.LogInformation("Plan creation started.");
+        this._logger.LogInformation("{PlannerType}: Plan creation started.", PlannerType);
 
         // Sensitive data, logging as trace, disabled by default
-        this._logger.LogTrace("Plan Goal: {Goal}", goal);
+        this._logger.LogTrace("{PlannerType}: Plan Goal: {Goal}", PlannerType, goal);
 
         var stopwatch = new Stopwatch();
 
@@ -49,32 +49,34 @@ public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellat
 
             stopwatch.Stop();
 
-            this._logger.LogInformation("Plan creation status: {Status}", "Success");
+            this._logger.LogInformation("{PlannerType}: Plan creation status: {Status}", PlannerType, "Success");
 
-            this._logger.LogInformation("Created plan: \n {Plan}", plan.ToSafePlanString());
+            this._logger.LogInformation("{PlannerType}: Created plan: \n {Plan}", PlannerType, plan.ToSafePlanString());
 
             // Sensitive data, logging as trace, disabled by default
-            this._logger.LogTrace("Created plan with details: \n {Plan}", plan.ToPlanString());
+            this._logger.LogTrace("{PlannerType}: Created plan with details: \n {Plan}", PlannerType, plan.ToPlanString());
 
             return plan;
         }
         catch (Exception ex)
         {
-            this._logger.LogInformation("Plan creation status: {Status}", "Failed");
-            this._logger.LogError(ex, "Plan creation exception details: {Message}", ex.Message);
+            this._logger.LogInformation("{PlannerType}: Plan creation status: {Status}", PlannerType, "Failed");
+            this._logger.LogError(ex, "{PlannerType}: Plan creation exception details: {Message}", PlannerType, ex.Message);
 
             throw;
         }
         finally
         {
-            this._logger.LogInformation("Plan creation finished in {ExecutionTime}ms.", stopwatch.ElapsedMilliseconds);
+            this._logger.LogInformation("{PlannerType}: Plan creation finished in {ExecutionTime}ms.", PlannerType, stopwatch.ElapsedMilliseconds);
 
             s_createPlanExecutionTime.Record(stopwatch.ElapsedMilliseconds);
         }
     }
 
     #region private ================================================================================
 
+    private const string PlannerType = nameof(SequentialPlanner);
+
     private readonly ISequentialPlanner _planner;
     private readonly ILogger _logger;
 
@@ -93,7 +95,7 @@ public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellat
     /// </summary>
     private static Histogram<double> s_createPlanExecutionTime =
         s_meter.CreateHistogram<double>(
-            name: "SK.SequentialPlanner.CreatePlan.ExecutionTime",
+            name: $"SK.{PlannerType}.CreatePlan.ExecutionTime",
             unit: "ms",
             description: "Execution time of plan creation");
 

dotnet/src/Extensions/Planning.StepwisePlanner/IStepwisePlanner.cs

@@ -0,0 +1,17 @@
+// Copyright (c) Microsoft. All rights reserved.
+
+namespace Microsoft.SemanticKernel.Planning.Stepwise;
+
+/// <summary>
+/// Interface for planner that creates a Stepwise plan using Mrkl systems.
+/// </summary>
+public interface IStepwisePlanner
+{
+    /// <summary>
+    /// Create a plan for a goal.
+    /// </summary>
+    /// <param name="goal">The goal to create a plan for.</param>
+    /// <returns>The plan.</returns>
+    /// <exception cref="PlanningException">Thrown when the plan cannot be created.</exception>
+    Plan CreatePlan(string goal);
+}