[Test Optimization] perf: logging/timing helpers #8070
+622
−92
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
tonyredondo
changed the title
This was referenced Jan 15, 2026
BenchmarksBenchmark execution time: 2026-01-19 10:03:11 Comparing candidate commit 4a649b1 in PR branch Found 10 performance improvements and 7 performance regressions! Performance is the same for 157 metrics, 18 unstable metrics. scenario:Benchmarks.Trace.Asm.AppSecBodyBenchmark.AllCycleSimpleBody netcoreapp3.1
scenario:Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody netcoreapp3.1
scenario:Benchmarks.Trace.Asm.AppSecEncoderBenchmark.EncodeLegacyArgs net6.0
scenario:Benchmarks.Trace.Asm.AppSecEncoderBenchmark.EncodeLegacyArgs netcoreapp3.1
scenario:Benchmarks.Trace.AspNetCoreBenchmark.SendRequest netcoreapp3.1
scenario:Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces net472
scenario:Benchmarks.Trace.CharSliceBenchmark.OptimizedCharSliceWithPool net6.0
scenario:Benchmarks.Trace.CharSliceBenchmark.OriginalCharSlice net6.0
scenario:Benchmarks.Trace.DbCommandBenchmark.ExecuteNonQuery netcoreapp3.1
scenario:Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark net6.0
scenario:Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark netcoreapp3.1
scenario:Benchmarks.Trace.SerilogBenchmark.EnrichedLog netcoreapp3.1
scenario:Benchmarks.Trace.SpanBenchmark.StartFinishScope net472
scenario:Benchmarks.Trace.SpanBenchmark.StartFinishTwoScopes net472
|
tonyredondo
force-pushed
the
tony/testoptimization-performance-work-pr1
branch
from
ad6c32d to
f0ccdd2
Compare
Execution-Time Benchmarks Report ⏱️Execution-time results for samples comparing This PR (8070) and master. ✅ No regressions detected - check the details below Full Metrics ComparisonFakeDbCommand
HttpMessageHandler
Comparison explanationExecution-time benchmarks measure the whole time it takes to execute a program, and are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are highlighted in **red**. The following thresholds were used for comparing the execution times:
Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard. Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph). Duration chartsFakeDbCommand (.NET Framework 4.8)gantt
title Execution time (ms) FakeDbCommand (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (68ms) : 67, 70
master - mean (68ms) : 67, 70
section Bailout
This PR (8070) - mean (72ms) : 71, 73
master - mean (72ms) : 71, 73
section CallTarget+Inlining+NGEN
This PR (8070) - mean (1,012ms) : 944, 1079
master - mean (1,013ms) : 943, 1082
FakeDbCommand (.NET Core 3.1)gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (106ms) : 104, 108
master - mean (106ms) : 103, 108
section Bailout
This PR (8070) - mean (107ms) : 106, 108
master - mean (107ms) : 105, 108
section CallTarget+Inlining+NGEN
This PR (8070) - mean (743ms) : 695, 792
master - mean (736ms) : 685, 786
FakeDbCommand (.NET 6)gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (94ms) : 92, 96
master - mean (94ms) : 92, 96
section Bailout
This PR (8070) - mean (95ms) : 94, 96
master - mean (94ms) : 93, 95
section CallTarget+Inlining+NGEN
This PR (8070) - mean (715ms) : 673, 757
master - mean (715ms) : 680, 750
FakeDbCommand (.NET 8)gantt
title Execution time (ms) FakeDbCommand (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (92ms) : 89, 94
master - mean (92ms) : 90, 95
section Bailout
This PR (8070) - mean (93ms) : 92, 94
master - mean (93ms) : 92, 95
section CallTarget+Inlining+NGEN
This PR (8070) - mean (637ms) : 622, 653
master - mean (636ms) : 622, 651
HttpMessageHandler (.NET Framework 4.8)gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (193ms) : 188, 198
master - mean (192ms) : 188, 196
section Bailout
This PR (8070) - mean (196ms) : 194, 198
master - mean (195ms) : 193, 198
section CallTarget+Inlining+NGEN
This PR (8070) - mean (1,132ms) : 1067, 1197
master - mean (1,124ms) : 1053, 1195
HttpMessageHandler (.NET Core 3.1)gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (277ms) : 271, 283
master - mean (275ms) : 270, 280
section Bailout
This PR (8070) - mean (277ms) : 271, 282
master - mean (276ms) : 271, 280
section CallTarget+Inlining+NGEN
This PR (8070) - mean (930ms) : 885, 976
master - mean (926ms) : 880, 972
HttpMessageHandler (.NET 6)gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (271ms) : 265, 278
master - mean (269ms) : 264, 274
section Bailout
This PR (8070) - mean (269ms) : 265, 274
master - mean (268ms) : 265, 272
section CallTarget+Inlining+NGEN
This PR (8070) - mean (935ms) : 887, 982
master - mean (916ms) : 855, 976
HttpMessageHandler (.NET 8)gantt
title Execution time (ms) HttpMessageHandler (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8070) - mean (273ms) : 261, 284
master - mean (268ms) : 263, 272
section Bailout
This PR (8070) - mean (269ms) : 265, 274
master - mean (268ms) : 263, 273
section CallTarget+Inlining+NGEN
This PR (8070) - mean (833ms) : 813, 852
master - mean (829ms) : 811, 847
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
This comment has been minimized.
This comment has been minimized.
tonyredondo
commented
Jan 16, 2026
| { | ||
| // Tells us which types are loaded, when, and how often. | ||
| SharedLogger.Debug("Logger retrieved for: {AssemblyQualifiedName}", classType.AssemblyQualifiedName); | ||
| if (SharedLogger.IsEnabled(LogEventLevel.Debug)) |
Member
Author
There was a problem hiding this comment.
RuntimeType.AssemblyQualifiedName always allocates a new string and do some internals QCalls, is fast but we can avoid it.
tonyredondo
commented
Jan 16, 2026
Comment on lines
+219
to
+220
| using var array = FixedSizeArrayPool<object?>.OneItemPool.Get(); | ||
| array.Array[0] = property; |
Member
Author
There was a problem hiding this comment.
previously we allocate an array for every single log line, here the idea is to have a small pool for it and reuse it.
tonyredondo
commented
Jan 16, 2026
| { | ||
| [MethodImpl(MethodImplOptions.AggressiveInlining)] | ||
| get => _utcStart.Add(Elapsed); | ||
| get => _utcStart.AddTicks(StopwatchHelpers.GetElapsedTicks(Stopwatch.GetTimestamp() - _timestamp)); |
Member
Author
There was a problem hiding this comment.
we really don't need to create a TimeSpan struct for this by calling Elapsed, we just count the ticks and add them.
Member
There was a problem hiding this comment.
is this measurably faster?
Member
Author
There was a problem hiding this comment.
not in recent frameworks, in olders frameworks the codegen is just a little better.
tonyredondo
commented
Jan 16, 2026
|
|
||
| namespace Datadog.Trace.Util; | ||
|
|
||
| internal struct CodeDuration : IDisposable |
Member
Author
There was a problem hiding this comment.
This is the version for use in an async/await method because we cannot use ref struct there. So creating a CodeDuration in that case will allocate in the heap (struct boxing).
Below there's the ref struct version to avoid any heap allocation in a normal sync method.
tonyredondo
commented
Jan 16, 2026
| } | ||
| } | ||
|
|
||
| internal ref struct CodeDurationRef |
Member
Author
There was a problem hiding this comment.
ref struct version to avoid an allocation in the heap.
tonyredondo
commented
Jan 16, 2026
| #endif | ||
|
|
||
| #if NETCOREAPP3_0_OR_GREATER | ||
| if (RuntimeHelpers.IsReferenceOrContainsReferences<T>()) |
Member
Author
There was a problem hiding this comment.
we clear the array if we know that T is a reference type (so we don't hold any reference from the GC)
tonyredondo
commented
Jan 16, 2026
|
|
||
| namespace Datadog.Trace.Util; | ||
|
|
||
| internal ref struct RefStopwatch |
Member
Author
There was a problem hiding this comment.
normal Stopwatch is a class, and we use multiple in the Initialization and in some of the CI visibility hotpath.
This version doesn't allocate (ref struct) but it's only useful in sync method, for async method is better to use the existing Stopwatch.
Member
There was a problem hiding this comment.
Should we include this as a code comment?
tonyredondo
force-pushed
the
tony/testoptimization-performance-work-pr1
branch
from
7a2fadb to
c58aa40
Compare
anmarchenko
approved these changes
Jan 16, 2026
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Summary of changes
Reason for change
Reduce allocations and improve timing diagnostics in hot paths.
Implementation details
Datadog.Trace.Utilfor allocation-free timing and pooling.Test coverage
CI passes then all changes are good.
Other details