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

Fix Microsoft.Extensions.Telemetry logging integration in 9.3.0 #6773

Merged
merged 3 commits into from
Mar 18, 2025

Conversation

andrewlock
Copy link
Member

Summary of changes

Fixes the Microsoft.Extensions.Telemetry integration for 9.3.0

Reason for change

9.3.0 introduced a new optional parameter to a public method we instrument, breaking our integration

Implementation details

Add instrumentation for the new signature

Test coverage

This is the test - if everything passes, we're good

Other details

Identified in #6732

@andrewlock andrewlock added type:enhancement Improvement to an existing feature area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) area:integrations area:direct-log-submission labels Mar 17, 2025
@andrewlock andrewlock requested review from a team as code owners March 17, 2025 11:12
@andrewlock
Copy link
Member Author

andrewlock commented Mar 17, 2025

Execution-Time Benchmarks Report ⏱️

Execution-time results for samples comparing the following branches/commits:

Execution-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 shown in red. The following thresholds were used for comparing the execution times:

  • Welch test with statistical test for significance of 5%
  • Only results indicating a difference greater than 5% and 5 ms are considered.

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).

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (69ms)  : 66, 72
     .   : milestone, 69,
    master - mean (69ms)  : 66, 72
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (1,004ms)  : 979, 1029
     .   : milestone, 1004,
    master - mean (1,024ms)  : 958, 1090
     .   : milestone, 1024,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (102ms)  : 99, 105
     .   : milestone, 102,
    master - mean (105ms)  : 101, 110
     .   : milestone, 105,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (681ms)  : 664, 698
     .   : milestone, 681,
    master - mean (699ms)  : 644, 755
     .   : milestone, 699,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (89ms)  : 87, 91
     .   : milestone, 89,
    master - mean (90ms)  : 87, 93
     .   : milestone, 90,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (639ms)  : 624, 654
     .   : milestone, 639,
    master - mean (645ms)  : 623, 667
     .   : milestone, 645,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (190ms)  : 186, 195
     .   : milestone, 190,
    master - mean (190ms)  : 187, 193
     .   : milestone, 190,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (1,105ms)  : 1075, 1134
     .   : milestone, 1105,
    master - mean (1,113ms)  : 1070, 1155
     .   : milestone, 1113,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (269ms)  : 266, 273
     .   : milestone, 269,
    master - mean (269ms)  : 266, 273
     .   : milestone, 269,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (873ms)  : 843, 904
     .   : milestone, 873,
    master - mean (877ms)  : 843, 911
     .   : milestone, 877,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6773) - mean (263ms)  : 259, 266
     .   : milestone, 263,
    master - mean (261ms)  : 257, 266
     .   : milestone, 261,

    section CallTarget+Inlining+NGEN
    This PR (6773) - mean (858ms)  : 821, 895
     .   : milestone, 858,
    master - mean (861ms)  : 827, 895
     .   : milestone, 861,

@datadog-datadog-prod-us1
Copy link

datadog-datadog-prod-us1 bot commented Mar 17, 2025

Datadog Report

All test runs 42cad7d 🔗

2 Total Test Services: 0 Failed, 2 Passed

Test Services
Service Name Failed Known Flaky New Flaky Passed Skipped Total Time Test Service View
dd-trace-dotnet 0 0 0 565136 5536 47h 29m 56.09s Link
exploration_tests 0 0 0 22085 3 1h 29m 15.87s Link

Copy link
Collaborator

@bouwkast bouwkast left a comment

Choose a reason for hiding this comment

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

This looks fine, but I think the ILogger may have changed as well as tests are failing here

@bouwkast
Copy link
Collaborator

This looks fine, but I think the ILogger may have changed as well as tests are failing here

Hmm maybe not, it is ILogger tests but for this logger specifically

@bouwkast bouwkast self-requested a review March 17, 2025 12:50
@andrewlock andrewlock force-pushed the andrew/fix-telemetry-integration branch from a5345a7 to 42cad7d Compare March 17, 2025 12:56
Copy link
Collaborator

@bouwkast bouwkast left a comment

Choose a reason for hiding this comment

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

LGTM

I did download the NuGet just to see that yes they do update the assembly version inline with the NuGet Version which is nice.

IntegrationName = LoggerIntegrationCommon.IntegrationName)]
[Browsable(false)]
[EditorBrowsable(EditorBrowsableState.Never)]
public class ExtendedLoggerFactoryConstructorIntegration_8xx
Copy link
Collaborator

Choose a reason for hiding this comment

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

Kinda 8xx but kinda 8xx_920 :)

Copy link
Member Author

Choose a reason for hiding this comment

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

Kinda 8xx but kinda 8xx_920 :)

Yeah, I considered that and thought meh 😅

@andrewlock
Copy link
Member Author

I did download the NuGet just to see that yes they do update the assembly version inline with the NuGet Version which is nice.

Yeah, same! 😄 Just in case you're not aware @bouwkast , there's also the "Open in NuGet Package Explorer" link on the sidebar. From there you can explore the nuget packages and check the dll versions etc without needing to explictly download it 🙂 (though in practice it downloads it in the browser, so not strictly true 😄)

@bouwkast
Copy link
Collaborator

I did download the NuGet just to see that yes they do update the assembly version inline with the NuGet Version which is nice.

Yeah, same! 😄 Just in case you're not aware @bouwkast , there's also the "Open in NuGet Package Explorer" link on the sidebar. From there you can explore the nuget packages and check the dll versions etc without needing to explictly download it 🙂 (though in practice it downloads it in the browser, so not strictly true 😄)

Well TIL

@andrewlock
Copy link
Member Author

Benchmarks Report for tracer 🐌

Benchmarks for #6773 compared to master:

  • 1 benchmarks are slower, with geometric mean 1.145
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 8.02μs 43.9ns 248ns 0.0159 0.00795 0 5.62 KB
master StartStopWithChild netcoreapp3.1 10μs 56.7ns 376ns 0.016 0.00533 0 5.81 KB
master StartStopWithChild net472 16.1μs 29.5ns 114ns 1.04 0.301 0.103 6.22 KB
#6773 StartStopWithChild net6.0 7.86μs 43.2ns 277ns 0.0117 0.00389 0 5.6 KB
#6773 StartStopWithChild netcoreapp3.1 10.4μs 55.8ns 306ns 0.0154 0.00514 0 5.8 KB
#6773 StartStopWithChild net472 15.9μs 42.7ns 165ns 1.07 0.332 0.103 6.22 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 501μs 408ns 1.58μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 659μs 619ns 2.4μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 844μs 879ns 3.4μs 0.419 0 0 3.3 KB
#6773 WriteAndFlushEnrichedTraces net6.0 490μs 409ns 1.53μs 0 0 0 2.7 KB
#6773 WriteAndFlushEnrichedTraces netcoreapp3.1 658μs 437ns 1.69μs 0 0 0 2.7 KB
#6773 WriteAndFlushEnrichedTraces net472 897μs 467ns 1.81μs 0.428 0 0 3.3 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 130μs 460ns 1.78μs 0.131 0 0 14.47 KB
master SendRequest netcoreapp3.1 144μs 493ns 1.91μs 0.216 0 0 17.27 KB
master SendRequest net472 0.000714ns 0.000211ns 0.000791ns 0 0 0 0 b
#6773 SendRequest net6.0 132μs 461ns 1.79μs 0.194 0 0 14.47 KB
#6773 SendRequest netcoreapp3.1 148μs 160ns 618ns 0.22 0 0 17.28 KB
#6773 SendRequest net472 0.00101ns 0.000322ns 0.00125ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 571μs 3.24μs 24.6μs 0.579 0 0 41.43 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 680μs 3.73μs 21.4μs 0.347 0 0 41.82 KB
master WriteAndFlushEnrichedTraces net472 852μs 4.17μs 17.2μs 8.33 2.5 0.417 53.3 KB
#6773 WriteAndFlushEnrichedTraces net6.0 570μs 3.16μs 18.7μs 0.543 0 0 41.5 KB
#6773 WriteAndFlushEnrichedTraces netcoreapp3.1 714μs 3.88μs 23.3μs 0.336 0 0 41.86 KB
#6773 WriteAndFlushEnrichedTraces net472 870μs 4.16μs 16.6μs 8.39 2.52 0.419 53.31 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.43μs 1.4ns 5.44ns 0.0143 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.87μs 1.91ns 7.39ns 0.0141 0 0 1.02 KB
master ExecuteNonQuery net472 2.11μs 2.96ns 11.5ns 0.156 0.00105 0 987 B
#6773 ExecuteNonQuery net6.0 1.38μs 3.08ns 11.9ns 0.0145 0 0 1.02 KB
#6773 ExecuteNonQuery netcoreapp3.1 1.73μs 1.67ns 6.24ns 0.0138 0 0 1.02 KB
#6773 ExecuteNonQuery net472 2.11μs 2.24ns 8.67ns 0.156 0.00105 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.22μs 0.433ns 1.62ns 0.0134 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.57μs 0.883ns 3.42ns 0.0134 0 0 976 B
master CallElasticsearch net472 2.61μs 1.39ns 5.37ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.31μs 0.607ns 2.35ns 0.0131 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.63μs 0.871ns 3.26ns 0.0139 0 0 1.02 KB
master CallElasticsearchAsync net472 2.71μs 1.42ns 5.48ns 0.166 0 0 1.05 KB
#6773 CallElasticsearch net6.0 1.14μs 0.684ns 2.56ns 0.0137 0 0 976 B
#6773 CallElasticsearch netcoreapp3.1 1.57μs 0.673ns 2.61ns 0.0134 0 0 976 B
#6773 CallElasticsearch net472 2.69μs 2.41ns 9.35ns 0.157 0 0 995 B
#6773 CallElasticsearchAsync net6.0 1.27μs 0.566ns 2.12ns 0.0134 0 0 952 B
#6773 CallElasticsearchAsync netcoreapp3.1 1.66μs 0.702ns 2.72ns 0.0141 0 0 1.02 KB
#6773 CallElasticsearchAsync net472 2.72μs 1.9ns 7.35ns 0.167 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.27μs 0.807ns 3.02ns 0.0129 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.63μs 1.09ns 4.06ns 0.0122 0 0 952 B
master ExecuteAsync net472 1.87μs 1.67ns 6.47ns 0.145 0 0 915 B
#6773 ExecuteAsync net6.0 1.37μs 0.672ns 2.42ns 0.0131 0 0 952 B
#6773 ExecuteAsync netcoreapp3.1 1.7μs 1.32ns 4.92ns 0.0127 0 0 952 B
#6773 ExecuteAsync net472 1.81μs 0.261ns 0.977ns 0.145 0 0 915 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net6.0 4.41μs 2.06ns 8ns 0.031 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.41μs 2.09ns 7.83ns 0.0379 0 0 2.85 KB
master SendAsync net472 7.36μs 1.66ns 6.41ns 0.495 0 0 3.12 KB
#6773 SendAsync net6.0 4.49μs 4.81ns 18ns 0.0314 0 0 2.31 KB
#6773 SendAsync netcoreapp3.1 5.3μs 1.46ns 5.07ns 0.0372 0 0 2.85 KB
#6773 SendAsync net472 7.58μs 1.52ns 5.9ns 0.493 0 0 3.12 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 1.49μs 0.442ns 1.59ns 0.0235 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.08μs 1.18ns 4.27ns 0.0229 0 0 1.64 KB
master EnrichedLog net472 2.56μs 0.916ns 3.55ns 0.249 0 0 1.57 KB
#6773 EnrichedLog net6.0 1.56μs 3.76ns 14.5ns 0.0231 0 0 1.64 KB
#6773 EnrichedLog netcoreapp3.1 2.27μs 1.3ns 5.04ns 0.0218 0 0 1.64 KB
#6773 EnrichedLog net472 2.58μs 1.87ns 7.25ns 0.25 0 0 1.57 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 113μs 470ns 2.1μs 0.0555 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 117μs 174ns 673ns 0.0579 0 0 4.28 KB
master EnrichedLog net472 154μs 152ns 588ns 0.681 0.227 0 4.46 KB
#6773 EnrichedLog net6.0 113μs 165ns 617ns 0.0559 0 0 4.28 KB
#6773 EnrichedLog netcoreapp3.1 115μs 177ns 664ns 0.0585 0 0 4.28 KB
#6773 EnrichedLog net472 160μs 721ns 2.79μs 0.636 0.159 0 4.46 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 3.01μs 0.691ns 2.59ns 0.0316 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.1μs 1.77ns 6.84ns 0.0288 0 0 2.2 KB
master EnrichedLog net472 4.72μs 1.93ns 7.48ns 0.32 0 0 2.02 KB
#6773 EnrichedLog net6.0 3.19μs 0.914ns 3.54ns 0.0305 0 0 2.2 KB
#6773 EnrichedLog netcoreapp3.1 4.18μs 2.49ns 9.63ns 0.0293 0 0 2.2 KB
#6773 EnrichedLog net472 4.81μs 1.46ns 5.46ns 0.32 0 0 2.02 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.37μs 1.13ns 4.21ns 0.0159 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.85μs 1.44ns 5.38ns 0.0157 0 0 1.14 KB
master SendReceive net472 2.21μs 2.8ns 10.5ns 0.183 0 0 1.16 KB
#6773 SendReceive net6.0 1.35μs 2.03ns 7.87ns 0.016 0 0 1.14 KB
#6773 SendReceive netcoreapp3.1 1.85μs 2.04ns 7.9ns 0.0149 0 0 1.14 KB
#6773 SendReceive net472 2.07μs 6ns 23.2ns 0.183 0 0 1.16 KB
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.83μs 2.28ns 8.52ns 0.0226 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 4.01μs 1.46ns 5.48ns 0.0207 0 0 1.65 KB
master EnrichedLog net472 4.28μs 4.31ns 16.7ns 0.323 0 0 2.04 KB
#6773 EnrichedLog net6.0 2.65μs 1.48ns 5.74ns 0.0224 0 0 1.6 KB
#6773 EnrichedLog netcoreapp3.1 3.99μs 2.53ns 9.82ns 0.0219 0 0 1.65 KB
#6773 EnrichedLog net472 4.36μs 3.32ns 12.8ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6773

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.145 404.51 463.00

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 404ns 0.113ns 0.437ns 0.00813 0 0 576 B
master StartFinishSpan netcoreapp3.1 602ns 0.583ns 2.18ns 0.00768 0 0 576 B
master StartFinishSpan net472 621ns 0.138ns 0.533ns 0.0917 0 0 578 B
master StartFinishScope net6.0 500ns 0.0864ns 0.323ns 0.00978 0 0 696 B
master StartFinishScope netcoreapp3.1 666ns 0.256ns 0.958ns 0.00945 0 0 696 B
master StartFinishScope net472 878ns 0.443ns 1.71ns 0.104 0 0 658 B
#6773 StartFinishSpan net6.0 463ns 0.0633ns 0.228ns 0.0081 0 0 576 B
#6773 StartFinishSpan netcoreapp3.1 628ns 0.254ns 0.952ns 0.00754 0 0 576 B
#6773 StartFinishSpan net472 677ns 0.498ns 1.86ns 0.0915 0 0 578 B
#6773 StartFinishScope net6.0 546ns 0.141ns 0.547ns 0.00977 0 0 696 B
#6773 StartFinishScope netcoreapp3.1 679ns 0.226ns 0.781ns 0.00927 0 0 696 B
#6773 StartFinishScope net472 848ns 0.234ns 0.904ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 601ns 0.221ns 0.827ns 0.00956 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 933ns 0.478ns 1.79ns 0.00934 0 0 696 B
master RunOnMethodBegin net472 1.08μs 0.294ns 1.14ns 0.104 0 0 658 B
#6773 RunOnMethodBegin net6.0 658ns 0.418ns 1.56ns 0.00958 0 0 696 B
#6773 RunOnMethodBegin netcoreapp3.1 891ns 0.493ns 1.78ns 0.00904 0 0 696 B
#6773 RunOnMethodBegin net472 1.18μs 0.411ns 1.59ns 0.104 0 0 658 B

@andrewlock andrewlock merged commit afc1701 into master Mar 18, 2025
133 of 135 checks passed
@andrewlock andrewlock deleted the andrew/fix-telemetry-integration branch March 18, 2025 12:50
@github-actions github-actions bot added this to the vNext-v3 milestone Mar 18, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:direct-log-submission area:integrations area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) type:enhancement Improvement to an existing feature
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants