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.

Sign up for GitHub

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

LogEmitter System.Diagnostics.Tracing extension project #3305

Closed
wants to merge 53 commits into from
Closed

LogEmitter System.Diagnostics.Tracing extension project #3305

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
53 commits
Select commit Hold shift + click to select a range
6d2f153
LogEmitter API.
CodeBlanch May 24, 2022
101ce19
Code review.
CodeBlanch May 25, 2022
7eb0006
Added LogRecordPool.
CodeBlanch May 26, 2022
20479f5
Nullable annotation updates.
CodeBlanch May 26, 2022
c64ca11
Merge branch 'main' into log-emitter
CodeBlanch May 26, 2022
53a6854
Cleanup.
CodeBlanch May 26, 2022
fd5a87e
Cleanup.
CodeBlanch May 26, 2022
035823b
Added reference counting into the log record pool.
CodeBlanch May 26, 2022
80cbdbb
Tweaks.
CodeBlanch May 28, 2022
744c399
Tweak.
CodeBlanch May 29, 2022
df93cf5
Test fix.
CodeBlanch May 29, 2022
1ba8afe
Merge branch 'main' into log-emitter
CodeBlanch May 29, 2022
9a0ee32
Test fix.
CodeBlanch May 29, 2022
888eb54
Rename.
CodeBlanch May 30, 2022
558e8d2
Trigger state buffering by processor inspection.
CodeBlanch May 31, 2022
4d76b87
Implement copy for in-memory log exporter.
CodeBlanch May 31, 2022
617d88d
Added GetDataRef.
CodeBlanch May 31, 2022
ca7e319
Tweaks.
CodeBlanch May 31, 2022
6fae76d
Merge branch 'main' into log-emitter
CodeBlanch May 31, 2022
a92e78e
Revert CompositeProcessor change.
CodeBlanch May 31, 2022
5e33474
Add log stress tests to solution.
CodeBlanch May 31, 2022
6b15b3b
Tweaks.
CodeBlanch May 31, 2022
2114dca
Code review.
CodeBlanch Jun 1, 2022
0d34533
Code review, example app, serilog + eventsource extensions.
CodeBlanch Jun 2, 2022
bb4293c
Rename.
CodeBlanch Jun 2, 2022
380f139
Typo.
CodeBlanch Jun 2, 2022
87597f8
New pool design + tests.
CodeBlanch Jun 6, 2022
345e1a2
Pool selection based on processor.
CodeBlanch Jun 6, 2022
ea63af4
Merge from main.
CodeBlanch Jun 7, 2022
a12d432
Update public api files.
CodeBlanch Jun 7, 2022
3b35268
Public api fix.
CodeBlanch Jun 7, 2022
57775a5
Lint and race comment.
CodeBlanch Jun 7, 2022
9ee18df
Comments in log emitter example app.
CodeBlanch Jun 7, 2022
f347e51
Switch to Volatile.Read.
CodeBlanch Jun 7, 2022
5537c73
Bump Microsoft.DotNet.ApiCompat.
CodeBlanch Jun 7, 2022
e0c2347
Typo fix.
CodeBlanch Jun 7, 2022
dd80cc9
Bump Microsoft.DotNet.ApiCompat.
CodeBlanch Jun 7, 2022
4f6b9e0
Attempting to fix ApiCompat failure.
CodeBlanch Jun 7, 2022
1dcd193
Tweak ApiCompatExcludeAttributeList path.
CodeBlanch Jun 7, 2022
226facf
Exclude NullableContextAttribute from ApiCompat.
CodeBlanch Jun 7, 2022
d3c5443
Merge from main.
CodeBlanch Jun 15, 2022
31f5a97
Merge from main.
CodeBlanch Jun 16, 2022
cb69e49
Fix merge.
CodeBlanch Jun 16, 2022
8693d93
Merge from main.
CodeBlanch Jun 17, 2022
b71006f
Updates.
CodeBlanch Jun 17, 2022
6269015
Merge from main.
CodeBlanch Jun 18, 2022
7647145
Revert OtlpLogExporter use of logRecord.GetDataRef because it is now …
CodeBlanch Jun 18, 2022
4f498af
Merge branch 'main' into log-emitter
cijothomas Jun 27, 2022
55537b5
Merge from main.
CodeBlanch Jun 30, 2022
d1a4b3b
Merge fix.
CodeBlanch Jun 30, 2022
ffda1ce
Merge from main.
CodeBlanch Jul 11, 2022
12c92ad
Merge from main.
CodeBlanch Jul 18, 2022
cf69b8c
Updates.
CodeBlanch Jul 18, 2022
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
Prev Previous commit
Next Next commit
Added GetDataRef.
  • Loading branch information
@CodeBlanch
CodeBlanch committed May 31, 2022
commit 617d88d96691e9b9c47ad9496ae75a78e85c567f
39 changes: 20 additions & 19 deletions src/OpenTelemetry.Exporter.OpenTelemetryProtocol/Implementation/LogRecordExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,30 +65,31 @@ internal static void AddBatch(
internal static OtlpLogs.LogRecord ToOtlpLog(this LogRecord logRecord)
{
OtlpLogs.LogRecord otlpLogRecord = null;
ref LogRecordData data = ref logRecord.GetDataRef();
Copy link
Member

Choose a reason for hiding this comment

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

Just confirming my own understanding of the improvements this PR brings... so this is more performant because accessing properties of the struct results in a call vs. callvirt, right?

Copy link
Member Author

Choose a reason for hiding this comment

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

This particular change is more to prevent a perf regression! This method used to work something like...

ldarg.1 -> call LogRecord.CategoryName.Get() -> ldfld CategoryName_Backing -> ret

(Because LogRecord is sealed it should already be a call instead of callvirt.)

Now due to the pooling changes it has to do...

ldarg.1 -> call LogRecord.CategoryName.Get() -> ldflda this.logRecordData -> call LogRecordData.CategoryName.Get() -> ldfld CategoryName_Backing -> ret

Extra call!

Using GetDataRef() it goes back to a single call like...

ldflda [address of ref] -> call LogRecordData.CategoryName.Get()-> ldfld CategoryName_Backing -> ret

Just an optimization to cut out the extra hops.

True perf really comes down to how the JIT decides to inline things. Here's a sharplab if you want to mess with it.

Copy link
Member Author

Choose a reason for hiding this comment

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

So what are the real perf gains on this PR?

I will attempt to answer this 😄

Our log logic was like this:

                var record = new LogRecord(
                    provider.IncludeScopes ? this.ScopeProvider : null,
                    DateTime.UtcNow,
                    this.categoryName,
                    logLevel,
                    eventId,
                    provider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null,
                    provider.ParseStateValues ? null : state,
                    exception,
                    provider.ParseStateValues ? this.ParseState(state) : null);

                processor.OnEnd(record);

                record.ScopeProvider = null;

And is now like this:

                var record = LogRecordPool.Rent();

                record.ScopeProvider = provider.IncludeScopes ? this.ScopeProvider : null;
                record.State = provider.ParseStateValues ? null : state;
                record.StateValues = provider.ParseStateValues ? this.ParseState(record, state) : null;

                ref LogRecordData data = ref record.Data;

                data.TimestampBacking = DateTime.UtcNow;
                data.CategoryName = this.categoryName;
                data.LogLevel = logLevel;
                data.EventId = eventId;
                data.Message = provider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null;
                data.Exception = exception;

                LogRecordData.SetActivityContext(ref data, Activity.Current);

                processor.OnEnd(record);

                record.ScopeProvider = null;

                // Attempt to return the LogRecord to the pool. This will no-op
                // if a batch exporter has added a reference.
                LogRecordPool.Return(record);

Should be slower, right?

Turns out, is only slightly slower (when hitting the [ThreadStatic]):

Method Mean Error StdDev Gen 0 Allocated
LogUsingCtor 38.89 ns 0.154 ns 0.137 ns 0.0102 128 B
LogUsingPool 40.37 ns 0.054 ns 0.048 ns - -

But we eliminated all the memory pressure. I think this is why the stress test is performing better with the pool. Only a few more CPU cycles to use the pool but the GC is asleep freeing up the CPU to process more logs. This is a largely a guess but kind of makes sense?

Now that benchmark is interesting. How is it introducing the pool logic made it only slightly slower than just calling ctor?

Check out this benchmark:

    public class CtorBenchmarks
    {
        [Benchmark]
        public TestSmallClass CtorSmallClass()
        {
            return new();
        }

        [Benchmark]
        public TestLargeClass CtorLargeClass()
        {
            return new();
        }

        public class TestSmallClass
        {
            public string? Prop1;
        }

        public class TestLargeClass
        {
            public string? Prop1;
            public string? Prop2;
            public string? Prop3;
            public int Prop4;
            public int Prop5;
            public int Prop6;
            public DateTime Prop7;
            public object? Prop8;
            public object? Prop9;
            public object? Prop10;
            public string? Prop11;
            public string? Prop12;
            public string? Prop13;
        }
    }
Method Mean Error StdDev Gen 0 Allocated
CtorSmallClass 1.884 ns 0.0236 ns 0.0209 ns 0.0019 24 B
CtorLargeClass 3.982 ns 0.0298 ns 0.0279 ns 0.0089 112 B

Number of fields on the class impacts the ctor time. LogRecord has a lot of fields so that gives us some wiggle room to execute our pool logic before just calling the ctor would be faster. Interesting, eh?


try
{
otlpLogRecord = new OtlpLogs.LogRecord
{
TimeUnixNano = (ulong)logRecord.Timestamp.ToUnixTimeNanoseconds(),
SeverityNumber = GetSeverityNumber(logRecord.LogLevel),
SeverityText = LogLevels[(int)logRecord.LogLevel],
TimeUnixNano = (ulong)data.Timestamp.ToUnixTimeNanoseconds(),
SeverityNumber = GetSeverityNumber(data.LogLevel),
SeverityText = LogLevels[(int)data.LogLevel],
};

if (!string.IsNullOrEmpty(logRecord.CategoryName))
if (!string.IsNullOrEmpty(data.CategoryName))
{
// TODO:
// 1. Track the following issue, and map CategoryName to Name
// if it makes it to log data model.
// https://github.com/open-telemetry/opentelemetry-specification/issues/2398
// 2. Confirm if this name for attribute is good.
otlpLogRecord.Attributes.AddStringAttribute("dotnet.ilogger.category", logRecord.CategoryName);
otlpLogRecord.Attributes.AddStringAttribute("dotnet.ilogger.category", data.CategoryName);
}

bool bodyPopulatedFromFormattedMessage = false;
if (logRecord.FormattedMessage != null)
if (data.Message != null)
{
otlpLogRecord.Body = new OtlpCommon.AnyValue { StringValue = logRecord.FormattedMessage };
otlpLogRecord.Body = new OtlpCommon.AnyValue { StringValue = data.Message };
bodyPopulatedFromFormattedMessage = true;
}

Expand All @@ -110,34 +111,34 @@ internal static OtlpLogs.LogRecord ToOtlpLog(this LogRecord logRecord)
}
}

if (logRecord.EventId.Id != default)
if (data.EventId.Id != default)
{
otlpLogRecord.Attributes.AddIntAttribute(nameof(logRecord.EventId.Id), logRecord.EventId.Id);
otlpLogRecord.Attributes.AddIntAttribute(nameof(data.EventId.Id), data.EventId.Id);
}

if (!string.IsNullOrEmpty(logRecord.EventId.Name))
if (!string.IsNullOrEmpty(data.EventId.Name))
{
otlpLogRecord.Attributes.AddStringAttribute(nameof(logRecord.EventId.Name), logRecord.EventId.Name);
otlpLogRecord.Attributes.AddStringAttribute(nameof(data.EventId.Name), data.EventId.Name);
}

if (logRecord.Exception != null)
if (data.Exception != null)
{
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionType, logRecord.Exception.GetType().Name);
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionMessage, logRecord.Exception.Message);
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionStacktrace, logRecord.Exception.ToInvariantString());
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionType, data.Exception.GetType().Name);
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionMessage, data.Exception.Message);
otlpLogRecord.Attributes.AddStringAttribute(SemanticConventions.AttributeExceptionStacktrace, data.Exception.ToInvariantString());
}

if (logRecord.TraceId != default && logRecord.SpanId != default)
if (data.TraceId != default && data.SpanId != default)
{
byte[] traceIdBytes = new byte[16];
byte[] spanIdBytes = new byte[8];

logRecord.TraceId.CopyTo(traceIdBytes);
logRecord.SpanId.CopyTo(spanIdBytes);
data.TraceId.CopyTo(traceIdBytes);
data.SpanId.CopyTo(spanIdBytes);

otlpLogRecord.TraceId = UnsafeByteOperations.UnsafeWrap(traceIdBytes);
otlpLogRecord.SpanId = UnsafeByteOperations.UnsafeWrap(spanIdBytes);
otlpLogRecord.Flags = (uint)logRecord.TraceFlags;
otlpLogRecord.Flags = (uint)data.TraceFlags;
}

int scopeDepth = -1;
Expand Down
1 change: 1 addition & 0 deletions src/OpenTelemetry/.publicApi/net462/PublicAPI.Unshipped.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ OpenTelemetry.Logs.LogEmitter
OpenTelemetry.Logs.LogEmitter.Log(in OpenTelemetry.Logs.LogRecordData data, in OpenTelemetry.Logs.LogRecordAttributeList attributes = default(OpenTelemetry.Logs.LogRecordAttributeList)) -> void
OpenTelemetry.Logs.LogEmitter.LogEmitter(OpenTelemetry.Logs.OpenTelemetryLoggerProvider! loggerProvider) -> void
OpenTelemetry.Logs.LogRecord.FormattedMessage.set -> void
OpenTelemetry.Logs.LogRecord.GetDataRef() -> OpenTelemetry.Logs.LogRecordData
OpenTelemetry.Logs.LogRecord.State.set -> void
OpenTelemetry.Logs.LogRecord.StateValues.set -> void
OpenTelemetry.Logs.LogRecordAttributeList
Copy link
Member

Choose a reason for hiding this comment

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

Since .NET uses the term Tag for metrics and traces, should we stay consistent and call 'em tags for logs 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.

I struggled with that one. We have State & StateValues on LogRecord today. The most consistent thing might be to name this LogRecordStateValueList and not introduce another concept? I ended up going with "attributes" because that is what the spec calls them and the LogEmitter API right now is pretty close to spec but open to whatever.

Copy link
Member

Choose a reason for hiding this comment

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

🤔 yea I hear ya on the struggle. I think sticking to Attribute to align with the spec might make sense in this context. Though also maybe this is a good enough reason to make LogRecordAttributeList internal for now. I guess I'm not too clear yet how all this may play out in the context of a logging framework besides ILogger.

Copy link
Member Author

Choose a reason for hiding this comment

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

Pretty much, just ignore ILogger 😄 What LogEmitter does is take a LogRecord from the pool, applies the LogRecordData + LogRecordAttributeList to it, and then sends it at the LogProcessor at the root of the OpenTelemetryLoggerProvider. It doesn't really flow through ILogger at all.

I haven't tested this yet, but to help illustrate here is the Serilog sink I scratched out to mess with the LogEmitter API:

    public static class OpenTelemetrySerilogSinkExtensions
    {
        public static LoggerConfiguration OpenTelemetry(
            this LoggerSinkConfiguration loggerConfiguration,
            OpenTelemetryLoggerProvider openTelemetryLoggerProvider)
        {
            Guard.ThrowIfNull(loggerConfiguration);

            return loggerConfiguration.Sink(new OpenTelemetrySerilogSink(openTelemetryLoggerProvider));
        }
    }

    internal sealed class OpenTelemetrySerilogSink : ILogEventSink
    {
        private readonly LogEmitter logEmitter;

        public OpenTelemetrySerilogSink(OpenTelemetryLoggerProvider openTelemetryLoggerProvider)
        {
            this.logEmitter = new LogEmitter(openTelemetryLoggerProvider);
        }

        public void Emit(LogEvent logEvent)
        {
            Debug.Assert(logEvent != null, "LogEvent was null.");

            LogRecordData data = new(Activity.Current)
            {
                Timestamp = logEvent!.Timestamp.UtcDateTime,
                LogLevel = (LogLevel)(int)logEvent.Level,
                Message = logEvent.MessageTemplate.Text,
                Exception = logEvent.Exception,
            };

            LogRecordAttributeList attributes = default;
            foreach (KeyValuePair<string, LogEventPropertyValue> property in logEvent.Properties)
            {
                // TODO: Serilog supports complex type logging. This is not yet
                // supported in OpenTelemetry.
                if (property.Key == Constants.SourceContextPropertyName)
                {
                    data.CategoryName = property.Value.ToString();
                }
                else if (property.Value is ScalarValue scalarValue)
                {
                    attributes.Add(property.Key, scalarValue.Value);
                }
                else if (property.Value is SequenceValue sequenceValue)
                {
                    IReadOnlyList<LogEventPropertyValue> elements = sequenceValue.Elements;
                    if (elements.Count > 0 && elements[0] is ScalarValue)
                    {
                        object[] values = new object[elements.Count];
                        for (int i = 0; i < elements.Count; i++)
                        {
                            if (elements[i] is ScalarValue value)
                            {
                                values[i] = value.Value;
                            }
                        }

                        attributes.Add(property.Key, values);
                    }
                }
            }

            this.logEmitter.Log(in data, in attributes);
        }
    }

Copy link
Member

Choose a reason for hiding this comment

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

Cool, yea this example is great. Is the reason due to size/performance that LogRecordData doesn't have an LogRecordAttributeList field? ... Oh, or maybe the reason is that if you were to do this.logEmitter.Log(in data) that the in data parameter would not preclude the attributes from being modified.

Copy link
Member Author

Choose a reason for hiding this comment

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

Originally I had the attributes as a field on LogRecordData but I ran into some weird compiler limitations. What I wanted to do was allow people to do this...

logEmitter.Log(new()
{
   Message = "Hello world",
   Attributes = { ["count" ] = 1, ["id"] = 18 }
})

That would work if "Attributes" was a reference type, but compiler doesn't allow with a value type! I tried a bunch of things, ultimately moved it to a separate parameter. At the moment you can do...

logEmitter.Log(
   new() { Message = "Hello world" },
   new() { ["count" ] = 1, ["id"] = 18 }
})

Besides that...

  • Having it separate keeps the size of LogRecordData down. Now LogRecords live in a pool and store a LogRecordData. Having the "attributes" as part of LogRecordData would mean that pool would take up a bunch more memory.

  • I could see people mess it up. Imagine something like this...

    LogRecord data = new()
{
   Message = "Hello world"
};

BuildAttributes(data.Attributes); // This passes a copy. So anything added in the method won't really be added.

logEmitter.Log(in data);

  • Having it separate leaves some room for expansion. What I'm working towards here is potentially using LogEmitter to support logging of complex types. Maybe the API will end up like this:

    LogEmitter.Log(in LogRecordData data, in LogRecordAttributeList attributes = default, in LogRecordObjectWriter objectWriter = default)

    Basically you always pass in the core sutff, but then you can pass in other things that depend on the case. I have no idea what it will ultimately look like but something I'm thinking about.

At one point I tried a builder pattern like...

logEmitter.Log(new()
   .SetMessage("Hello world")
   .AddAttribute("count", 1))

But that is tricky to do with a struct. Each time you return the struct it is a new copy so you have to write it like public static ref LogRecordBuilder SetMessage(this ref LogRecordBuilder builder). Seemed gross 🤣

Expand Down
1 change: 1 addition & 0 deletions src/OpenTelemetry/.publicApi/netstandard2.0/PublicAPI.Unshipped.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@ OpenTelemetry.Logs.LogEmitter
OpenTelemetry.Logs.LogEmitter.Log(in OpenTelemetry.Logs.LogRecordData data, in OpenTelemetry.Logs.LogRecordAttributeList attributes = default(OpenTelemetry.Logs.LogRecordAttributeList)) -> void
OpenTelemetry.Logs.LogEmitter.LogEmitter(OpenTelemetry.Logs.OpenTelemetryLoggerProvider! loggerProvider) -> void
OpenTelemetry.Logs.LogRecord.FormattedMessage.set -> void
OpenTelemetry.Logs.LogRecord.GetDataRef() -> OpenTelemetry.Logs.LogRecordData
OpenTelemetry.Logs.LogRecord.State.set -> void
OpenTelemetry.Logs.LogRecord.StateValues.set -> void
OpenTelemetry.Logs.LogRecordAttributeList
Expand Down
9 changes: 9 additions & 0 deletions src/OpenTelemetry/Logs/LogRecord.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -176,6 +176,15 @@ public void ForEachScope<TState>(Action<LogRecordScope, TState> callback, TState
}
}

/// <summary>
/// Gets a reference to the <see cref="LogRecordData"/> for the log message.
/// </summary>
/// <returns><see cref="LogRecordData"/>.</returns>
public ref LogRecordData GetDataRef()
{
return ref this.Data;
}

/// <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.
Expand Down