Skip to content

[Shared] Fix bug in logger#6335

Merged
gleocadie merged 1 commit into
masterfrom
gleocadie/fix-bug-in-logger
Nov 22, 2024
Merged

[Shared] Fix bug in logger#6335
gleocadie merged 1 commit into
masterfrom
gleocadie/fix-bug-in-logger

Conversation

@gleocadie

@gleocadie gleocadie commented Nov 22, 2024

Copy link
Copy Markdown
Collaborator

Summary of changes

Fix a bug in the logger for WCHAR[n] string.

Reason for change

When get a string from the Windows API (for ex:) like

WCHAR s[250];
auto nbChars = SuperOldApi(..., s, 250);
...
Log::Info(s);

The logger will write all the 250 characters even if the string is smaller.
Example My Log Line^@Garbage^@^@^@^@^@
Instead of My Log Line

Implementation details

  • Remove the template optimization and use shared::ToString instead

Test coverage

  • Add a test in the profiler unit tests

Other details

@gleocadie
gleocadie requested review from a team as code owners November 22, 2024 09:36
@andrewlock

andrewlock commented Nov 22, 2024

Copy link
Copy Markdown
Member

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

gantt
    title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (72ms)  : 64, 79
     .   : milestone, 72,
    master - mean (71ms)  : 64, 78
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (1,110ms)  : 1091, 1129
     .   : milestone, 1110,
    master - mean (1,109ms)  : 1083, 1135
     .   : milestone, 1109,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (108ms)  : 106, 110
     .   : milestone, 108,
    master - mean (109ms)  : 106, 112
     .   : milestone, 109,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (770ms)  : 754, 786
     .   : milestone, 770,
    master - mean (772ms)  : 752, 791
     .   : milestone, 772,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (92ms)  : 90, 95
     .   : milestone, 92,
    master - mean (92ms)  : 91, 94
     .   : milestone, 92,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (724ms)  : 706, 743
     .   : milestone, 724,
    master - mean (726ms)  : 711, 741
     .   : milestone, 726,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (191ms)  : 185, 197
     .   : milestone, 191,
    master - mean (192ms)  : 186, 198
     .   : milestone, 192,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (1,215ms)  : 1196, 1235
     .   : milestone, 1215,
    master - mean (1,214ms)  : 1192, 1237
     .   : milestone, 1214,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (277ms)  : 271, 282
     .   : milestone, 277,
    master - mean (278ms)  : 272, 284
     .   : milestone, 278,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (946ms)  : 928, 964
     .   : milestone, 946,
    master - mean (949ms)  : 933, 965
     .   : milestone, 949,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6335) - mean (266ms)  : 263, 269
     .   : milestone, 266,
    master - mean (266ms)  : 262, 270
     .   : milestone, 266,

    section CallTarget+Inlining+NGEN
    This PR (6335) - mean (934ms)  : 918, 951
     .   : milestone, 934,
    master - mean (931ms)  : 914, 948
     .   : milestone, 931,
Loading

@datadog-ddstaging

datadog-ddstaging Bot commented Nov 22, 2024 •
edited
Loading

Copy link
Copy Markdown

Datadog Report

Branch report: gleocadie/fix-bug-in-logger
Commit report: 09e4e02
Test service: dd-trace-dotnet

❌ 1 Failed (1 Known Flaky), 449178 Passed, 3185 Skipped, 22h 7m 17.62s Total Time
❄️ 1 New Flaky
⌛ 1 Performance Regression

❌ Failed Tests (1)

  • ShouldGetAllocationSamplesViaEtw - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - ❄️ Known flaky - Details

    Expand for error 
     
 Actual:   Falseilure

New Flaky Tests (1)

  • ReadyToRunManualAndAutomatic - Datadog.Trace.ClrProfiler.IntegrationTests.ManualInstrumentationTests - Last Failure

    Expand for error 
     Results do not match.
 Differences:
 Received: ManualInstrumentationTests.ManualAndAutomatic.received.txt
 Verified: ManualInstrumentationTests.ManualAndAutomatic.verified.txt
 Received Content:
 [
   {
     TraceId: Id_1,
     SpanId: Id_2,
     Name: initial,
 ...

⌛ Performance Regressions vs Default Branch (1)

  • Profiler_garbagecollections_cpu_walltime - scenarios 2.74s (+174.35ms, +7%) - Details

@andrewlock

andrewlock commented Nov 22, 2024

Copy link
Copy Markdown
Member

Benchmarks Report for tracer 🐌

Benchmarks for #6335 compared to master:

  • 2 benchmarks are slower, with geometric mean 1.161
  • 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 7.97μs 45.4ns 327ns 0.0119 0.00398 0 5.61 KB
master StartStopWithChild netcoreapp3.1 9.92μs 54.9ns 334ns 0.0151 0.00503 0 5.8 KB
master StartStopWithChild net472 16.3μs 51.3ns 199ns 1.06 0.332 0.116 6.21 KB
#6335 StartStopWithChild net6.0 7.89μs 44.7ns 322ns 0.0166 0.00831 0 5.6 KB
#6335 StartStopWithChild netcoreapp3.1 10.2μs 51.9ns 254ns 0.0149 0.00498 0 5.8 KB
#6335 StartStopWithChild net472 16.2μs 52.1ns 202ns 1.03 0.288 0.0881 6.21 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 487μs 394ns 1.53μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 654μs 145ns 543ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 859μs 583ns 2.26μs 0.425 0 0 3.3 KB
#6335 WriteAndFlushEnrichedTraces net6.0 499μs 334ns 1.29μs 0 0 0 2.7 KB
#6335 WriteAndFlushEnrichedTraces netcoreapp3.1 661μs 378ns 1.46μs 0 0 0 2.7 KB
#6335 WriteAndFlushEnrichedTraces net472 855μs 435ns 1.63μs 0.425 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 152μs 856ns 6.52μs 0.148 0 0 14.47 KB
master SendRequest netcoreapp3.1 167μs 884ns 6μs 0.169 0 0 17.27 KB
master SendRequest net472 0.000513ns 0.000275ns 0.00103ns 0 0 0 0 b
#6335 SendRequest net6.0 152μs 863ns 7.72μs 0.134 0 0 14.47 KB
#6335 SendRequest netcoreapp3.1 172μs 996ns 9.18μs 0.158 0 0 17.27 KB
#6335 SendRequest net472 0.00145ns 0.000882ns 0.00318ns 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 564μs 2.75μs 11μs 0.558 0 0 41.57 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 680μs 3.75μs 22.8μs 0.406 0 0 41.75 KB
master WriteAndFlushEnrichedTraces net472 863μs 4.32μs 18.3μs 8.56 2.57 0.428 53.28 KB
#6335 WriteAndFlushEnrichedTraces net6.0 568μs 2.39μs 9.86μs 0.598 0 0 41.47 KB
#6335 WriteAndFlushEnrichedTraces netcoreapp3.1 685μs 3.44μs 15μs 0.353 0 0 41.71 KB
#6335 WriteAndFlushEnrichedTraces net472 862μs 2.12μs 8.21μs 8.13 2.57 0.428 53.3 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.31μs 0.782ns 2.93ns 0.0145 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.73μs 2.21ns 8.25ns 0.0138 0 0 1.02 KB
master ExecuteNonQuery net472 2.04μs 2.42ns 9.38ns 0.156 0.00102 0 987 B
#6335 ExecuteNonQuery net6.0 1.36μs 1.15ns 4.29ns 0.0141 0 0 1.02 KB
#6335 ExecuteNonQuery netcoreapp3.1 1.8μs 1.91ns 7.13ns 0.0134 0 0 1.02 KB
#6335 ExecuteNonQuery net472 2.1μs 2ns 7.75ns 0.157 0.00104 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.2μs 0.724ns 2.71ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.51μs 1.23ns 4.6ns 0.0129 0 0 976 B
master CallElasticsearch net472 2.46μs 1.32ns 5.12ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.35μs 0.535ns 2.07ns 0.0129 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.66μs 0.878ns 3.4ns 0.0134 0 0 1.02 KB
master CallElasticsearchAsync net472 2.75μs 1.27ns 4.76ns 0.166 0 0 1.05 KB
#6335 CallElasticsearch net6.0 1.33μs 1.12ns 4.18ns 0.0135 0 0 976 B
#6335 CallElasticsearch netcoreapp3.1 1.49μs 0.74ns 2.77ns 0.0132 0 0 976 B
#6335 CallElasticsearch net472 2.62μs 0.936ns 3.5ns 0.157 0 0 995 B
#6335 CallElasticsearchAsync net6.0 1.32μs 0.581ns 2.17ns 0.0133 0 0 952 B
#6335 CallElasticsearchAsync netcoreapp3.1 1.62μs 1.13ns 4.23ns 0.0137 0 0 1.02 KB
#6335 CallElasticsearchAsync net472 2.76μs 1.42ns 5.31ns 0.166 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.31μs 0.484ns 1.81ns 0.0131 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.62μs 2.24ns 8.37ns 0.0128 0 0 952 B
master ExecuteAsync net472 1.77μs 0.485ns 1.81ns 0.145 0 0 915 B
#6335 ExecuteAsync net6.0 1.38μs 0.709ns 2.65ns 0.0131 0 0 952 B
#6335 ExecuteAsync netcoreapp3.1 1.64μs 0.76ns 2.94ns 0.0122 0 0 952 B
#6335 ExecuteAsync net472 1.83μs 0.441ns 1.65ns 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.32μs 3.27ns 12.7ns 0.0323 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.35μs 3.02ns 11.7ns 0.0375 0 0 2.85 KB
master SendAsync net472 7.37μs 8.02ns 31.1ns 0.493 0 0 3.12 KB
#6335 SendAsync net6.0 4.34μs 2.74ns 10.6ns 0.0326 0 0 2.31 KB
#6335 SendAsync netcoreapp3.1 5.2μs 3.28ns 11.8ns 0.039 0 0 2.85 KB
#6335 SendAsync net472 7.36μs 1.54ns 5.96ns 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.6μs 0.785ns 2.94ns 0.0233 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.22μs 0.93ns 3.48ns 0.0221 0 0 1.64 KB
master EnrichedLog net472 2.77μs 0.859ns 3.33ns 0.249 0 0 1.57 KB
#6335 EnrichedLog net6.0 1.54μs 0.868ns 3.25ns 0.0231 0 0 1.64 KB
#6335 EnrichedLog netcoreapp3.1 2.26μs 4.63ns 17.3ns 0.022 0 0 1.64 KB
#6335 EnrichedLog net472 2.62μs 1.61ns 6.23ns 0.249 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 119μs 174ns 673ns 0.0596 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 124μs 226ns 875ns 0 0 0 4.28 KB
master EnrichedLog net472 150μs 107ns 399ns 0.681 0.227 0 4.46 KB
#6335 EnrichedLog net6.0 121μs 144ns 557ns 0.0604 0 0 4.28 KB
#6335 EnrichedLog netcoreapp3.1 123μs 128ns 480ns 0 0 0 4.28 KB
#6335 EnrichedLog net472 151μs 133ns 516ns 0.675 0.225 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.12μs 1.24ns 4.82ns 0.0297 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.17μs 3.85ns 14.9ns 0.0293 0 0 2.2 KB
master EnrichedLog net472 4.91μs 4.95ns 19.2ns 0.32 0 0 2.02 KB
#6335 EnrichedLog net6.0 3.11μs 1.27ns 4.92ns 0.0311 0 0 2.2 KB
#6335 EnrichedLog netcoreapp3.1 4.13μs 1.61ns 6.03ns 0.0291 0 0 2.2 KB
#6335 EnrichedLog net472 4.85μs 1.93ns 7.47ns 0.318 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.29μs 0.403ns 1.51ns 0.016 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.76μs 1ns 3.88ns 0.015 0 0 1.14 KB
master SendReceive net472 2.03μs 1.27ns 4.92ns 0.183 0 0 1.16 KB
#6335 SendReceive net6.0 1.28μs 0.686ns 2.66ns 0.016 0 0 1.14 KB
#6335 SendReceive netcoreapp3.1 1.77μs 0.854ns 3.2ns 0.0151 0 0 1.14 KB
#6335 SendReceive net472 2.05μs 0.983ns 3.54ns 0.184 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.7μs 0.665ns 2.49ns 0.0217 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.99μs 1.83ns 6.59ns 0.0223 0 0 1.65 KB
master EnrichedLog net472 4.34μs 1.7ns 6.12ns 0.322 0 0 2.04 KB
#6335 EnrichedLog net6.0 2.8μs 1.37ns 5.29ns 0.0224 0 0 1.6 KB
#6335 EnrichedLog netcoreapp3.1 3.87μs 1.18ns 4.42ns 0.023 0 0 1.65 KB
#6335 EnrichedLog net472 4.44μs 1.9ns 7.37ns 0.324 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6335

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 1.125 640.08 720.00

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 388ns 0.528ns 2.04ns 0.00809 0 0 576 B
master StartFinishSpan netcoreapp3.1 615ns 1.12ns 4.34ns 0.00767 0 0 576 B
master StartFinishSpan net472 643ns 1.25ns 4.82ns 0.0917 0 0 578 B
master StartFinishScope net6.0 477ns 0.672ns 2.6ns 0.0099 0 0 696 B
master StartFinishScope netcoreapp3.1 639ns 1.12ns 4.18ns 0.00921 0 0 696 B
master StartFinishScope net472 847ns 1.27ns 4.91ns 0.105 0 0 658 B
#6335 StartFinishSpan net6.0 398ns 0.268ns 1ns 0.008 0 0 576 B
#6335 StartFinishSpan netcoreapp3.1 595ns 1.2ns 4.64ns 0.00756 0 0 576 B
#6335 StartFinishSpan net472 654ns 1.15ns 4.44ns 0.0918 0 0 578 B
#6335 StartFinishScope net6.0 496ns 0.68ns 2.55ns 0.00977 0 0 696 B
#6335 StartFinishScope netcoreapp3.1 721ns 1.37ns 5.31ns 0.00918 0 0 696 B
#6335 StartFinishScope net472 905ns 1.19ns 4.62ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6335

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.199 594.38 712.43

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 594ns 0.832ns 3.22ns 0.00963 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 857ns 1.45ns 5.61ns 0.00952 0 0 696 B
master RunOnMethodBegin net472 1.09μs 1.86ns 7.22ns 0.104 0 0 658 B
#6335 RunOnMethodBegin net6.0 713ns 1.05ns 4.08ns 0.00965 0 0 696 B
#6335 RunOnMethodBegin netcoreapp3.1 936ns 1.94ns 7.51ns 0.00947 0 0 696 B
#6335 RunOnMethodBegin net472 1.12μs 1.8ns 6.98ns 0.104 0 0 658 B

chrisnas
chrisnas approved these changes Nov 22, 2024
View reviewed changes

@chrisnas chrisnas left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

LGTM

@gleocadie
gleocadie merged commit 078c2ec into master Nov 22, 2024
@gleocadie
gleocadie deleted the gleocadie/fix-bug-in-logger branch November 22, 2024 14:10
@github-actions github-actions Bot added this to the vNext-v3 milestone Nov 22, 2024
@robertpi robertpi added area:shared-components area:builds project files, build scripts, pipelines, versioning, releases, packages labels Dec 18, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@chrisnas chrisnas chrisnas approved these changes

Assignees

No one assigned

Labels

area:builds project files, build scripts, pipelines, versioning, releases, packages area:shared-components

Projects

None yet

Milestone

3.7.0

Development

Successfully merging this pull request may close these issues.

4 participants

@gleocadie @andrewlock @chrisnas @robertpi