Skip to content

Commit

Permalink
.Net: SK Telemetry improvements (#1905)
Browse files Browse the repository at this point in the history
### 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 PR contains changes to improve observability for Semantic Kernel
users, including:
- Logging: using already existing `ILogger` interface with some
improvements described below.
- Metering: implemented using `Meter` and `MeterListener` classes from
`System.Diagnostics.Metrics` namespace.
- Tracing: implemented using `Activity`, `ActivitySource` and
`ActivityListener` classes from `System.Diagnostics` namespace.

Added telemetry uses native .NET methods, which means that it's not
dependent on specific telemetry tool.
Current PR contains console application using Application Insights as
example to show telemetry capabilities in Kernel.

Changes include instrumentation for `SequentialPlanner` as a starting
point and later there will be new PRs for other types of planners and
more improvements for kernel telemetry.

Also, there are updates for `LogLevel` handling across codebase to align
with described log level purpose:

https://learn.microsoft.com/en-us/dotnet/api/microsoft.extensions.logging.loglevel?view=dotnet-plat-ext-7.0

Particularly, there are changes for `LogLevel.Trace` to be used for
sensitive data and most detailed messages, which should not be enabled
in prodution environments.

### Description
<!-- Describe your changes, the overall approach, the underlying design.
These notes will help understanding how your code works. Thanks! -->
Changes:
- Marked `.WithLogger` method in KernelBuilder as obsolete and added new
method `.WithLogging`.
- Added new methods `.WithMetering` and `.WithTracing` in KernelBuilder.
- Improved `LogLevel` handling across codebase to cover cases of logging
sensitive data.
- Implemented `InstrumentedSequentialPlanner` for instrumentation using
decorator pattern.
- Extended `InvokeAsync` method in `Plan` for instrumentation.

### Contribution Checklist
<!-- Before submitting this PR, please make sure: -->
- [x] The code builds clean without any errors or warnings
- [x] The PR follows SK Contribution Guidelines
(https://github.com/microsoft/semantic-kernel/blob/main/CONTRIBUTING.md)
- [x] The code follows the .NET coding conventions
(https://learn.microsoft.com/dotnet/csharp/fundamentals/coding-style/coding-conventions)
verified with `dotnet format`
- [x] All unit tests pass, and I have added new tests where possible
- [x] I didn't break anyone 😄

---------

Co-authored-by: Shawn Callegari <[email protected]>
  • Loading branch information
dmytrostruk and shawncal committed Jul 18, 2023
1 parent f622bfe commit 55dc794
Show file tree
Hide file tree
Showing 45 changed files with 742 additions and 131 deletions.
2 changes: 2 additions & 0 deletions dotnet/Directory.Packages.props
Original file line number Diff line number Diff line change
Expand Up @@ -8,12 +8,14 @@
<PackageVersion Include="Azure.AI.OpenAI" Version="1.0.0-beta.5" />
<PackageVersion Include="Azure.Identity" Version="1.9.0" />
<PackageVersion Include="Azure.Search.Documents" Version="11.5.0-beta.3" />
<PackageVersion Include="Microsoft.ApplicationInsights.WorkerService" Version="2.21.0" />
<PackageVersion Include="Microsoft.Bcl.HashCode" Version="[1.1.0, )" />
<PackageVersion Include="Microsoft.Bcl.AsyncInterfaces" Version="6.0.0" />
<PackageVersion Include="Microsoft.Extensions.Http" Version="6.0.0" />
<PackageVersion Include="NRedisStack" Version="0.8.0" />
<PackageVersion Include="Pgvector" Version="0.1.3" />
<PackageVersion Include="Polly" Version="7.2.4" />
<PackageVersion Include="System.Diagnostics.DiagnosticSource" Version="7.0.2" />

This comment has been minimized.

Copy link
@Woland2k

Woland2k Aug 30, 2023

Contributor

This introduces dependency on .net 7.0 thus breaking azure functions deployment as well as any other products targeting .net 6 LTS (related issue #1793)

<PackageVersion Include="System.Linq.Async" Version="6.0.1" />
<PackageVersion Include="System.Text.Json" Version="6.0.8" />
<!-- Microsoft.Extensions.Logging -->
Expand Down
9 changes: 9 additions & 0 deletions dotnet/SK-dotnet.sln
Original file line number Diff line number Diff line change
Expand Up @@ -145,6 +145,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Connectors.AI.Oobabooga", "
EndProject
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Planning.StepwisePlanner", "src\Extensions\Planning.StepwisePlanner\Planning.StepwisePlanner.csproj", "{4762BCAF-E1C5-4714-B88D-E50FA333C50E}"
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "ApplicationInsightsExample", "samples\ApplicationInsightsExample\ApplicationInsightsExample.csproj", "{C754950A-E16C-4F96-9CC7-9328E361B5AF}"
EndProject
Global
GlobalSection(SolutionConfigurationPlatforms) = preSolution
Debug|Any CPU = Debug|Any CPU
Expand Down Expand Up @@ -356,6 +358,12 @@ Global
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Publish|Any CPU.Build.0 = Publish|Any CPU
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Release|Any CPU.ActiveCfg = Release|Any CPU
{4762BCAF-E1C5-4714-B88D-E50FA333C50E}.Release|Any CPU.Build.0 = Release|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Debug|Any CPU.Build.0 = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Publish|Any CPU.ActiveCfg = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Publish|Any CPU.Build.0 = Debug|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Release|Any CPU.ActiveCfg = Release|Any CPU
{C754950A-E16C-4F96-9CC7-9328E361B5AF}.Release|Any CPU.Build.0 = Release|Any CPU
EndGlobalSection
GlobalSection(SolutionProperties) = preSolution
HideSolutionNode = FALSE
Expand Down Expand Up @@ -407,6 +415,7 @@ Global
{E6EDAB8F-3406-4DBF-9AAB-DF40DC2CA0FA} = {FA3720F1-C99A-49B2-9577-A940257098BF}
{677F1381-7830-4115-9C1A-58B282629DC6} = {0247C2C9-86C3-45BA-8873-28B0948EDC0C}
{4762BCAF-E1C5-4714-B88D-E50FA333C50E} = {078F96B4-09E1-4E0E-B214-F71A4F4BF633}
{C754950A-E16C-4F96-9CC7-9328E361B5AF} = {FA3720F1-C99A-49B2-9577-A940257098BF}
EndGlobalSection
GlobalSection(ExtensibilityGlobals) = postSolution
SolutionGuid = {FBDC56A3-86AD-4323-AA0F-201E59123B83}
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,27 @@
<Project Sdk="Microsoft.NET.Sdk">

<PropertyGroup>
<TargetFramework>net6.0</TargetFramework>
<RollForward>LatestMajor</RollForward>
<OutputType>Exe</OutputType>
<LangVersion>10</LangVersion>
<Nullable>enable</Nullable>
<ImplicitUsings>disable</ImplicitUsings>
<IsPackable>false</IsPackable>
<!-- Suppress: "Declare types in namespaces", "Require ConfigureAwait" -->
<NoWarn>CA1050;CA1707;CA2007;VSTHRD111</NoWarn>
<UserSecretsId>5ee045b0-aea3-4f08-8d31-32d1a6f8fed0</UserSecretsId>
</PropertyGroup>

<ItemGroup>
<PackageReference Include="Microsoft.ApplicationInsights.WorkerService" />
<PackageReference Include="Microsoft.Extensions.Configuration.UserSecrets" />
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\..\src\Extensions\Planning.SequentialPlanner\Planning.SequentialPlanner.csproj" />
<ProjectReference Include="..\..\src\Connectors\Connectors.AI.OpenAI\Connectors.AI.OpenAI.csproj" />
<ProjectReference Include="..\..\src\SemanticKernel\SemanticKernel.csproj" />
</ItemGroup>

</Project>
192 changes: 192 additions & 0 deletions dotnet/samples/ApplicationInsightsExample/Program.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,192 @@
// Copyright (c) Microsoft. All rights reserved.

using System;
using System.Collections.Concurrent;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using System.Threading.Tasks;
using Microsoft.ApplicationInsights;
using Microsoft.ApplicationInsights.DataContracts;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.ApplicationInsights;
using Microsoft.SemanticKernel;
using Microsoft.SemanticKernel.Planning;
using Microsoft.SemanticKernel.Planning.Sequential;

/// <summary>
/// Example of telemetry in Semantic Kernel using Application Insights within console application.
/// </summary>
public sealed class Program
{
/// <summary>
/// Log level to be used by <see cref="ILogger"/>.
/// </summary>
/// <remarks>
/// <see cref="LogLevel.Information"/> is set by default. <para />
/// <see cref="LogLevel.Trace"/> will enable logging with more detailed information, including sensitive data. Should not be used in production. <para />
/// </remarks>
private static LogLevel LogLevel = LogLevel.Information;

public static async Task Main()
{
var serviceProvider = GetServiceProvider();

var telemetryClient = serviceProvider.GetRequiredService<TelemetryClient>();
var logger = serviceProvider.GetRequiredService<ILogger<Program>>();

using var meterListener = new MeterListener();
using var activityListener = new ActivityListener();

ConfigureMetering(meterListener, telemetryClient);
ConfigureTracing(activityListener, telemetryClient);

var kernel = GetKernel(logger);
var planner = GetPlanner(kernel, logger);

try
{
using var operation = telemetryClient.StartOperation<DependencyTelemetry>("ApplicationInsights.Example");

Console.WriteLine("Operation/Trace ID:");
Console.WriteLine(Activity.Current?.TraceId);

var plan = await planner.CreatePlanAsync("Write a poem about John Doe, then translate it into Italian.");

Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());

var result = await kernel.RunAsync(plan);

Console.WriteLine("Result:");
Console.WriteLine(result.Result);
}
finally
{
// Explicitly call Flush() followed by sleep is required in console apps.
// This is to ensure that even if application terminates, telemetry is sent to the back-end.
telemetryClient.Flush();
await Task.Delay(5000);
}
}

private static ServiceProvider GetServiceProvider()
{
var services = new ServiceCollection();

ConfigureApplicationInsightsTelemetry(services);

return services.BuildServiceProvider();
}

private static void ConfigureApplicationInsightsTelemetry(ServiceCollection services)
{
string instrumentationKey = Env.Var("ApplicationInsights__InstrumentationKey");

services.AddLogging(loggingBuilder =>
{
loggingBuilder.AddFilter<ApplicationInsightsLoggerProvider>(typeof(Program).FullName, LogLevel);
loggingBuilder.SetMinimumLevel(LogLevel);
});

services.AddApplicationInsightsTelemetryWorkerService(options =>
{
options.ConnectionString = $"InstrumentationKey={instrumentationKey}";
});
}

private static IKernel GetKernel(ILogger logger)
{
string folder = RepoFiles.SampleSkillsPath();

var kernel = new KernelBuilder()
.WithLogger(logger)
.WithAzureChatCompletionService(
Env.Var("AzureOpenAI__ChatDeploymentName"),
Env.Var("AzureOpenAI__Endpoint"),
Env.Var("AzureOpenAI__ApiKey"))
.Build();

kernel.ImportSemanticSkillFromDirectory(folder, "SummarizeSkill", "WriterSkill");

return kernel;
}

private static ISequentialPlanner GetPlanner(
IKernel kernel,
ILogger logger,
int maxTokens = 1024)
{
var plannerConfig = new SequentialPlannerConfig { MaxTokens = maxTokens };

return new SequentialPlanner(kernel, plannerConfig).WithInstrumentation(logger);
}

/// <summary>
/// Example of metering configuration in Application Insights
/// using <see cref="MeterListener"/> to attach for <see cref="Meter"/> recordings.
/// </summary>
/// <param name="meterListener">Instance of <see cref="MeterListener"/> for metering configuration.</param>
/// <param name="telemetryClient">Instance of Application Insights <see cref="TelemetryClient"/>.</param>
private static void ConfigureMetering(MeterListener meterListener, TelemetryClient telemetryClient)
{
meterListener.InstrumentPublished = (instrument, listener) =>
{
// Subscribe to all metrics in Semantic Kernel
if (instrument.Meter.Name.StartsWith("Microsoft.SemanticKernel", StringComparison.Ordinal))
{
listener.EnableMeasurementEvents(instrument);
}
};

MeasurementCallback<double> measurementCallback = (instrument, measurement, tags, state) =>
{
telemetryClient.GetMetric(instrument.Name).TrackValue(measurement);
};

meterListener.SetMeasurementEventCallback(measurementCallback);

meterListener.Start();
}

/// <summary>
/// Example of advanced distributed tracing configuration in Application Insights
/// using <see cref="ActivityListener"/> to attach for <see cref="Activity"/> events.
/// </summary>
/// <param name="activityListener">Instance of <see cref="ActivityListener"/> for tracing configuration.</param>
/// <param name="telemetryClient">Instance of Application Insights <see cref="TelemetryClient"/>.</param>
private static void ConfigureTracing(ActivityListener activityListener, TelemetryClient telemetryClient)
{
var operations = new ConcurrentDictionary<string, IOperationHolder<DependencyTelemetry>>();

// For more detailed tracing we need to attach Activity entity to Application Insights operation manually.
Action<Activity> activityStarted = activity =>
{
var operation = telemetryClient.StartOperation<DependencyTelemetry>(activity);
operation.Telemetry.Type = activity.Kind.ToString();
operations.TryAdd(activity.TraceId.ToString(), operation);
};

// We also need to manually stop Application Insights operation when Activity entity is stopped.
Action<Activity> activityStopped = activity =>
{
if (operations.TryRemove(activity.TraceId.ToString(), out var operation))
{
telemetryClient.StopOperation(operation);
}
};

// Subscribe to all traces in Semantic Kernel
activityListener.ShouldListenTo =
activitySource => activitySource.Name.StartsWith("Microsoft.SemanticKernel", StringComparison.Ordinal);

activityListener.Sample = (ref ActivityCreationOptions<ActivityContext> _) => ActivitySamplingResult.AllData;
activityListener.SampleUsingParentId = (ref ActivityCreationOptions<string> _) => ActivitySamplingResult.AllData;
activityListener.ActivityStarted = activityStarted;
activityListener.ActivityStopped = activityStopped;

ActivitySource.AddActivityListener(activityListener);
}
}
36 changes: 36 additions & 0 deletions dotnet/samples/ApplicationInsightsExample/RepoUtils/Env.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,36 @@
// Copyright (c) Microsoft. All rights reserved.

using System;
using Microsoft.Extensions.Configuration;

#pragma warning disable CA1812 // instantiated by AddUserSecrets
internal sealed class Env
#pragma warning restore CA1812
{
/// <summary>
/// Simple helper used to load env vars and secrets like credentials,
/// to avoid hard coding them in the sample code
/// </summary>
/// <param name="name">Secret name / Env var name</param>
/// <returns>Value found in Secret Manager or Environment Variable</returns>
internal static string Var(string name)
{
var configuration = new ConfigurationBuilder()
.AddUserSecrets<Env>()
.Build();

var value = configuration[name];
if (!string.IsNullOrEmpty(value))
{
return value;
}

value = Environment.GetEnvironmentVariable(name);
if (string.IsNullOrEmpty(value))
{
throw new ArgumentException($"Secret / Env var not set: {name}");
}

return value;
}
}
39 changes: 39 additions & 0 deletions dotnet/samples/ApplicationInsightsExample/RepoUtils/RepoFiles.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,39 @@
// Copyright (c) Microsoft. All rights reserved.

using System.IO;
using System.Reflection;

internal static class RepoFiles
{
/// <summary>
/// Scan the local folders from the repo, looking for "samples/skills" folder.
/// </summary>
/// <returns>The full path to samples/skills</returns>
public static string SampleSkillsPath()
{
const string Parent = "samples";
const string Folder = "skills";

bool SearchPath(string pathToFind, out string result, int maxAttempts = 10)
{
var currDir = Path.GetFullPath(Assembly.GetExecutingAssembly().Location);
bool found;
do
{
result = Path.Join(currDir, pathToFind);
found = Directory.Exists(result);
currDir = Path.GetFullPath(Path.Combine(currDir, ".."));
} while (maxAttempts-- > 0 && !found);

return found;
}

if (!SearchPath(Parent + Path.DirectorySeparatorChar + Folder, out string path)
&& !SearchPath(Folder, out path))
{
throw new DirectoryNotFoundException("Skills directory not found. The app needs the skills from the repo to work.");
}

return path;
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -92,7 +92,7 @@ private static async Task PoetrySamplesAsync()
// - WriterSkill.Translate language='Italian' INPUT='' =>

Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());

var result = await kernel.RunAsync(plan);

Expand Down Expand Up @@ -124,7 +124,7 @@ private static async Task EmailSamplesAsync()
// - email.SendEmail INPUT='$TRANSLATED_SUMMARY' email_address='$EMAIL_ADDRESS' =>

Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());

var input =
"Once upon a time, in a faraway kingdom, there lived a kind and just king named Arjun. " +
Expand Down Expand Up @@ -166,7 +166,7 @@ private static async Task BookSamplesAsync()
// - WriterSkill.NovelChapter chapterIndex='3' previousChapter='$CHAPTER_2_SYNOPSIS' INPUT='$CHAPTER_3_SYNOPSIS' theme='Children's mystery' => RESULT__CHAPTER_3

Console.WriteLine("Original plan:");
Console.WriteLine(originalPlan.ToPlanString());
Console.WriteLine(originalPlan.ToPlanWithGoalString());

Stopwatch sw = new();
sw.Start();
Expand Down Expand Up @@ -215,7 +215,7 @@ private static async Task MemorySampleAsync()
var plan = await planner.CreatePlanAsync(goal);

Console.WriteLine("Original plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
}

private static IKernel InitializeKernelAndPlanner(out SequentialPlanner planner, int maxTokens = 1024)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -147,7 +147,7 @@ public async Task<string> RunMarkupAsync(string docString, SKContext context)
var plan = docString.FromMarkup("Run a piece of xml markup", context);

Console.WriteLine("Markup plan:");
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());
Console.WriteLine();

var result = await plan.InvokeAsync();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -141,7 +141,7 @@ public static async Task PlanningWithGroundedness()
var plannerConfig = new SequentialPlannerConfig { };
var planner = new SequentialPlanner(kernel, plannerConfig);
var plan = await planner.CreatePlanAsync(ask);
Console.WriteLine(plan.ToPlanString());
Console.WriteLine(plan.ToPlanWithGoalString());

var results = await plan.InvokeAsync(s_groundingText);
Console.WriteLine(results.Result);
Expand Down
Loading

0 comments on commit 55dc794

Please sign in to comment.