Performance Improvements - Logging #2946

RohitRanjanMS · 2023-01-09T11:39:46Z

This PR addresses the issue #2842.
Enabling Application Insights has significant performance and throughput overhead. Function supports adding context to log/metric telemetry using BeginScope(). Each call to BeginScope() creates another level of nesting, so that logs/metrics produced within the scope can be tagged with information about where they came from. While this is done extensively in host, customers can create scopes as well (.Net In-Proc) . Nick did an investigation to highlight the performance overhead of using scopes. This is primarily due to multiple Dictionaries that get allocated to support scope. One at the time of passing the scope attributes, another when these attributes are received and wrapped in ReadOnlyDictionary. There’s another set of allocation when the current scope is built where-in it recursively iterate through the nested scopes.

Improvements in this PR

ApplicationInsightsLogger.cs
a. Removed BeginScope from the Log() method. All the known properties are passed as param and added to the telemetry property. This reduces the level of nesting and also reduces the cost of building scopeInfo.
b. Reduced the numer of times GetMergedStateDictionaryOrNull is called.
c. Removed Linq from ApplyScopeProperties().
d. Saved some boxing/unboxing and made type casting more efficient.
LogLevelEnumHelper .cs
Enum helper to convert enum into string. This uses a cached string array. No allocation and very efficient compared to ToString().
WebJobsTelemetryInitializer.cs
a. Restricted the call to GetMergedStateDictionaryOrNull() for only DependencyTelemetry.
b. Category, LogLevel, EventId and EventName are set in ApplicationInsightsLogger.Log() method.
DictionaryLoggerScope.cs
a. Push() - If state is a dictionary, then use it otherwise build a new dictionary.
b. GetMergedStateDictionaryOrNull() – Return null if Current is null.
c. Cached the scopeInfo and return from cache if exist. The cache is tied to the current scope.
e. _itemCount – to avoid dictionary resizing.

Benchmarking:
Memory Allocation:

Dictionary<string, object> allocation is down by ~99.75%.
Resize is almost negligible.

Req/sec and avg response time is down by ~8%

Execution Time

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/LogLevelEnumHelper.cs

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/DictionaryLoggerScope.cs

…ationInsightsLogger.cs Co-authored-by: Jacob Viau <javia@microsoft.com>

NickCraver

Changes are looking good - My main concern is around the GetMergedStateDictionaryOrNull shifts - have we done memory profiling on that tree in particular? (I see the total profiling - nice! - I'm only asking about the remainder) I worry with the new approach we may be adding dictionary allocations overall. I think we can scope this in some places but that's messy too - IMO we need another way to go about doing this all together, but I'm not sure where else it's still used looking only at the diff scope of this PR.

Overall: I think there's probably a round of changes here I'm not seeing in GitHub's current version given resolved comments, happy to take a peek at latest if helpful - nice work!

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/LogLevelEnumHelper.cs

...rosoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs

…/Azure/azure-webjobs-sdk into roranjan/AILoggerPerfImprovement

brettsam · 2023-03-13T15:10:54Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/DictionaryLoggerScope.cs

@@ -12,16 +12,16 @@ internal class DictionaryLoggerScope
    {
        private static AsyncLocal<DictionaryLoggerScope> _value = new AsyncLocal<DictionaryLoggerScope>();

-        private DictionaryLoggerScope(IReadOnlyDictionary<string, object> state, DictionaryLoggerScope parent)


Have you looked into getting rid of this type entirely? I wrote this years ago before ExternalScopes were supported and have changed every other instance of logging to use that rather than this. The only holdout is how we access the scope in the TelemetryInitializer, but I never did enough research to figure out how to get around that.

I'd be curious how much improvement we get by using the built-in ScopeProvider, which I assume is optimized for performance...

I'd be interested to see performance reports if this was used (even if it is fairly hacked together for now).

I did try IExternalScopeProvider but it didn't work.

As you mentioned, we need the scope in the TelemetryInitializer for Dependencies. All telemetry items flow through the ApplicationInsightsLogger except dependencies. TelemetryInitializer is the only way I can think of to enrich dependencies with additional information.

IExternalScopeProvider calls an internal BeginScope instead of the one provided by us. We need this for StartTelemetryIfFunctionInvocation. ApplicationInsightsLogger is the only logger that uses BeginScope.

I did some benchmarking against IExternalScopeProvider and it's very efficient and works like magic. Unfortunately, couldn't use it here.
The proposed changes are efficient as well, we are saving almost 99.74% allocation even with all the complexities.

@RohitRanjanMS can you share your code with the IExternalScopeProvider implementation?

sure, I don't have a commit, but I can make a quick change and push to a branch.

I created a branch that uses IExternalScopeProvider. I don't see any issue with BeginScope() now and the only thing that's stopping us from using this is WebJobsTelemetryInitializer.

I did some benchmarking using LoggerFactoryScopeProvider. While the performance is almost same, memory allocation is significantly less.

Thank you for the branch. I understand your issue now of needing access to the log scope - or rather to a telemetry property bag for multiple forms of telemetry (traces and logs here). I believe this is a concept solved by OTel Baggage, but we don't have access to it here. I don't really like the idea of rolling our own scope and having this discrepancy in how this one ILogger works - but addressing this is not that straight forward.

As for the allocation difference you see - yes, your sample branch is allocating an extra dictionary. You can remove that perf hit by avoiding the dictionary allocation and attaching scope data directly to where it needs to go within the ForEachScope delegate. Additionally, you want to use the state parameter to pass in any variables you access within the ForEachScope delegate to avoid function closures. With those 2 changes you should see significantly less allocations.

NickCraver

Current code looks good from an efficiency standpoint - I'm only reviewing in text so limited here and profiles are very much appreciated!

My only suggestion here would be: do we want to beef up the testing slightly specifically on scopes/expected values? There's enough of a change here I'm not sure existing tests cover all the cases that can happen with overrides, what if the value set in an override is null, etc - just from a 1:1 behavior with the old for nested properties.

RohitRanjanMS · 2023-03-16T22:00:47Z

Current code looks good from an efficiency standpoint - I'm only reviewing in text so limited here and profiles are very much appreciated!

My only suggestion here would be: do we want to beef up the testing slightly specifically on scopes/expected values? There's enough of a change here I'm not sure existing tests cover all the cases that can happen with overrides, what if the value set in an override is null, etc - just from a 1:1 behavior with the old for nested properties.

I will have a look at test cases and add more if we don't have enough coverage.

jviau

Small nits and some perf suggestions.

My primary concern is the way this makes our one ApplicationInsightsLogger unique. I worry that we have two ways log scopes are done, and it is not clear if you need to use ILogger.BeginScope or this other DictionaryLoggerScope. I get that we are trying to bring log scope properties over to distributed tracing (AI dependencies here). Did we explore if Activity.Tags would work here? Or is there some other prescribed pattern for having a general "telemetry scope" instead of a log scope?

I am approving this as the PR goal is performance and the DictionaryLoggerScope deviation (which is my primary concern) predates this PR.

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/DictionaryLoggerScope.cs

jviau · 2023-03-20T18:36:47Z

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/DictionaryLoggerScope.cs

@@ -12,16 +12,16 @@ internal class DictionaryLoggerScope
    {
        private static AsyncLocal<DictionaryLoggerScope> _value = new AsyncLocal<DictionaryLoggerScope>();

-        private DictionaryLoggerScope(IReadOnlyDictionary<string, object> state, DictionaryLoggerScope parent)


Thank you for the branch. I understand your issue now of needing access to the log scope - or rather to a telemetry property bag for multiple forms of telemetry (traces and logs here). I believe this is a concept solved by OTel Baggage, but we don't have access to it here. I don't really like the idea of rolling our own scope and having this discrepancy in how this one ILogger works - but addressing this is not that straight forward.

As for the allocation difference you see - yes, your sample branch is allocating an extra dictionary. You can remove that perf hit by avoiding the dictionary allocation and attaching scope data directly to where it needs to go within the ForEachScope delegate. Additionally, you want to use the state parameter to pass in any variables you access within the ForEachScope delegate to avoid function closures. With those 2 changes you should see significantly less allocations.

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Extensions/LogLevelExtension.cs

...rosoft.Azure.WebJobs.Logging.ApplicationInsights/Initializers/WebJobsTelemetryInitializer.cs

src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/DictionaryLoggerScope.cs

e.g., TelemetryClient client = new TelemetryClient(); client.InstrumentationKey = "<>"; client.TrackTrace("msg");

Initial Commit.

76b86d7

RohitRanjanMS marked this pull request as draft January 9, 2023 11:40

RohitRanjanMS added 4 commits January 18, 2023 12:28

Fixed Eventid

7d4e4d1

More changes

0932332

More changes

b8f46a0

Fixed current scope

963f0bb

RohitRanjanMS marked this pull request as ready for review January 24, 2023 20:36

RohitRanjanMS requested review from mathewc, NickCraver, brettsam and fabiocav January 24, 2023 20:36

RohitRanjanMS self-assigned this Jan 24, 2023

RohitRanjanMS requested a review from jviau January 24, 2023 21:10

jviau reviewed Jan 24, 2023

View reviewed changes

Update src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Applic…

16f4026

…ationInsightsLogger.cs Co-authored-by: Jacob Viau <javia@microsoft.com>

NickCraver reviewed Jan 25, 2023

View reviewed changes

RohitRanjanMS added 2 commits January 26, 2023 00:02

Fixed if else

7ff0886

Merge branch 'roranjan/AILoggerPerfImprovement' of https://github.com…

7b42189

…/Azure/azure-webjobs-sdk into roranjan/AILoggerPerfImprovement

RohitRanjanMS requested a review from AnatoliB February 1, 2023 18:03

RohitRanjanMS added 4 commits February 3, 2023 00:03

Removed state from DictionaryScope

a771b61

Pattern matching

26595a5

Removed space

3818c14

Removed unused namespace

923a3c8

RohitRanjanMS requested review from NickCraver and jviau February 14, 2023 09:13

brettsam reviewed Mar 13, 2023

View reviewed changes

Fixed null handling.

66eba1d

NickCraver reviewed Mar 15, 2023

View reviewed changes

jviau approved these changes Mar 20, 2023

View reviewed changes

RohitRanjanMS added 6 commits March 21, 2023 12:40

Optimizing for the first BeginScope invocation.

a53f39d

Fixed code

c8d909c

Added tests to validate overriding in DictionaryLoggerScope.

97eb097

Fixed int/double casting.

b83c6a3

Add scope properties for logs emitted using TelemetryClient.

591395b

e.g., TelemetryClient client = new TelemetryClient(); client.InstrumentationKey = "<>"; client.TrackTrace("msg");

Fixed spacing

550d8fe

RohitRanjanMS requested a review from michaelpeng36 April 4, 2023 19:47

RohitRanjanMS merged commit 85485d4 into dev Apr 4, 2023

RohitRanjanMS deleted the roranjan/AILoggerPerfImprovement branch April 4, 2023 19:56

cataggar mentioned this pull request Apr 19, 2023

Disable Host.Results logs at the function level for HttpTrigger functions Azure/azure-functions-host#4742

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Performance Improvements - Logging #2946

Performance Improvements - Logging #2946

RohitRanjanMS commented Jan 9, 2023 •

edited

Loading

NickCraver left a comment •

edited

Loading

brettsam Mar 13, 2023

RohitRanjanMS Mar 13, 2023

jviau Mar 13, 2023 •

edited

Loading

RohitRanjanMS Mar 13, 2023

RohitRanjanMS Mar 16, 2023

RohitRanjanMS Mar 20, 2023

jviau Mar 20, 2023

NickCraver left a comment

RohitRanjanMS commented Mar 16, 2023

jviau left a comment •

edited

Loading

jviau Mar 20, 2023

Performance Improvements - Logging #2946

Performance Improvements - Logging #2946

Conversation

RohitRanjanMS commented Jan 9, 2023 • edited Loading

NickCraver left a comment • edited Loading

Choose a reason for hiding this comment

brettsam Mar 13, 2023

Choose a reason for hiding this comment

RohitRanjanMS Mar 13, 2023

Choose a reason for hiding this comment

jviau Mar 13, 2023 • edited Loading

Choose a reason for hiding this comment

RohitRanjanMS Mar 13, 2023

Choose a reason for hiding this comment

RohitRanjanMS Mar 16, 2023

Choose a reason for hiding this comment

RohitRanjanMS Mar 20, 2023

Choose a reason for hiding this comment

jviau Mar 20, 2023

Choose a reason for hiding this comment

NickCraver left a comment

Choose a reason for hiding this comment

RohitRanjanMS commented Mar 16, 2023

jviau left a comment • edited Loading

Choose a reason for hiding this comment

jviau Mar 20, 2023

Choose a reason for hiding this comment

RohitRanjanMS commented Jan 9, 2023 •

edited

Loading

NickCraver left a comment •

edited

Loading

jviau Mar 13, 2023 •

edited

Loading

jviau left a comment •

edited

Loading