Logs: Buffer log state values to fix disposing HttpContext #2932

CodeBlanch · 2022-02-23T06:45:26Z

Changes

BatchLogRecordExportProcessor will now buffer log StateValues to fix the issue caused by ASP.NET Core hosting state wrapping HttpContext which can be disposed before export has triggered.

TODOs

Appropriate CHANGELOG.md updated for non-trivial changes

…lues

codecov · 2022-02-23T07:07:10Z

Codecov Report

Merging #2932 (39ebc13) into main (72ade32) will increase coverage by 0.10%.
The diff coverage is 97.36%.

@@            Coverage Diff             @@
##             main    #2932      +/-   ##
==========================================
+ Coverage   83.86%   83.96%   +0.10%     
==========================================
  Files         254      254              
  Lines        8941     8966      +25     
==========================================
+ Hits         7498     7528      +30     
+ Misses       1443     1438       -5

Impacted Files	Coverage Δ
...penTelemetry/Logs/BatchLogRecordExportProcessor.cs	`0.00% <0.00%> (ø)`
...rter.InMemory/InMemoryExporterLoggingExtensions.cs	`100.00% <100.00%> (ø)`
src/OpenTelemetry/Logs/LogRecord.cs	`97.50% <100.00%> (+0.57%)`	⬆️
src/OpenTelemetry/Logs/OpenTelemetryLogger.cs	`95.00% <100.00%> (+0.55%)`	⬆️
...enTelemetry/Logs/SimpleLogRecordExportProcessor.cs	`0.00% <0.00%> (-100.00%)`	⬇️
...tation/OpenTelemetryProtocolExporterEventSource.cs	`75.00% <0.00%> (-10.00%)`	⬇️
...ZPages/Implementation/ZPagesExporterEventSource.cs	`56.25% <0.00%> (-6.25%)`	⬇️
src/OpenTelemetry/BatchExportProcessor.cs	`84.21% <0.00%> (-3.16%)`	⬇️
src/OpenTelemetry/Metrics/CompositeMetricReader.cs	`73.13% <0.00%> (-1.11%)`	⬇️
...Telemetry/Internal/SelfDiagnosticsEventListener.cs	`96.87% <0.00%> (-0.79%)`	⬇️
... and 11 more

pellared

just a few minor (nit) comments

src/OpenTelemetry/Logs/LogRecord.cs

src/OpenTelemetry/CHANGELOG.md

test/OpenTelemetry.Tests/Logs/LogRecordTest.cs

cijothomas · 2022-02-23T18:21:10Z

src/OpenTelemetry/Logs/LogRecord.cs

+                // See:
+                // https://github.com/open-telemetry/opentelemetry-dotnet/issues/2905
+
+                this.bufferedStateValues = new(this.stateValues);


does this copy the whole collection to bufferedStateValues? if not, we'll still have the same issue, when we eventually iteration on bufferedStateValues?

It definitely works because I started with a failing test and then I made it pass. BUT... there are two branches in List<T> I was expecting us to hit the first one which I thought would be faster. Looking at it right now, we are probably falling into the second one which just does an enumeration. Because IReadOnlyList<T> does not implement ICollection<T>. Oh .NET collections! That enumeration is probably costing us some allocation we can avoid. Let me perf test it a bit and I'll reply back.

@cijothomas OK I did some perf testing. Perf depends on the concrete type of the state. When there is an ICollection<T> the CopyTo directly over the array gives a nice boost. When there is only IReadOnlyList we can avoid an allocation using a for loop instead of using the enumerator. For other states, we already make a copy so there isn't any need to buffer at all. I added some type checking to optimize for those cases.

Let me know what you think about that.

Method NumberOfItemsInState Mean Error StdDev Gen 0 Gen 1 Allocated

BufferListState 0 38.79 ns 0.480 ns 0.401 ns 0.0108 - 136 B

BufferReadOnlyState 0 37.15 ns 0.324 ns 0.253 ns 0.0108 - 136 B

BufferCopiedState 0 39.59 ns 0.565 ns 0.472 ns 0.0108 - 136 B

BufferListState 100 142.18 ns 1.753 ns 1.369 ns 0.1402 0.0007 1,760 B

BufferReadOnlyState 100 648.79 ns 11.549 ns 10.803 ns 0.1402 - 1,760 B

BufferCopiedState 100 39.69 ns 0.807 ns 0.829 ns 0.0108 - 136 B

cijothomas · 2022-02-23T18:24:27Z

src/OpenTelemetry/Logs/LogRecord.cs

        {
-            if (this.ScopeProvider == null || this.bufferedScopes != null)
+            if (this.stateValues != null && this.bufferedStateValues == null)


https://github.com/open-telemetry/opentelemetry-dotnet/blob/main/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs#L67 should we set to null similar to being done for scopes?

I like it! Updated so state works the same. Had to update a lot of tests but I think it was worth it. LMK what you think.

alanwest · 2022-02-24T20:01:55Z

src/OpenTelemetry/Logs/LogRecord.cs

+        /// <remarks>
+        /// Note: StateValues are only available during the lifecycle of the log
+        /// message being written. If you need to capture state to be used later
+        /// (for example in batching scenarios), call <see cref="Buffer"/> to


Buffer is an internal API and StateValues is public. Might lead to confusion being in the comment here. Should Buffer be a public API since maybe there are other use cases besides the batching processor where someone extending the SDK would want access to call Buffer?

@alanwest I think it was public originally but then in code review on the initial PR we made it internal. Didn't catch the comments, sorry.

I took this in a different direction. Check out this commit: c057ea0

The change yesterday to clear state after processing LogRecords introduced/exposed an issue in our InMemoryExporter. Basically, it isn't very useful because the exported LogRecords don't have states or scopes available!

I added a setting on SimpleLogRecordExportProcessor which the InMemoryExporter log extension now uses to turn on buffering. It is currently public. If we leave it public, I think we can keep LogRecord.Buffer internal. Basically now if users need buffering they can either use SimpleLogRecordExportProcessor with the new property or BatchLogRecordExportProcessor which always buffers. I updated the comments referenced here to point to the public stuff.

/cc @cijothomas @reyang

… data buffering.

reyang · 2022-02-25T04:30:29Z

src/OpenTelemetry.Exporter.InMemory/InMemoryExporterLoggingExtensions.cs

+            return loggerOptions.AddProcessor(
+                new SimpleLogRecordExportProcessor(new InMemoryExporter<LogRecord>(exportedItems))
+                {
+                    BufferLogData = true,


Is this for InMemoryExporter scenario, or there are more use cases?

Check out the comment above this one. I was typing that out while you were reviewing 😄 I think it has general use, which is why I made it public. But it doesn't have to be, we could make it internal and use InternalsVisibleTo to allow InMemoryExporter project to set it. Or figure out something else entirely!

I'm interested about the general use.

I thought InMemoryExporter is the only odd ball here because it allows users to examine the log records after Export() has returned (and I was thinking maybe we just change AddInMemoryExporter to use batch processor 😆). Do you see other cases where log records are consumed outside Export()?

@reyang I couldn't up with any good concrete use cases for it to be public so I redid the change. Take a look and let me know what you think. I gave the log in-memory registration extension its own processor to control the buffering. No impact to actual workloads that way. Used InternalsVisibleTo in order to allow that processor to call Buffer without a public API change. I did try using the batch processor, but that changed the semantics. Tests need to spin or call force flush I think keeping it on simple keeps the tests simple 😉

Take a look and let me know what you think. I gave the log in-memory registration extension its own processor to control the buffering. Used InternalsVisibleTo in order to allow that processor to call Buffer without a public API change.

+1 Looks solid 👍 I think InMemoryExporter would justify InternalsVisibleTo because the fact that it allows data to be examined after Export() returned is making it special comparing to all other exporters.

I did try using the batch processor, but that changed the semantics. Tests need to spin or call force flush I think keeping it on simple keeps the tests simple.

These are the pros and cons I could think of:

[minus] The Batch version will require ForceFlush, which is a semantic change (we can imagine folks who already rely on the Simple behavior would see test breaks).

[minus] the Batch version might drop the data on the floor if the circular buffer runs out of space, making it a bit unpredictable.

[plus] The Batch version makes InMemoryExporter suitable for perf test, because it doesn't have a global lock like the Simple version (so callers won't yield control when there is contention).

[plus] The Batch version makes the semantic consistent across logs/metrics/traces - because in Metrics case folks have to ForceFlush anyways.

I would weight 1 > 2 > 3 > 4. The change you've made seems to be the best balance IMHO.

…nMemoryExporter.

cijothomas · 2022-03-02T05:02:57Z

Will need to review in deep, so holding off from merging. The immediate crash issue is addressed separately

As discussed in today's SIG, we might want to explore and see if it is feasible to optimize for the common patter (i.e using extension methods like LogInformation, source-generation.etc), which provides state as IReadOnlyList<string,object>, and not ICollection.

github-actions · 2022-03-10T03:19:37Z

This PR was marked stale due to lack of activity and will be closed in 7 days. Commenting or Pushing will instruct the bot to automatically remove the label. This bot runs once per day.

github-actions · 2022-03-18T03:17:48Z

Closed as inactive. Feel free to reopen if this PR is still being worked on.

Buffer log state values to fix disposing HttpContext.

fad47ef

CodeBlanch requested a review from a team as a code owner February 23, 2022 06:45

CodeBlanch added 2 commits February 22, 2022 22:48

CHANGELOG update.

fe866ca

Merge remote-tracking branch 'upstream/main' into logs-buffer-stateva…

35c70e2

…lues

pellared reviewed Feb 23, 2022

View reviewed changes

src/OpenTelemetry/Logs/LogRecord.cs Outdated Show resolved Hide resolved

src/OpenTelemetry/CHANGELOG.md Outdated Show resolved Hide resolved

test/OpenTelemetry.Tests/Logs/LogRecordTest.cs Outdated Show resolved Hide resolved

Merge branch 'main' into logs-buffer-statevalues

36417e4

cijothomas reviewed Feb 23, 2022

View reviewed changes

cijothomas and others added 4 commits February 23, 2022 11:25

Merge branch 'main' into logs-buffer-statevalues

daf2452

Code review.

2b6a4f0

Nits.

4ca35b5

Nits.

36c8958

reyang approved these changes Feb 24, 2022

View reviewed changes

alanwest reviewed Feb 24, 2022

View reviewed changes

Add a property on SimpleLogRecordExportProcessor to control LogRecord…

c057ea0

… data buffering.

reyang reviewed Feb 25, 2022

View reviewed changes

CodeBlanch added 3 commits February 25, 2022 20:40

Type checks for state buffering.

16d3868

Tweak.

c057566

Revert public API change and use a buffering processor dedicated to I…

39ebc13

…nMemoryExporter.

cijothomas added the pr:do-not-merge label Mar 2, 2022

github-actions bot added the Stale label Mar 10, 2022

CodeBlanch mentioned this pull request Mar 16, 2022

Logs: Performance and safety enhancements #3056

Closed

3 tasks

github-actions bot closed this Mar 18, 2022

CodeBlanch mentioned this pull request Jun 28, 2022

Logs: Add log record pooling #3385

Merged

1 task

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logs: Buffer log state values to fix disposing HttpContext #2932

Logs: Buffer log state values to fix disposing HttpContext #2932

CodeBlanch commented Feb 23, 2022 •

edited

Loading

codecov bot commented Feb 23, 2022 •

edited

Loading

pellared left a comment

cijothomas Feb 23, 2022

CodeBlanch Feb 24, 2022

CodeBlanch Feb 26, 2022

cijothomas Feb 23, 2022

CodeBlanch Feb 24, 2022

reyang Feb 24, 2022

alanwest Feb 24, 2022

CodeBlanch Feb 25, 2022

reyang Feb 25, 2022

CodeBlanch Feb 25, 2022

reyang Feb 25, 2022 •

edited

Loading

CodeBlanch Feb 26, 2022

reyang Feb 26, 2022 •

edited

Loading

cijothomas commented Mar 2, 2022 •

edited

Loading

github-actions bot commented Mar 10, 2022

github-actions bot commented Mar 18, 2022

Method	NumberOfItemsInState	Mean	Error	StdDev	Gen 0	Gen 1	Allocated
BufferListState	0	38.79 ns	0.480 ns	0.401 ns	0.0108	-	136 B
BufferReadOnlyState	0	37.15 ns	0.324 ns	0.253 ns	0.0108	-	136 B
BufferCopiedState	0	39.59 ns	0.565 ns	0.472 ns	0.0108	-	136 B
BufferListState	100	142.18 ns	1.753 ns	1.369 ns	0.1402	0.0007	1,760 B
BufferReadOnlyState	100	648.79 ns	11.549 ns	10.803 ns	0.1402	-	1,760 B
BufferCopiedState	100	39.69 ns	0.807 ns	0.829 ns	0.0108	-	136 B

Logs: Buffer log state values to fix disposing HttpContext #2932

Logs: Buffer log state values to fix disposing HttpContext #2932

Conversation

CodeBlanch commented Feb 23, 2022 • edited Loading

Changes

TODOs

codecov bot commented Feb 23, 2022 • edited Loading

Codecov Report

pellared left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

reyang Feb 25, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

reyang Feb 26, 2022 • edited Loading

Choose a reason for hiding this comment

cijothomas commented Mar 2, 2022 • edited Loading

github-actions bot commented Mar 10, 2022

github-actions bot commented Mar 18, 2022

CodeBlanch commented Feb 23, 2022 •

edited

Loading

codecov bot commented Feb 23, 2022 •

edited

Loading

reyang Feb 25, 2022 •

edited

Loading

reyang Feb 26, 2022 •

edited

Loading

cijothomas commented Mar 2, 2022 •

edited

Loading