Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logs: Add log record pooling #3385

Merged
merged 20 commits into from
Jun 30, 2022
Merged
Show file tree
Hide file tree
Changes from 19 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -42,9 +42,7 @@ private static ExportResult ExportLogRecord(in Batch<LogRecord> batch, ICollecti

foreach (var log in batch)
{
log.BufferLogScopes();

exportedItems.Add(log);
exportedItems.Add(log.Copy());
}

return ExportResult.Success;
Expand Down
44 changes: 42 additions & 2 deletions src/OpenTelemetry/Batch.cs
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
using System.Diagnostics;
using System.Diagnostics.CodeAnalysis;
using OpenTelemetry.Internal;
using OpenTelemetry.Logs;

namespace OpenTelemetry
{
Expand Down Expand Up @@ -90,7 +91,11 @@ public void Dispose()
// Drain anything left in the batch.
while (this.circularBuffer.RemovedCount < this.targetCount)
{
this.circularBuffer.Read();
T item = this.circularBuffer.Read();
if (typeof(T) == typeof(LogRecord))
cijothomas marked this conversation as resolved.
Show resolved Hide resolved
{
LogRecordSharedPool.Current.Return((LogRecord)(object)item);
}
}
}
}
Expand Down Expand Up @@ -140,6 +145,32 @@ public struct Enumerator : IEnumerator<T>
return false;
};

private static readonly BatchEnumeratorMoveNextFunc MoveNextCircularBufferLogRecord = (ref Enumerator enumerator) =>
{
// Note: This type check here is to give the JIT a hint it can
// remove all of this code when T != LogRecord
if (typeof(T) == typeof(LogRecord))
{
var circularBuffer = enumerator.circularBuffer;

var currentItem = enumerator.Current;
if (currentItem != null)
{
LogRecordSharedPool.Current.Return((LogRecord)(object)currentItem);
cijothomas marked this conversation as resolved.
Show resolved Hide resolved
}

if (circularBuffer!.RemovedCount < enumerator.targetCount)
{
enumerator.current = circularBuffer.Read();
return true;
}

enumerator.current = null;
}

return false;
};

private static readonly BatchEnumeratorMoveNextFunc MoveNextArray = (ref Enumerator enumerator) =>
{
var items = enumerator.items;
Expand Down Expand Up @@ -179,7 +210,7 @@ internal Enumerator(CircularBuffer<T> circularBuffer, long targetCount)
this.circularBuffer = circularBuffer;
this.targetCount = targetCount;
this.itemIndex = 0;
this.moveNextFunc = MoveNextCircularBuffer;
this.moveNextFunc = typeof(T) == typeof(LogRecord) ? MoveNextCircularBufferLogRecord : MoveNextCircularBuffer;
}

internal Enumerator(T[] items, long targetCount)
Expand All @@ -201,6 +232,15 @@ internal Enumerator(T[] items, long targetCount)
/// <inheritdoc/>
public void Dispose()
{
if (typeof(T) == typeof(LogRecord))
{
var currentItem = this.current;
if (currentItem != null)
{
LogRecordSharedPool.Current.Return((LogRecord)(object)currentItem);
this.current = null;
}
}
}

/// <inheritdoc/>
Expand Down
15 changes: 12 additions & 3 deletions src/OpenTelemetry/BatchExportProcessor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading;
using OpenTelemetry.Internal;

Expand Down Expand Up @@ -95,8 +96,8 @@ public abstract class BatchExportProcessor<T> : BaseExportProcessor<T>
/// </summary>
internal long ProcessedCount => this.circularBuffer.RemovedCount;

/// <inheritdoc/>
protected override void OnExport(T data)
[MethodImpl(MethodImplOptions.AggressiveInlining)]
internal bool TryExport(T data)
{
if (this.circularBuffer.TryAdd(data, maxSpinCount: 50000))
{
Expand All @@ -111,11 +112,19 @@ protected override void OnExport(T data)
}
}

return; // enqueue succeeded
return true; // enqueue succeeded
}

// either the queue is full or exceeded the spin limit, drop the item on the floor
Interlocked.Increment(ref this.droppedCount);

return false;
}

/// <inheritdoc/>
protected override void OnExport(T data)
{
this.TryExport(data);
}

/// <inheritdoc/>
Expand Down
3 changes: 3 additions & 0 deletions src/OpenTelemetry/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,9 @@
* Handle possible exception when initializing the default service name.
([#3405](https://github.com/open-telemetry/opentelemetry-dotnet/pull/3405))

* `LogRecord` instances are now reused to reduce memory pressure
([#3385](https://github.com/open-telemetry/opentelemetry-dotnet/pull/3385))

## 1.3.0

Released 2022-Jun-03
Expand Down
20 changes: 10 additions & 10 deletions src/OpenTelemetry/CompositeProcessor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -26,7 +26,7 @@ namespace OpenTelemetry
{
public class CompositeProcessor<T> : BaseProcessor<T>
{
private readonly DoublyLinkedListNode head;
internal readonly DoublyLinkedListNode Head;
private DoublyLinkedListNode tail;
private bool disposed;

Expand All @@ -40,8 +40,8 @@ public CompositeProcessor(IEnumerable<BaseProcessor<T>> processors)
throw new ArgumentException($"'{iter}' is null or empty", nameof(iter));
}

this.head = new DoublyLinkedListNode(iter.Current);
this.tail = this.head;
this.Head = new DoublyLinkedListNode(iter.Current);
this.tail = this.Head;

while (iter.MoveNext())
{
Expand All @@ -66,7 +66,7 @@ public CompositeProcessor<T> AddProcessor(BaseProcessor<T> processor)
/// <inheritdoc/>
public override void OnEnd(T data)
{
for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
cur.Value.OnEnd(data);
}
Expand All @@ -75,7 +75,7 @@ public override void OnEnd(T data)
/// <inheritdoc/>
public override void OnStart(T data)
{
for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
cur.Value.OnStart(data);
}
Expand All @@ -85,7 +85,7 @@ internal override void SetParentProvider(BaseProvider parentProvider)
{
base.SetParentProvider(parentProvider);

for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
cur.Value.SetParentProvider(parentProvider);
}
Expand All @@ -99,7 +99,7 @@ protected override bool OnForceFlush(int timeoutMilliseconds)
? null
: Stopwatch.StartNew();

for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
if (sw == null)
{
Expand All @@ -125,7 +125,7 @@ protected override bool OnShutdown(int timeoutMilliseconds)
? null
: Stopwatch.StartNew();

for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
if (sw == null)
{
Expand All @@ -150,7 +150,7 @@ protected override void Dispose(bool disposing)
{
if (disposing)
{
for (var cur = this.head; cur != null; cur = cur.Next)
for (var cur = this.Head; cur != null; cur = cur.Next)
{
try
{
Expand All @@ -169,7 +169,7 @@ protected override void Dispose(bool disposing)
base.Dispose(disposing);
}

private class DoublyLinkedListNode
internal sealed class DoublyLinkedListNode
{
public readonly BaseProcessor<T> Value;

Expand Down
9 changes: 7 additions & 2 deletions src/OpenTelemetry/Logs/BatchLogRecordExportProcessor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -57,9 +57,14 @@ public override void OnEnd(LogRecord data)
// happen here.
Debug.Assert(data != null, "LogRecord was null.");

data!.BufferLogScopes();
data!.Buffer();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lets add a TODO to add a targeted test for testing #2905

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had some tests I did on #2932 so I just updated and added them to this PR.


base.OnEnd(data);
data.AddReference();

if (!this.TryExport(data))
{
LogRecordSharedPool.Current.Return(data);
utpilla marked this conversation as resolved.
Show resolved Hide resolved
}
}
}
}
101 changes: 93 additions & 8 deletions src/OpenTelemetry/Logs/LogRecord.cs
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using System.Threading;
using Microsoft.Extensions.Logging;
using OpenTelemetry.Internal;

Expand All @@ -30,15 +32,21 @@ namespace OpenTelemetry.Logs
public sealed class LogRecord
{
internal LogRecordData Data;
internal List<KeyValuePair<string, object?>>? AttributeStorage;
internal List<object?>? BufferedScopes;
internal int PoolReferenceCount = int.MaxValue;

private static readonly Action<object?, List<object?>> AddScopeToBufferedList = (object? scope, List<object?> state) =>
{
state.Add(scope);
};

private List<object?>? bufferedScopes;
internal LogRecord()
{
}

// Note: Some users are calling this with reflection. Try not to change the signature to be nice.
[Obsolete("Call LogRecordPool.Rent instead.")]
internal LogRecord(
IExternalScopeProvider? scopeProvider,
DateTime timestamp,
Expand Down Expand Up @@ -191,9 +199,9 @@ public void ForEachScope<TState>(Action<LogRecordScope, TState> callback, TState

var forEachScopeState = new ScopeForEachState<TState>(callback, state);

if (this.bufferedScopes != null)
if (this.BufferedScopes != null)
{
foreach (object? scope in this.bufferedScopes)
foreach (object? scope in this.BufferedScopes)
{
ScopeForEachState<TState>.ForEachScope(scope, forEachScopeState);
}
Expand All @@ -213,22 +221,99 @@ public void ForEachScope<TState>(Action<LogRecordScope, TState> callback, TState
return ref this.Data;
}

[MethodImpl(MethodImplOptions.AggressiveInlining)]
internal void ResetReferenceCount()
{
this.PoolReferenceCount = 1;
}

[MethodImpl(MethodImplOptions.AggressiveInlining)]
internal void AddReference()
{
Interlocked.Increment(ref this.PoolReferenceCount);
utpilla marked this conversation as resolved.
Show resolved Hide resolved
}

[MethodImpl(MethodImplOptions.AggressiveInlining)]
internal int RemoveReference()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Member Author

@CodeBlanch CodeBlanch Jun 24, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How passionately do you feel about this? I looked around, don't see any good example or prior art in .NET. AddRef w/ Release seems a bit odd for me for a .NET API. AddRef and RemoveRef I think would be better? Or AddRef w/ ReleaseRef.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

only 1% 😄

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

{
return Interlocked.Decrement(ref this.PoolReferenceCount);
}

// Note: Typically called when LogRecords are added into a batch so they
// can be safely processed outside of the log call chain.
internal void Buffer()
{
// Note: State values are buffered because some states are not safe
// to access outside of the log call chain. See:
// https://github.com/open-telemetry/opentelemetry-dotnet/issues/2905
this.BufferLogStateValues();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

add a comment/todo for "state" - do we need to do similar for state as well?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated


this.BufferLogScopes();

// Note: There is no buffering of "State" only "StateValues". We
// don't inspect "object State" at all. It is undefined what
// exporters will do with "State". Some might ignore it, some might
// attempt to access it as a list. That is potentially dangerous.
// TODO: Investigate what to do here. Should we obsolete State and
// just use the StateValues design?
}

internal LogRecord Copy()
{
// Note: We only buffer scopes here because state values are copied
// directly below.
this.BufferLogScopes();

return new()
{
Data = this.Data,
State = this.State,
StateValues = this.StateValues == null ? null : new List<KeyValuePair<string, object?>>(this.StateValues),
BufferedScopes = this.BufferedScopes == null ? null : new List<object?>(this.BufferedScopes),
};
}

/// <summary>
/// Buffers the state values attached to the log into a list so that
/// they can be safely processed after the log message lifecycle has
/// ended.
/// </summary>
private void BufferLogStateValues()
{
var stateValues = this.StateValues;
if (stateValues == null || stateValues == this.AttributeStorage)
{
return;
}

var attributeStorage = this.AttributeStorage ??= new List<KeyValuePair<string, object?>>(stateValues.Count);

// Note: AddRange here will copy all of the KeyValuePairs from
// stateValues to AttributeStorage. This "captures" the state and
// fixes issues where the values are generated at enumeration time
// like
// https://github.com/open-telemetry/opentelemetry-dotnet/issues/2905.
attributeStorage.AddRange(stateValues);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

add a comment this is what triggers the iteration/enumeration to "snap" what we need before things could get disposed.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Updated


this.StateValues = attributeStorage;
}

/// <summary>
/// Buffers the scopes attached to the log into a list so that they can
/// be safely processed after the log message lifecycle has ended.
/// </summary>
internal void BufferLogScopes()
private void BufferLogScopes()
{
if (this.ScopeProvider == null || this.bufferedScopes != null)
if (this.ScopeProvider == null)
{
return;
}

List<object?> scopes = new List<object?>();
List<object?> scopes = this.BufferedScopes ??= new List<object?>(LogRecordPoolHelper.DefaultMaxNumberOfScopes);

this.ScopeProvider?.ForEachScope(AddScopeToBufferedList, scopes);
this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopes);

this.bufferedScopes = scopes;
this.ScopeProvider = null;
}

private readonly struct ScopeForEachState<TState>
Expand Down
Loading