-
-
Notifications
You must be signed in to change notification settings - Fork 230
perf(logs): avoid string allocation when no parameters are passed #4697
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
base: main
Are you sure you want to change the base?
Changes from all commits
09ad86b
786ce11
77eb6af
ac8c995
91046c1
4f7d7c9
17a5ffe
4da13f3
afebf0a
5d1493d
ab926d9
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,14 @@ | ||
| ``` | ||
|
|
||
| BenchmarkDotNet v0.13.12, macOS 26.3.1 (a) (25D771280a) [Darwin 25.3.0] | ||
| Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores | ||
| .NET SDK 10.0.201 | ||
| [Host] : .NET 9.0.8 (9.0.825.36511), Arm64 RyuJIT AdvSIMD | ||
| DefaultJob : .NET 9.0.8 (9.0.825.36511), Arm64 RyuJIT AdvSIMD | ||
|
|
||
|
|
||
| ``` | ||
| | Method | Mean | Error | StdDev | Gen0 | Gen1 | Allocated | | ||
| |--------------------- |---------:|--------:|--------:|-------:|-------:|----------:| | ||
| | LogWithoutParameters | 102.3 ns | 1.28 ns | 1.19 ns | 0.0640 | 0.0001 | 536 B | | ||
| | LogWithParameters | 248.5 ns | 4.86 ns | 5.40 ns | 0.1087 | - | 912 B | | ||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,59 @@ | ||
| #nullable enable | ||
|
|
||
| using BenchmarkDotNet.Attributes; | ||
| using Sentry.Extensibility; | ||
| using Sentry.Internal; | ||
| using Sentry.Testing; | ||
|
|
||
| namespace Sentry.Benchmarks; | ||
|
|
||
| public class SentryStructuredLoggerBenchmarks | ||
| { | ||
| private Hub _hub = null!; | ||
| private SentryStructuredLogger _logger = null!; | ||
|
|
||
| private SentryLog? _lastLog; | ||
|
|
||
| [GlobalSetup] | ||
| public void Setup() | ||
| { | ||
| SentryOptions options = new() | ||
| { | ||
| Dsn = DsnSamples.ValidDsn, | ||
| EnableLogs = true, | ||
| }; | ||
| options.SetBeforeSendLog((SentryLog log) => | ||
| { | ||
| _lastLog = log; | ||
| return null; | ||
| }); | ||
|
|
||
| MockClock clock = new(new DateTimeOffset(2025, 04, 22, 14, 51, 00, 789, TimeSpan.FromHours(2))); | ||
|
|
||
| _hub = new Hub(options, DisabledHub.Instance); | ||
| _logger = SentryStructuredLogger.Create(_hub, options, clock); | ||
| } | ||
|
|
||
| [Benchmark] | ||
| public void LogWithoutParameters() | ||
| { | ||
| _logger.LogInfo("Message Text"); | ||
| } | ||
|
|
||
| [Benchmark] | ||
| public void LogWithParameters() | ||
| { | ||
| _logger.LogInfo("Template string with arguments: {0}, {1}, {2}, {3}", "string", true, 1, 2.2); | ||
| } | ||
|
|
||
| [GlobalCleanup] | ||
| public void Cleanup() | ||
| { | ||
| _hub.Dispose(); | ||
|
|
||
| if (_lastLog is null) | ||
| { | ||
| throw new InvalidOperationException("Last Log is null"); | ||
| } | ||
| } | ||
| } |
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -30,26 +30,33 @@ private protected override void CaptureLog(SentryLogLevel level, string template | |
| _hub.GetTraceIdAndSpanId(out var traceId, out var spanId); | ||
|
|
||
| string message; | ||
| try | ||
| { | ||
| message = string.Format(CultureInfo.InvariantCulture, template, parameters ?? []); | ||
| } | ||
| catch (FormatException e) | ||
| { | ||
| _options.DiagnosticLogger?.LogError(e, "Template string does not match the provided argument. The Log will be dropped."); | ||
| return; | ||
| } | ||
| ImmutableArray<KeyValuePair<string, object>> @params; | ||
|
|
||
| ImmutableArray<KeyValuePair<string, object>> @params = default; | ||
| if (parameters is { Length: > 0 }) | ||
| { | ||
| try | ||
| { | ||
| message = string.Format(CultureInfo.InvariantCulture, template, parameters); | ||
| } | ||
| catch (FormatException e) | ||
| { | ||
| _options.DiagnosticLogger?.LogError(e, "Template string does not match the provided argument. The Log will be dropped."); | ||
| return; | ||
| } | ||
|
|
||
| var builder = ImmutableArray.CreateBuilder<KeyValuePair<string, object>>(parameters.Length); | ||
| for (var index = 0; index < parameters.Length; index++) | ||
| { | ||
| builder.Add(new KeyValuePair<string, object>(index.ToString(), parameters[index])); | ||
| } | ||
| @params = builder.DrainToImmutable(); | ||
| } | ||
| else | ||
| { | ||
| message = template; | ||
| template = null!; // SentryLog.Template is declared nullable (string?) | ||
| @params = ImmutableArray<KeyValuePair<string, object>>.Empty; | ||
|
Comment on lines
+56
to
+58
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. question: Breaking Change? This improvement is - technically speaking - also a behavioral (breaking?) change, when Logging a plain message without positional arguments, observable by user code through the options.SetBeforeSendLog(static (SentryLog log) =>
{
_ = (log.Message, log.Template, log.Parameters);
return log;
});No changes to the resulting serialized payload, though - we have a check in place that does not serialize a when Logging without positional Parameters: e.g.
Another benefit of when Logging with positional Parameters: e.g.
See also https://develop.sentry.dev/sdk/telemetry/logs/#default-attributes.
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. and a follow-up question: Shall we note this in the CHANGELOG? |
||
| } | ||
|
|
||
| SentryLog log = new(timestamp, traceId, level, message) | ||
| { | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -25,6 +25,8 @@ internal SentryLog(DateTimeOffset timestamp, SentryId traceId, SentryLogLevel le | |
| Message = message; | ||
| // 7 is the number of built-in attributes, so we start with that. | ||
| _attributes = new Dictionary<string, SentryAttribute>(7); | ||
| // ensure the ImmutableArray`1 is not default, so we can omit IsDefault checks before accessing other members | ||
| Parameters = ImmutableArray<KeyValuePair<string, object>>.Empty; | ||
|
Comment on lines
+28
to
+29
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. note: this ensures that the In But in the down-stream
With this assignment, we ensure that it's never |
||
| } | ||
|
|
||
| /// <summary> | ||
|
|
@@ -58,7 +60,15 @@ internal SentryLog(DateTimeOffset timestamp, SentryId traceId, SentryLogLevel le | |
| /// <summary> | ||
| /// The parameters to the template string. | ||
| /// </summary> | ||
| public ImmutableArray<KeyValuePair<string, object>> Parameters { get; init; } | ||
| public ImmutableArray<KeyValuePair<string, object>> Parameters | ||
| { | ||
| get; | ||
| init | ||
| { | ||
| Debug.Assert(!value.IsDefault); // DEBUG-only check, because .ctor is internal and set-accessor is init-only | ||
| field = value; | ||
| } | ||
| } | ||
|
|
||
| /// <summary> | ||
| /// The span id of the span that was active when the log was collected. | ||
|
|
@@ -190,6 +200,8 @@ internal void SetOrigin(string origin) | |
|
|
||
| internal void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) | ||
| { | ||
| Debug.Assert(!Parameters.IsDefault); | ||
|
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. note: omit default checks Since we ensured in the |
||
|
|
||
| writer.WriteStartObject(); | ||
|
|
||
| #if NET9_0_OR_GREATER | ||
|
|
@@ -222,17 +234,14 @@ internal void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) | |
|
|
||
| // the SDK MUST NOT attach a sentry.message.template attribute if there are no parameters | ||
| // https://develop.sentry.dev/sdk/telemetry/logs/#default-attributes | ||
| if (Template is not null && !Parameters.IsDefaultOrEmpty) | ||
| if (Template is not null && !Parameters.IsEmpty) | ||
| { | ||
| SentryAttributeSerializer.WriteStringAttribute(writer, "sentry.message.template", Template); | ||
| } | ||
|
|
||
| if (!Parameters.IsDefault) | ||
| foreach (var parameter in Parameters) | ||
| { | ||
| foreach (var parameter in Parameters) | ||
| { | ||
| SentryAttributeSerializer.WriteAttribute(writer, $"sentry.message.parameter.{parameter.Key}", parameter.Value, logger); | ||
| } | ||
| SentryAttributeSerializer.WriteAttribute(writer, $"sentry.message.parameter.{parameter.Key}", parameter.Value, logger); | ||
| } | ||
|
|
||
| foreach (var attribute in _attributes) | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -22,6 +22,20 @@ public SentryMetricTests(ITestOutputHelper output) | |
| _output = new TestOutputDiagnosticLogger(output); | ||
| } | ||
|
|
||
| [Fact] | ||
| public void Create_Default_HasMinimalSpecification() | ||
|
Comment on lines
+25
to
+26
Member
Author
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. note: I wanted to keep the tests for both Logs and Metrics in sync |
||
| { | ||
| var metric = new SentryMetric<int>(Timestamp, TraceId, SentryMetricType.Counter, "sentry_tests.sentry_metric_tests.counter", 1); | ||
|
|
||
| metric.Timestamp.Should().Be(Timestamp); | ||
| metric.TraceId.Should().Be(TraceId); | ||
| metric.Type.Should().Be(SentryMetricType.Counter); | ||
| metric.Name.Should().Be("sentry_tests.sentry_metric_tests.counter"); | ||
| metric.Value.Should().Be(1); | ||
| metric.SpanId.Should().Be(null); | ||
| metric.Unit.Should().BeEquivalentTo(null); | ||
| } | ||
|
|
||
| [Fact] | ||
| public void Protocol_Default_VerifyAttributes() | ||
| { | ||
|
|
||
Uh oh!
There was an error while loading. Please reload this page.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
note: perf comparison
Before this change:
After this change:
Result:
System.String.Format