Skip to content

Commit 10e1998

Browse files
TaoChenOSUTaoChenOSU
authored
.Net: Establish pattern to use LoggerMessage attribute in KernelFunction and Instrumented Planner (microsoft#3859)
### 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. --> It has been recommended by folks from the OpenTelemetry team to use the `LoggerMessage` attribute to produce more optimized code. As we are improving observability for the kernel, it's also important that we achieve better observability with optimized performance. For more information, please refer to this link: https://learn.microsoft.com/en-us/dotnet/core/extensions/logger-message-generator ### Description <!-- Describe your changes, the overall approach, the underlying design. These notes will help understanding how your code works. Thanks! --> 1. Create a new extension for `KernelFunction` named `KernelFunctionLogExtensions` that contains methods to perform optimized logging. 2. Turn logging calls in `PlannerInstrumentation` to calls to source-generated logging code. Other parts of the kernel will also adopt `LoggerMessage` in the future. ### Contribution Checklist <!-- Before submitting this PR, please make sure: --> - [ ] The code builds clean without any errors or warnings - [ ] 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 - [ ] All unit tests pass, and I have added new tests where possible - [ ] I didn't break anyone 😄
1 parent 9ea33b5 commit 10e1998

File tree

4 files changed

+130
-42
lines changed

4 files changed

+130
-42
lines changed

‎dotnet/src/InternalUtilities/planning/PlannerInstrumentation.cs

+46-17
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@
1010
namespace Microsoft.SemanticKernel.Planning;
1111

1212
/// <summary>Surrounds the invocation of a planner with logging and metrics.</summary>
13-
internal static class PlannerInstrumentation
13+
internal static partial class PlannerInstrumentation
1414
{
1515
/// <summary><see cref="ActivitySource"/> for planning-related activities.</summary>
1616
private static readonly ActivitySource s_activitySource = new("Microsoft.SemanticKernel.Planning");
@@ -27,7 +27,6 @@ internal static class PlannerInstrumentation
2727
/// <summary>Invokes the supplied <paramref name="createPlanAsync"/> delegate, surrounded by logging and metrics.</summary>
2828
public static async Task<TPlan> CreatePlanAsync<TPlanner, TPlan>(
2929
Func<TPlanner, Kernel, string, CancellationToken, Task<TPlan>> createPlanAsync,
30-
Func<TPlan, string> planToString,
3130
TPlanner planner, Kernel kernel, string goal, ILogger logger, CancellationToken cancellationToken)
3231
where TPlanner : class
3332
where TPlan : class
@@ -36,39 +35,69 @@ public static async Task<TPlan> CreatePlanAsync<TPlanner, TPlan>(
3635

3736
using var _ = s_activitySource.StartActivity(plannerName);
3837

39-
if (logger.IsEnabled(LogLevel.Trace))
40-
{
41-
logger.LogTrace("Plan creation started. Goal: {Goal}", goal); // Sensitive data, logging as trace, disabled by default
42-
}
43-
else if (logger.IsEnabled(LogLevel.Information))
44-
{
45-
logger.LogInformation("Plan creation started.");
46-
}
38+
logger.LogPlanCreationStarted();
39+
logger.LogGoal(goal);
4740

4841
TagList tags = new() { { "sk.planner.name", plannerName } };
4942
long startingTimestamp = Stopwatch.GetTimestamp();
5043
try
5144
{
5245
var plan = await createPlanAsync(planner, kernel, goal, cancellationToken).ConfigureAwait(false);
53-
54-
if (logger.IsEnabled(LogLevel.Information))
55-
{
56-
logger.LogInformation("Plan created. Plan:\n{Plan}", planToString(plan));
57-
}
46+
logger.LogPlanCreated();
47+
logger.LogPlan(plan);
5848

5949
return plan;
6050
}
6151
catch (Exception ex)
6252
{
63-
logger.LogError(ex, "Plan creation failed. Error: {Message}", ex.Message);
53+
logger.LogPlanCreationError(ex, ex.Message);
6454
tags.Add("error.type", ex.GetType().FullName);
6555
throw;
6656
}
6757
finally
6858
{
6959
TimeSpan duration = new((long)((Stopwatch.GetTimestamp() - startingTimestamp) * (10_000_000.0 / Stopwatch.Frequency)));
70-
logger.LogInformation("Plan creation duration: {Duration}ms.", duration.TotalMilliseconds);
60+
logger.LogPlanCreationDuration(duration.TotalSeconds);
7161
s_createPlanDuration.Record(duration.TotalSeconds, in tags);
7262
}
7363
}
64+
65+
#region Logging helpers
66+
[LoggerMessage(
67+
EventId = 0,
68+
Level = LogLevel.Information,
69+
Message = "Plan creation started.")]
70+
static partial void LogPlanCreationStarted(this ILogger logger);
71+
72+
[LoggerMessage(
73+
EventId = 1,
74+
Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
75+
Message = "Goal: {Goal}")]
76+
static partial void LogGoal(this ILogger logger, string goal);
77+
78+
[LoggerMessage(
79+
EventId = 2,
80+
Level = LogLevel.Information,
81+
Message = "Plan created.")]
82+
static partial void LogPlanCreated(this ILogger logger);
83+
84+
[LoggerMessage(
85+
EventId = 3,
86+
Level = LogLevel.Trace, // Sensitive data, logging as trace, disabled by default
87+
Message = "Plan:\n{Plan}")]
88+
static partial void LogPlan(this ILogger logger, object plan);
89+
90+
[LoggerMessage(
91+
EventId = 4,
92+
Level = LogLevel.Error,
93+
Message = "Plan creation failed. Error: {Message}")]
94+
static partial void LogPlanCreationError(this ILogger logger, Exception exception, string message);
95+
96+
[LoggerMessage(
97+
EventId = 5,
98+
Level = LogLevel.Information,
99+
Message = "Plan creation duration: {Duration}s.")]
100+
static partial void LogPlanCreationDuration(this ILogger logger, double duration);
101+
102+
#endregion
74103
}

‎dotnet/src/Planners/Planners.Handlebars/Handlebars/HandlebarsPlanner.cs

-1
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,6 @@ public Task<HandlebarsPlan> CreatePlanAsync(Kernel kernel, string goal, Cancella
4444
return PlannerInstrumentation.CreatePlanAsync(
4545
static (HandlebarsPlanner planner, Kernel kernel, string goal, CancellationToken cancellationToken)
4646
=> planner.CreatePlanCoreAsync(kernel, goal, cancellationToken),
47-
static (HandlebarsPlan plan) => plan.ToString(),
4847
this, kernel, goal, logger, cancellationToken);
4948
}
5049

‎dotnet/src/SemanticKernel.Abstractions/Functions/KernelFunction.cs

+5-24
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@
44
using System.Collections.Generic;
55
using System.Diagnostics;
66
using System.Diagnostics.Metrics;
7-
using System.Linq;
87
using System.Runtime.CompilerServices;
98
using System.Threading;
109
using System.Threading.Tasks;
@@ -145,11 +144,7 @@ public async Task<FunctionResult> InvokeAsync(
145144

146145
// Ensure arguments are initialized.
147146
arguments ??= new KernelArguments();
148-
149-
if (logger.IsEnabled(LogLevel.Trace))
150-
{
151-
logger.LogTrace("Function invoking. Arguments: {Arguments}", string.Join(", ", arguments.Select(v => $"{v.Key}:{v.Value}")));
152-
}
147+
logger.LogFunctionInvokingWithArguments(this.Name, arguments);
153148

154149
TagList tags = new() { { "sk.function.name", this.Name } };
155150
long startingTimestamp = Stopwatch.GetTimestamp();
@@ -182,11 +177,7 @@ public async Task<FunctionResult> InvokeAsync(
182177
throw new OperationCanceledException($"A {nameof(Kernel)}.{nameof(Kernel.FunctionInvoked)} event handler requested cancellation after function invocation.");
183178
}
184179

185-
if (logger.IsEnabled(LogLevel.Trace))
186-
{
187-
logger.LogTrace("Function succeeded. Result: {Result}", functionResult.Value);
188-
}
189-
180+
logger.LogFunctionInvokedSuccess(functionResult.Value);
190181
return functionResult;
191182
}
192183
catch (Exception ex)
@@ -199,10 +190,7 @@ public async Task<FunctionResult> InvokeAsync(
199190
// Record the invocation duration metric and log the completion.
200191
TimeSpan duration = new((long)((Stopwatch.GetTimestamp() - startingTimestamp) * (10_000_000.0 / Stopwatch.Frequency)));
201192
s_invocationDuration.Record(duration.TotalSeconds, in tags);
202-
if (logger.IsEnabled(LogLevel.Information))
203-
{
204-
logger.LogInformation("Function completed. Duration: {Duration}s", duration.TotalSeconds);
205-
}
193+
logger.LogFunctionComplete(duration.TotalSeconds);
206194
}
207195
}
208196

@@ -276,11 +264,7 @@ public async IAsyncEnumerable<T> InvokeStreamingAsync<T>(
276264
ILogger logger = kernel.LoggerFactory.CreateLogger(this.Name);
277265

278266
arguments ??= new KernelArguments();
279-
280-
if (logger.IsEnabled(LogLevel.Trace))
281-
{
282-
logger.LogTrace("Function streaming. Arguments: {Arguments}", string.Join(", ", arguments.Select(v => $"{v.Key}:{v.Value}")));
283-
}
267+
logger.LogFunctionStreamingInvokingWithArguments(this.Name, arguments);
284268

285269
TagList tags = new() { { "sk.function.name", this.Name } };
286270
long startingTimestamp = Stopwatch.GetTimestamp();
@@ -379,10 +363,7 @@ private static void HandleException(
379363
{
380364
// Log the exception and add its type to the tags that'll be included with recording the invocation duration.
381365
tags.Add("error.type", ex.GetType().FullName);
382-
if (logger.IsEnabled(LogLevel.Error))
383-
{
384-
logger.LogError(ex, "Function failed. Error: {Message}", ex.Message);
385-
}
366+
logger.LogFunctionError(ex, ex.Message);
386367

387368
// If the exception is an OperationCanceledException, wrap it in a KernelFunctionCanceledException
388369
// in order to convey additional details about what function was canceled. This is particularly

‎dotnet/src/SemanticKernel.Abstractions/Functions/KernelFunctionLogMessages.cs

+79
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,79 @@
1+
// Copyright (c) Microsoft. All rights reserved.
2+
3+
using System;
4+
using Microsoft.Extensions.Logging;
5+
6+
namespace Microsoft.SemanticKernel;
7+
8+
/// <summary>
9+
/// Extensions for logging <see cref="KernelFunction"/> invocations.
10+
/// This extension uses the <see cref="LoggerMessageAttribute"/> to
11+
/// generate logging code at compile time to achieve optimized code.
12+
/// </summary>
13+
internal static partial class KernelFunctionLogMessages
14+
{
15+
/// <summary>
16+
/// Logs invocation of a <see cref="KernelFunction"/>.
17+
/// </summary>
18+
[LoggerMessage(
19+
EventId = 0,
20+
Level = LogLevel.Trace,
21+
Message = "Function {FunctionName} invoking. Arguments: {Arguments}.")]
22+
public static partial void LogFunctionInvokingWithArguments(
23+
this ILogger logger,
24+
string functionName,
25+
KernelArguments arguments);
26+
27+
/// <summary>
28+
/// Logs cancellation of a <see cref="KernelFunction"/>.
29+
/// </summary>
30+
[LoggerMessage(
31+
EventId = 1,
32+
Level = LogLevel.Information,
33+
Message = "Function canceled prior to invocation.")]
34+
public static partial void LogFunctionCanceledPriorToInvoking(this ILogger logger);
35+
36+
/// <summary>
37+
/// Logs successful invocation of a <see cref="KernelFunction"/>.
38+
/// </summary>
39+
[LoggerMessage(
40+
EventId = 2,
41+
Level = LogLevel.Trace,
42+
Message = "Function succeeded. Result: {Result}")]
43+
public static partial void LogFunctionInvokedSuccess(this ILogger logger, object? result);
44+
45+
/// <summary>
46+
/// Logs <see cref="KernelFunction"/> error.
47+
/// </summary>
48+
[LoggerMessage(
49+
EventId = 3,
50+
Level = LogLevel.Error,
51+
Message = "Function failed. Error: {Message}")]
52+
public static partial void LogFunctionError(
53+
this ILogger logger,
54+
Exception exception,
55+
string message);
56+
57+
/// <summary>
58+
/// Logs <see cref="KernelFunction"/> complete.
59+
/// </summary>
60+
[LoggerMessage(
61+
EventId = 4,
62+
Level = LogLevel.Information,
63+
Message = "Function completed. Duration: {Duration}s")]
64+
public static partial void LogFunctionComplete(
65+
this ILogger logger,
66+
double duration);
67+
68+
/// <summary>
69+
/// Logs streaming invocation of a <see cref="KernelFunction"/>.
70+
/// </summary>
71+
[LoggerMessage(
72+
EventId = 5,
73+
Level = LogLevel.Trace,
74+
Message = "Function {FunctionName} streaming. Arguments: {Arguments}.")]
75+
public static partial void LogFunctionStreamingInvokingWithArguments(
76+
this ILogger logger,
77+
string functionName,
78+
KernelArguments arguments);
79+
}

0 commit comments

Comments
 (0)