.Net: Delete IPlanner and associated WithInstrumentation (microsoft#3601

) Not all planner have the same shape, and there's no current demonstrated need to use them interchangeably via an abstraction. IPlanner existed temporarily to provide a hook for WithInstrumentation, but it's not desirable. Instead, all the planners just get the instrumentation abilities built in. Contributes to microsoft#3490 Co-authored-by: Mark Wallace <[email protected]>
TaoChenOSU · Nov 22, 2023 · 5623544 · 5623544
1 parent 3add2b2
commit 5623544
Show file tree

Hide file tree

Showing 11 changed files with 180 additions and 181 deletions.
diff --git a/dotnet/samples/ApplicationInsightsExample/Program.cs b/dotnet/samples/ApplicationInsightsExample/Program.cs
@@ -51,7 +51,7 @@ public static async Task Main()
         ConfigureTracing(activityListener, telemetryClient);
 
         var kernel = GetKernel(loggerFactory);
-        var planner = GetSequentialPlanner(kernel, loggerFactory);
+        var planner = GetSequentialPlanner(kernel);
 
         try
         {
@@ -128,26 +128,23 @@ private static Kernel GetKernel(ILoggerFactory loggerFactory)
         return kernel;
     }
 
-    private static IPlanner GetSequentialPlanner(
+    private static SequentialPlanner GetSequentialPlanner(
         Kernel kernel,
-        ILoggerFactory loggerFactory,
         int maxTokens = 1024)
     {
         var plannerConfig = new SequentialPlannerConfig { MaxTokens = maxTokens };
 
-        return new SequentialPlanner(kernel, plannerConfig).WithInstrumentation(loggerFactory);
+        return new SequentialPlanner(kernel, plannerConfig);
     }
 
-    private static IPlanner GetActionPlanner(
-        Kernel kernel,
-        ILoggerFactory loggerFactory)
+    private static ActionPlanner GetActionPlanner(
+        Kernel kernel)
     {
-        return new ActionPlanner(kernel).WithInstrumentation(loggerFactory);
+        return new ActionPlanner(kernel);
     }
 
-    private static IPlanner GetStepwisePlanner(
+    private static StepwisePlanner GetStepwisePlanner(
         Kernel kernel,
-        ILoggerFactory loggerFactory,
         int minIterationTimeMs = 1500,
         int maxTokens = 2000)
     {
@@ -157,7 +154,7 @@ private static IPlanner GetStepwisePlanner(
             MaxTokens = maxTokens
         };
 
-        return new StepwisePlanner(kernel, plannerConfig).WithInstrumentation(loggerFactory);
+        return new StepwisePlanner(kernel, plannerConfig);
     }
 
     /// <summary>

diff --git a/dotnet/samples/KernelSyntaxExamples/Example51_StepwisePlanner.cs b/dotnet/samples/KernelSyntaxExamples/Example51_StepwisePlanner.cs
@@ -139,7 +139,7 @@ private static async Task RunWithQuestionAsync(Kernel kernel, ExecutionResult cu
         try
         {
             StepwisePlanner planner = new(kernel: kernel, config: plannerConfig);
-            var plan = await planner.CreatePlanAsync(question);
+            var plan = planner.CreatePlan(question);
 
             var functionResult = await kernel.RunAsync(plan);
 

diff --git a/dotnet/src/IntegrationTests/Planners/StepwisePlanner/StepwisePlannerTests.cs b/dotnet/src/IntegrationTests/Planners/StepwisePlanner/StepwisePlannerTests.cs
@@ -45,7 +45,7 @@ public StepwisePlannerTests(ITestOutputHelper output)
     [Theory]
     [InlineData(false, "Who is the current president of the United States? What is his current age divided by 2", "ExecutePlan", "StepwisePlanner")]
     [InlineData(true, "Who is the current president of the United States? What is his current age divided by 2", "ExecutePlan", "StepwisePlanner")]
-    public async Task CanCreateStepwisePlanAsync(bool useChatModel, string prompt, string expectedFunction, string expectedPlugin)
+    public void CanCreateStepwisePlanAsync(bool useChatModel, string prompt, string expectedFunction, string expectedPlugin)
     {
         // Arrange
         bool useEmbeddings = false;
@@ -58,7 +58,7 @@ public async Task CanCreateStepwisePlanAsync(bool useChatModel, string prompt, s
         var planner = new StepwisePlanner(kernel, new() { MaxIterations = 10 });
 
         // Act
-        var plan = await planner.CreatePlanAsync(prompt);
+        var plan = planner.CreatePlan(prompt);
 
         // Assert
         Assert.Empty(plan.Steps);
@@ -84,7 +84,7 @@ public async Task CanExecuteStepwisePlanAsync(bool useChatModel, string prompt,
         var planner = new StepwisePlanner(kernel, new() { MaxIterations = 10 });
 
         // Act
-        var plan = await planner.CreatePlanAsync(prompt);
+        var plan = planner.CreatePlan(prompt);
         var planResult = await plan.InvokeAsync(kernel);
         var result = planResult.GetValue<string>();
 
@@ -113,7 +113,7 @@ public async Task ExecutePlanFailsWithTooManyFunctionsAsync()
         var planner = new StepwisePlanner(kernel, new() { MaxTokens = 1000 });
 
         // Act
-        var plan = await planner.CreatePlanAsync("I need to buy a new brush for my cat. Can you show me options?");
+        var plan = planner.CreatePlan("I need to buy a new brush for my cat. Can you show me options?");
 
         // Assert
         var ex = await Assert.ThrowsAsync<SKException>(async () => await kernel.RunAsync(plan));
@@ -131,7 +131,7 @@ public async Task ExecutePlanSucceedsWithAlmostTooManyFunctionsAsync()
         var planner = new StepwisePlanner(kernel);
 
         // Act
-        var plan = await planner.CreatePlanAsync("I need to buy a new brush for my cat. Can you show me options?");
+        var plan = planner.CreatePlan("I need to buy a new brush for my cat. Can you show me options?");
         var functionResult = await kernel.RunAsync(plan);
         var result = functionResult.GetValue<string>();
 

diff --git a/dotnet/src/Planners/Planners.Core/Action/ActionPlanner.cs b/dotnet/src/Planners/Planners.Core/Action/ActionPlanner.cs
@@ -28,7 +28,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 : IPlanner
+public sealed class ActionPlanner
 {
     private const string StopSequence = "#END-OF-PLAN";
     private const string PluginName = "this";
@@ -92,11 +92,25 @@ public ActionPlanner(
         this._logger = this._kernel.LoggerFactory.CreateLogger(this.GetType());
     }
 
-    /// <inheritdoc />
-    public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
+    /// <summary>Creates a plan for the specified goal.</summary>
+    /// <param name="goal">The goal for which a plan should be created.</param>
+    /// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
+    /// <returns>The created plan.</returns>
+    /// <exception cref="ArgumentNullException"><paramref name="goal"/> is null.</exception>
+    /// <exception cref="ArgumentException"><paramref name="goal"/> is empty or entirely composed of whitespace.</exception>
+    /// <exception cref="SKException">A plan could not be created.</exception>
+    public Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
     {
         Verify.NotNullOrWhiteSpace(goal);
 
+        return PlannerInstrumentation.CreatePlanAsync(
+            static (ActionPlanner planner, string goal, CancellationToken cancellationToken) => planner.CreatePlanCoreAsync(goal, cancellationToken),
+            static (Plan plan) => plan.ToSafePlanString(),
+            this, goal, this._logger, cancellationToken);
+    }
+
+    private async Task<Plan> CreatePlanCoreAsync(string goal, CancellationToken cancellationToken)
+    {
         this._context.Variables.Update(goal);
 
         FunctionResult result = await this._plannerFunction.InvokeAsync(this._kernel, this._context, cancellationToken: cancellationToken).ConfigureAwait(false);

diff --git a/dotnet/src/Planners/Planners.Core/Handlebars/HandlebarsPlanner.cs b/dotnet/src/Planners/Planners.Core/Handlebars/HandlebarsPlanner.cs
@@ -7,6 +7,7 @@
 using System.Text.RegularExpressions;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 using Microsoft.SemanticKernel.AI.ChatCompletion;
 
 namespace Microsoft.SemanticKernel.Planning.Handlebars;
@@ -27,6 +28,7 @@ public sealed class HandlebarsPlanner
     public Stopwatch Stopwatch { get; } = new();
 
     private readonly Kernel _kernel;
+    private readonly ILogger _logger;
 
     private readonly HandlebarsPlannerConfig _config;
 
@@ -41,16 +43,27 @@ public HandlebarsPlanner(Kernel kernel, HandlebarsPlannerConfig? config = defaul
     {
         this._kernel = kernel;
         this._config = config ?? new HandlebarsPlannerConfig();
+        this._logger = kernel.LoggerFactory.CreateLogger(this.GetType());
     }
 
-    /// <summary>
-    /// Create a plan for a goal.
-    /// </summary>
-    /// <param name="goal">The goal to create a plan for.</param>
+    /// <summary>Creates a plan for the specified goal.</summary>
+    /// <param name="goal">The goal for which a plan should be created.</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="SKException">Thrown when the plan cannot be created.</exception>
-    public async Task<HandlebarsPlan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
+    /// <returns>The created plan.</returns>
+    /// <exception cref="ArgumentNullException"><paramref name="goal"/> is null.</exception>
+    /// <exception cref="ArgumentException"><paramref name="goal"/> is empty or entirely composed of whitespace.</exception>
+    /// <exception cref="SKException">A plan could not be created.</exception>
+    public Task<HandlebarsPlan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
+    {
+        Verify.NotNullOrWhiteSpace(goal);
+
+        return PlannerInstrumentation.CreatePlanAsync(
+            createPlanAsync: static (HandlebarsPlanner planner, string goal, CancellationToken cancellationToken) => planner.CreatePlanCoreAsync(goal, cancellationToken),
+            planToString: static (HandlebarsPlan plan) => plan.ToString(),
+            this, goal, this._logger, cancellationToken);
+    }
+
+    private async Task<HandlebarsPlan> CreatePlanCoreAsync(string goal, CancellationToken cancellationToken = default)
     {
         var availableFunctions = this.GetAvailableFunctionsManual(cancellationToken);
         var handlebarsTemplate = this.GetHandlebarsTemplate(this._kernel, goal, availableFunctions);

diff --git a/dotnet/src/Planners/Planners.Core/PlannerInstrumentation.cs b/dotnet/src/Planners/Planners.Core/PlannerInstrumentation.cs
@@ -0,0 +1,77 @@
+// 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;
+
+#pragma warning disable IDE0130
+// ReSharper disable once CheckNamespace - using planners namespace
+namespace Microsoft.SemanticKernel.Planning;
+#pragma warning restore IDE0130
+
+/// <summary>Surrounds the invocation of a planner with logging and metrics.</summary>
+internal static class PlannerInstrumentation
+{
+    /// <summary><see cref="ActivitySource"/> for planning-related activities.</summary>
+    private static readonly ActivitySource s_activitySource = new("Microsoft.SemanticKernel.Planning");
+
+    /// <summary><see cref="Meter"/> for planner-related metrics.</summary>
+    private static readonly Meter s_meter = new("Microsoft.SemanticKernel.Planning");
+
+    /// <summary><see cref="Histogram{T}"/> to record plan creation duration.</summary>
+    private static readonly Histogram<double> s_createPlanDuration = s_meter.CreateHistogram<double>(
+        name: "sk.planning.create_plan.duration",
+        unit: "s",
+        description: "Duration time of plan creation.");
+
+    /// <summary>Invokes the supplied <paramref name="createPlanAsync"/> delegate, surrounded by logging and metrics.</summary>
+    internal static async Task<TPlan> CreatePlanAsync<TPlanner, TPlan>(
+        Func<TPlanner, string, CancellationToken, Task<TPlan>> createPlanAsync,
+        Func<TPlan, string> planToString,
+        TPlanner planner, string goal, ILogger logger, CancellationToken cancellationToken)
+        where TPlanner : class
+        where TPlan : class
+    {
+        string plannerName = planner.GetType().FullName;
+
+        using var _ = s_activitySource.StartActivity(plannerName);
+
+        if (logger.IsEnabled(LogLevel.Trace))
+        {
+            logger.LogTrace("Plan creation started. Goal: {Goal}", goal); // Sensitive data, logging as trace, disabled by default
+        }
+        else if (logger.IsEnabled(LogLevel.Information))
+        {
+            logger.LogInformation("Plan creation started.");
+        }
+
+        TagList tags = new() { { "sk.planner.name", plannerName } };
+        long startingTimestamp = Stopwatch.GetTimestamp();
+        try
+        {
+            var plan = await createPlanAsync(planner, goal, cancellationToken).ConfigureAwait(false);
+
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                logger.LogInformation("Plan created. Plan:\n{Plan}", planToString(plan));
+            }
+
+            return plan;
+        }
+        catch (Exception ex)
+        {
+            logger.LogError(ex, "Plan creation failed. Error: {Message}", ex.Message);
+            tags.Add("error.type", ex.GetType().FullName);
+            throw;
+        }
+        finally
+        {
+            TimeSpan duration = new((long)((Stopwatch.GetTimestamp() - startingTimestamp) * (10_000_000.0 / Stopwatch.Frequency)));
+            logger.LogInformation("Plan creation duration: {Duration}ms.", duration.TotalMilliseconds);
+            s_createPlanDuration.Record(duration.TotalSeconds, in tags);
+        }
+    }
+}
diff --git a/dotnet/src/Planners/Planners.Core/Sequential/SequentialPlanner.cs b/dotnet/src/Planners/Planners.Core/Sequential/SequentialPlanner.cs
@@ -1,7 +1,9 @@
 // Copyright (c) Microsoft. All rights reserved.
 
+using System;
 using System.Threading;
 using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
 using Microsoft.SemanticKernel.AI;
 using Microsoft.SemanticKernel.Orchestration;
 
@@ -13,7 +15,7 @@ namespace Microsoft.SemanticKernel.Planning;
 /// <summary>
 /// A planner that uses semantic function to create a sequential plan.
 /// </summary>
-public sealed class SequentialPlanner : IPlanner
+public sealed class SequentialPlanner
 {
     private const string StopSequence = "<!-- END -->";
     private const string AvailableFunctionsKey = "available_functions";
@@ -51,13 +53,28 @@ public SequentialPlanner(
             });
 
         this._kernel = kernel;
+        this._logger = this._kernel.LoggerFactory.CreateLogger(this.GetType());
     }
 
-    /// <inheritdoc />
-    public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
+    /// <summary>Creates a plan for the specified goal.</summary>
+    /// <param name="goal">The goal for which a plan should be created.</param>
+    /// <param name="cancellationToken">The <see cref="CancellationToken"/> to monitor for cancellation requests. The default is <see cref="CancellationToken.None"/>.</param>
+    /// <returns>The created plan.</returns>
+    /// <exception cref="ArgumentNullException"><paramref name="goal"/> is null.</exception>
+    /// <exception cref="ArgumentException"><paramref name="goal"/> is empty or entirely composed of whitespace.</exception>
+    /// <exception cref="SKException">A plan could not be created.</exception>
+    public Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellationToken = default)
     {
         Verify.NotNullOrWhiteSpace(goal);
 
+        return PlannerInstrumentation.CreatePlanAsync(
+            createPlanAsync: static (SequentialPlanner planner, string goal, CancellationToken cancellationToken) => planner.CreatePlanCoreAsync(goal, cancellationToken),
+            planToString: static (Plan plan) => plan.ToSafePlanString(),
+            this, goal, this._logger, cancellationToken);
+    }
+
+    private async Task<Plan> CreatePlanCoreAsync(string goal, CancellationToken cancellationToken)
+    {
         string relevantFunctionsManual = await this._kernel.Plugins.GetFunctionsManualAsync(this.Config, goal, null, cancellationToken).ConfigureAwait(false);
 
         ContextVariables vars = new(goal)
@@ -99,6 +116,7 @@ public async Task<Plan> CreatePlanAsync(string goal, CancellationToken cancellat
     private SequentialPlannerConfig Config { get; }
 
     private readonly Kernel _kernel;
+    private readonly ILogger _logger;
 
     /// <summary>
     /// the function flow semantic function, which takes a goal and creates an xml plan that can be executed