diff --git a/dotnet/samples/ApplicationInsightsExample/Program.cs b/dotnet/samples/ApplicationInsightsExample/Program.cs index f77237a6a31b..272dbc7440cc 100644 --- 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); } /// diff --git a/dotnet/samples/KernelSyntaxExamples/Example51_StepwisePlanner.cs b/dotnet/samples/KernelSyntaxExamples/Example51_StepwisePlanner.cs index 8061a23bceaf..8ac7048e9b4f 100644 --- 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 index 349d740a0975..321a664f9d38 100644 --- 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(); @@ -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(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(); diff --git a/dotnet/src/Planners/Planners.Core/Action/ActionPlanner.cs b/dotnet/src/Planners/Planners.Core/Action/ActionPlanner.cs index f105ef2b5e21..cc9aedefae8e 100644 --- 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. /// -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()); } - /// - public async Task CreatePlanAsync(string goal, CancellationToken cancellationToken = default) + /// Creates a plan for the specified goal. + /// The goal for which a plan should be created. + /// The to monitor for cancellation requests. The default is . + /// The created plan. + /// is null. + /// is empty or entirely composed of whitespace. + /// A plan could not be created. + public Task 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 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 index ab366779e8a1..d9ef41d84dd3 100644 --- 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()); } - /// - /// Create a plan for a goal. - /// - /// The goal to create a plan for. + /// Creates a plan for the specified goal. + /// The goal for which a plan should be created. /// The to monitor for cancellation requests. The default is . - /// The plan. - /// Thrown when the plan cannot be created. - public async Task CreatePlanAsync(string goal, CancellationToken cancellationToken = default) + /// The created plan. + /// is null. + /// is empty or entirely composed of whitespace. + /// A plan could not be created. + public Task 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 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 new file mode 100644 index 000000000000..43fa2601cb96 --- /dev/null +++ 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 + +/// Surrounds the invocation of a planner with logging and metrics. +internal static class PlannerInstrumentation +{ + /// for planning-related activities. + private static readonly ActivitySource s_activitySource = new("Microsoft.SemanticKernel.Planning"); + + /// for planner-related metrics. + private static readonly Meter s_meter = new("Microsoft.SemanticKernel.Planning"); + + /// to record plan creation duration. + private static readonly Histogram s_createPlanDuration = s_meter.CreateHistogram( + name: "sk.planning.create_plan.duration", + unit: "s", + description: "Duration time of plan creation."); + + /// Invokes the supplied delegate, surrounded by logging and metrics. + internal static async Task CreatePlanAsync( + Func> createPlanAsync, + Func 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 index 715e754f5980..938fd9786536 100644 --- 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; /// /// A planner that uses semantic function to create a sequential plan. /// -public sealed class SequentialPlanner : IPlanner +public sealed class SequentialPlanner { private const string StopSequence = ""; private const string AvailableFunctionsKey = "available_functions"; @@ -51,13 +53,28 @@ public SequentialPlanner( }); this._kernel = kernel; + this._logger = this._kernel.LoggerFactory.CreateLogger(this.GetType()); } - /// - public async Task CreatePlanAsync(string goal, CancellationToken cancellationToken = default) + /// Creates a plan for the specified goal. + /// The goal for which a plan should be created. + /// The to monitor for cancellation requests. The default is . + /// The created plan. + /// is null. + /// is empty or entirely composed of whitespace. + /// A plan could not be created. + public Task 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 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 CreatePlanAsync(string goal, CancellationToken cancellat private SequentialPlannerConfig Config { get; } private readonly Kernel _kernel; + private readonly ILogger _logger; /// /// the function flow semantic function, which takes a goal and creates an xml plan that can be executed diff --git a/dotnet/src/Planners/Planners.Core/Stepwise/StepwisePlanner.cs b/dotnet/src/Planners/Planners.Core/Stepwise/StepwisePlanner.cs index 6f8a4efa81f9..860c13758b4e 100644 --- a/dotnet/src/Planners/Planners.Core/Stepwise/StepwisePlanner.cs +++ b/dotnet/src/Planners/Planners.Core/Stepwise/StepwisePlanner.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; using System.ComponentModel; +using System.Diagnostics; using System.Diagnostics.CodeAnalysis; using System.Globalization; using System.Linq; @@ -28,7 +29,7 @@ namespace Microsoft.SemanticKernel.Planning; /// /// An implementation of a Mrkl system as described in https://arxiv.org/pdf/2205.00445.pdf /// -public class StepwisePlanner : IPlanner +public class StepwisePlanner { /// /// Initialize a new instance of the class. @@ -67,22 +68,37 @@ public StepwisePlanner( this._logger = this._kernel.LoggerFactory.CreateLogger(this.GetType()); } - /// - public Task CreatePlanAsync(string goal, CancellationToken cancellationToken = default) + /// Creates a plan for the specified goal. + /// The goal for which a plan should be created. + /// The created plan. + /// is null. + /// is empty or entirely composed of whitespace. + /// A plan could not be created. + public Plan CreatePlan(string goal) { Verify.NotNullOrWhiteSpace(goal); - Plan plan = new(this._nativeFunctions["ExecutePlan"]); - plan.PluginName = RestrictedPluginName; - - plan.Parameters.Set("question", goal); - - plan.Outputs.Add("stepCount"); - plan.Outputs.Add("functionCount"); - plan.Outputs.Add("stepsTaken"); - plan.Outputs.Add("iterations"); - - return Task.FromResult(plan); + Task task = PlannerInstrumentation.CreatePlanAsync( + static (StepwisePlanner planner, string goal, CancellationToken _) => + { + Plan plan = new(planner._nativeFunctions["ExecutePlan"]) + { + PluginName = RestrictedPluginName, + Outputs = { "stepCount", "functionCount", "stepsTaken", "iterations" }, + }; + plan.Parameters.Set("question", goal); + return Task.FromResult(plan); + }, + static (Plan plan) => plan.ToSafePlanString(), + this, goal, this._logger, CancellationToken.None); + + // The instrumentation doesn't do any asynchronous work other than invoke the supplied callback, + // which we know will complete synchronously, so we can safely use GetResult without incurring + // blocking as the operation will have already completed by the time the call returns. + Debug.Assert(task.IsCompleted); +#pragma warning disable VSTHRD002 // Avoid problematic synchronous waits + return task.GetAwaiter().GetResult(); +#pragma warning restore VSTHRD002 } /// @@ -622,7 +638,7 @@ private static void AddExecutionStatsToContext(List stepsTaken, SKCo // Context used to access the list of functions in the kernel private readonly Kernel _kernel; - private readonly ILogger? _logger; + private readonly ILogger _logger; /// /// Planner native functions diff --git a/dotnet/src/SemanticKernel.Core/Planning/IPlanner.cs b/dotnet/src/SemanticKernel.Core/Planning/IPlanner.cs deleted file mode 100644 index 89184b36b4e2..000000000000 --- a/dotnet/src/SemanticKernel.Core/Planning/IPlanner.cs +++ /dev/null @@ -1,23 +0,0 @@ -// Copyright (c) Microsoft. All rights reserved. - -using System; -using System.Threading; -using System.Threading.Tasks; - -#pragma warning disable IDE0130 -// ReSharper disable once CheckNamespace - Using NS of Plan -namespace Microsoft.SemanticKernel.Planning; -#pragma warning restore IDE0130 - -/// Represents a planner that creates a plan to achieve a goal. -public interface IPlanner -{ - /// Creates a plan for the specified goal. - /// The goal for which a plan should be created. - /// The to monitor for cancellation requests. The default is . - /// The created plan. - /// is null. - /// is empty or entirely composed of whitespace. - /// A plan could not be created. - Task CreatePlanAsync(string goal, CancellationToken cancellationToken = default); -} diff --git a/dotnet/src/SemanticKernel.Core/Planning/InstrumentedPlanner.cs b/dotnet/src/SemanticKernel.Core/Planning/InstrumentedPlanner.cs deleted file mode 100644 index 8f276eb0b02e..000000000000 --- a/dotnet/src/SemanticKernel.Core/Planning/InstrumentedPlanner.cs +++ /dev/null @@ -1,92 +0,0 @@ -// 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; - -#pragma warning disable IDE0130 -// ReSharper disable once CheckNamespace - using planners namespace -namespace Microsoft.SemanticKernel.Planning; -#pragma warning restore IDE0130 - -/// Instrumented planner that surrounds the invocation of another planner with logging and metrics. -internal sealed class InstrumentedPlanner : IPlanner -{ - /// for planning-related activities. - private static readonly ActivitySource s_activitySource = new("Microsoft.SemanticKernel.Planning"); - - /// for planner-related metrics. - private static readonly Meter s_meter = new("Microsoft.SemanticKernel.Planning"); - - /// to record plan creation duration. - private static readonly Histogram s_createPlanDuration = s_meter.CreateHistogram( - name: "sk.planning.create_plan.duration", - unit: "s", - description: "Duration time of plan creation."); - - /// Wrapped planner instance. - private readonly IPlanner _planner; - - /// Logger to use for logging activities. - private readonly ILogger _logger; - - /// Creates a new instance of the class. - /// Instance of to decorate. - /// The to use for logging. If null, no logging will be performed. - public InstrumentedPlanner(IPlanner planner, ILoggerFactory? loggerFactory = null) - { - this._planner = planner; - this._logger = loggerFactory is not null ? loggerFactory.CreateLogger(planner.GetType()) : NullLogger.Instance; - } - - /// - async Task IPlanner.CreatePlanAsync(string goal, CancellationToken cancellationToken) - { - string plannerName = this._planner.GetType().FullName; - - using var _ = s_activitySource.StartActivity(plannerName); - - if (this._logger.IsEnabled(LogLevel.Trace)) - { - this._logger.LogTrace("Plan creation started. Goal: {Goal}", goal); // Sensitive data, logging as trace, disabled by default - } - else if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation("Plan creation started."); - } - - TagList tags = new() { { "sk.planner.name", plannerName } }; - long startingTimestamp = Stopwatch.GetTimestamp(); - try - { - var plan = await this._planner.CreatePlanAsync(goal, cancellationToken).ConfigureAwait(false); - - if (this._logger.IsEnabled(LogLevel.Trace)) - { - this._logger.LogTrace("Plan created:\n{Plan}", plan.ToPlanString()); // Sensitive data, logging as trace, disabled by default - } - else if (this._logger.IsEnabled(LogLevel.Information)) - { - this._logger.LogInformation("Plan created:\n{Plan}", plan.ToSafePlanString()); - } - - return plan; - } - catch (Exception ex) - { - this._logger.LogError(ex, "Plan creation failed: {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))); - this._logger.LogInformation("Plan creation duration: {Duration}ms.", duration.TotalMilliseconds); - s_createPlanDuration.Record(duration.TotalSeconds, in tags); - } - } -} diff --git a/dotnet/src/SemanticKernel.Core/Planning/PlannerExtensions.cs b/dotnet/src/SemanticKernel.Core/Planning/PlannerExtensions.cs deleted file mode 100644 index 2004f2992fbc..000000000000 --- a/dotnet/src/SemanticKernel.Core/Planning/PlannerExtensions.cs +++ /dev/null @@ -1,21 +0,0 @@ -// Copyright (c) Microsoft. All rights reserved. - -using Microsoft.Extensions.Logging; - -#pragma warning disable IDE0130 -// ReSharper disable once CheckNamespace - Using NS of Plan -namespace Microsoft.SemanticKernel.Planning; -#pragma warning restore IDE0130 - -/// Provides extension methods for instances. -public static class PlannerExtensions -{ - /// Gets an that surrounds the invocation of another planner with logging and metrics. - /// Instance of to decorate. - /// The to use for logging. If null, no additional logging will be performed. - public static IPlanner WithInstrumentation(this IPlanner planner, ILoggerFactory? loggerFactory = null) - { - Verify.NotNull(planner); - return planner as InstrumentedPlanner ?? new InstrumentedPlanner(planner, loggerFactory); - } -}