[Shared] Fix bug in logger #6335

gleocadie · 2024-11-22T09:36:38Z

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

andrewlock · 2024-11-22T10:09:56Z

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,

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,

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,

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,

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,

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,

datadog-ddstaging · 2024-11-22T10:14:08Z

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 · 2024-11-22T10:59:43Z

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	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	487μs	394ns	1.53μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	654μs	145ns	543ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	859μs	583ns	2.26μs	0.425	3.3 KB
#6335	`WriteAndFlushEnrichedTraces`	net6.0	499μs	334ns	1.29μs	0	2.7 KB
#6335	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	661μs	378ns	1.46μs	0	2.7 KB
#6335	`WriteAndFlushEnrichedTraces`	net472	855μs	435ns	1.63μs	0.425	3.3 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	152μs	856ns	6.52μs	0.148	14.47 KB
master	`SendRequest`	netcoreapp3.1	167μs	884ns	6μs	0.169	17.27 KB
master	`SendRequest`	net472	0.000513ns	0.000275ns	0.00103ns	0	0 b
#6335	`SendRequest`	net6.0	152μs	863ns	7.72μs	0.134	14.47 KB
#6335	`SendRequest`	netcoreapp3.1	172μs	996ns	9.18μs	0.158	17.27 KB
#6335	`SendRequest`	net472	0.00145ns	0.000882ns	0.00318ns	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	Allocated
master	`ExecuteNonQuery`	net6.0	1.31μs	0.782ns	2.93ns	0.0145	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.73μs	2.21ns	8.25ns	0.0138	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.04μs	2.42ns	9.38ns	0.156	0.00102	987 B
#6335	`ExecuteNonQuery`	net6.0	1.36μs	1.15ns	4.29ns	0.0141	0	1.02 KB
#6335	`ExecuteNonQuery`	netcoreapp3.1	1.8μs	1.91ns	7.13ns	0.0134	0	1.02 KB
#6335	`ExecuteNonQuery`	net472	2.1μs	2ns	7.75ns	0.157	0.00104	987 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net6.0	1.2μs	0.724ns	2.71ns	0.0138	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.51μs	1.23ns	4.6ns	0.0129	976 B
master	`CallElasticsearch`	net472	2.46μs	1.32ns	5.12ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.35μs	0.535ns	2.07ns	0.0129	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.66μs	0.878ns	3.4ns	0.0134	1.02 KB
master	`CallElasticsearchAsync`	net472	2.75μs	1.27ns	4.76ns	0.166	1.05 KB
#6335	`CallElasticsearch`	net6.0	1.33μs	1.12ns	4.18ns	0.0135	976 B
#6335	`CallElasticsearch`	netcoreapp3.1	1.49μs	0.74ns	2.77ns	0.0132	976 B
#6335	`CallElasticsearch`	net472	2.62μs	0.936ns	3.5ns	0.157	995 B
#6335	`CallElasticsearchAsync`	net6.0	1.32μs	0.581ns	2.17ns	0.0133	952 B
#6335	`CallElasticsearchAsync`	netcoreapp3.1	1.62μs	1.13ns	4.23ns	0.0137	1.02 KB
#6335	`CallElasticsearchAsync`	net472	2.76μs	1.42ns	5.31ns	0.166	1.05 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net6.0	1.31μs	0.484ns	1.81ns	0.0131	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.62μs	2.24ns	8.37ns	0.0128	952 B
master	`ExecuteAsync`	net472	1.77μs	0.485ns	1.81ns	0.145	915 B
#6335	`ExecuteAsync`	net6.0	1.38μs	0.709ns	2.65ns	0.0131	952 B
#6335	`ExecuteAsync`	netcoreapp3.1	1.64μs	0.76ns	2.94ns	0.0122	952 B
#6335	`ExecuteAsync`	net472	1.83μs	0.441ns	1.65ns	0.145	915 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	4.32μs	3.27ns	12.7ns	0.0323	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.35μs	3.02ns	11.7ns	0.0375	2.85 KB
master	`SendAsync`	net472	7.37μs	8.02ns	31.1ns	0.493	3.12 KB
#6335	`SendAsync`	net6.0	4.34μs	2.74ns	10.6ns	0.0326	2.31 KB
#6335	`SendAsync`	netcoreapp3.1	5.2μs	3.28ns	11.8ns	0.039	2.85 KB
#6335	`SendAsync`	net472	7.36μs	1.54ns	5.96ns	0.493	3.12 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.6μs	0.785ns	2.94ns	0.0233	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.22μs	0.93ns	3.48ns	0.0221	1.64 KB
master	`EnrichedLog`	net472	2.77μs	0.859ns	3.33ns	0.249	1.57 KB
#6335	`EnrichedLog`	net6.0	1.54μs	0.868ns	3.25ns	0.0231	1.64 KB
#6335	`EnrichedLog`	netcoreapp3.1	2.26μs	4.63ns	17.3ns	0.022	1.64 KB
#6335	`EnrichedLog`	net472	2.62μs	1.61ns	6.23ns	0.249	1.57 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net6.0	119μs	174ns	673ns	0.0596	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	124μs	226ns	875ns	0	0	4.28 KB
master	`EnrichedLog`	net472	150μs	107ns	399ns	0.681	0.227	4.46 KB
#6335	`EnrichedLog`	net6.0	121μs	144ns	557ns	0.0604	0	4.28 KB
#6335	`EnrichedLog`	netcoreapp3.1	123μs	128ns	480ns	0	0	4.28 KB
#6335	`EnrichedLog`	net472	151μs	133ns	516ns	0.675	0.225	4.46 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	3.12μs	1.24ns	4.82ns	0.0297	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.17μs	3.85ns	14.9ns	0.0293	2.2 KB
master	`EnrichedLog`	net472	4.91μs	4.95ns	19.2ns	0.32	2.02 KB
#6335	`EnrichedLog`	net6.0	3.11μs	1.27ns	4.92ns	0.0311	2.2 KB
#6335	`EnrichedLog`	netcoreapp3.1	4.13μs	1.61ns	6.03ns	0.0291	2.2 KB
#6335	`EnrichedLog`	net472	4.85μs	1.93ns	7.47ns	0.318	2.02 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net6.0	1.29μs	0.403ns	1.51ns	0.016	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.76μs	1ns	3.88ns	0.015	1.14 KB
master	`SendReceive`	net472	2.03μs	1.27ns	4.92ns	0.183	1.16 KB
#6335	`SendReceive`	net6.0	1.28μs	0.686ns	2.66ns	0.016	1.14 KB
#6335	`SendReceive`	netcoreapp3.1	1.77μs	0.854ns	3.2ns	0.0151	1.14 KB
#6335	`SendReceive`	net472	2.05μs	0.983ns	3.54ns	0.184	1.16 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.7μs	0.665ns	2.49ns	0.0217	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.99μs	1.83ns	6.59ns	0.0223	1.65 KB
master	`EnrichedLog`	net472	4.34μs	1.7ns	6.12ns	0.322	2.04 KB
#6335	`EnrichedLog`	net6.0	2.8μs	1.37ns	5.29ns	0.0224	1.6 KB
#6335	`EnrichedLog`	netcoreapp3.1	3.87μs	1.18ns	4.42ns	0.023	1.65 KB
#6335	`EnrichedLog`	net472	4.44μs	1.9ns	7.37ns	0.324	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	Allocated
master	`StartFinishSpan`	net6.0	388ns	0.528ns	2.04ns	0.00809	576 B
master	`StartFinishSpan`	netcoreapp3.1	615ns	1.12ns	4.34ns	0.00767	576 B
master	`StartFinishSpan`	net472	643ns	1.25ns	4.82ns	0.0917	578 B
master	`StartFinishScope`	net6.0	477ns	0.672ns	2.6ns	0.0099	696 B
master	`StartFinishScope`	netcoreapp3.1	639ns	1.12ns	4.18ns	0.00921	696 B
master	`StartFinishScope`	net472	847ns	1.27ns	4.91ns	0.105	658 B
#6335	`StartFinishSpan`	net6.0	398ns	0.268ns	1ns	0.008	576 B
#6335	`StartFinishSpan`	netcoreapp3.1	595ns	1.2ns	4.64ns	0.00756	576 B
#6335	`StartFinishSpan`	net472	654ns	1.15ns	4.44ns	0.0918	578 B
#6335	`StartFinishScope`	net6.0	496ns	0.68ns	2.55ns	0.00977	696 B
#6335	`StartFinishScope`	netcoreapp3.1	721ns	1.37ns	5.31ns	0.00918	696 B
#6335	`StartFinishScope`	net472	905ns	1.19ns	4.62ns	0.104	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	Allocated
master	`RunOnMethodBegin`	net6.0	594ns	0.832ns	3.22ns	0.00963	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	857ns	1.45ns	5.61ns	0.00952	696 B
master	`RunOnMethodBegin`	net472	1.09μs	1.86ns	7.22ns	0.104	658 B
#6335	`RunOnMethodBegin`	net6.0	713ns	1.05ns	4.08ns	0.00965	696 B
#6335	`RunOnMethodBegin`	netcoreapp3.1	936ns	1.94ns	7.51ns	0.00947	696 B
#6335	`RunOnMethodBegin`	net472	1.12μs	1.8ns	6.98ns	0.104	658 B

chrisnas

LGTM

Fix bug in logger

09e4e02

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

chrisnas approved these changes Nov 22, 2024

View reviewed changes

gleocadie merged commit 078c2ec into master Nov 22, 2024
82 of 85 checks passed

gleocadie deleted the gleocadie/fix-bug-in-logger branch November 22, 2024 14:10

github-actions bot added this to the vNext-v3 milestone Nov 22, 2024

robertpi added area:shared-components area:builds project files, build scripts, pipelines, versioning, releases, packages labels Dec 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Shared] Fix bug in logger #6335

[Shared] Fix bug in logger #6335

gleocadie commented Nov 22, 2024

andrewlock commented Nov 22, 2024

datadog-ddstaging bot commented Nov 22, 2024 •

edited

Loading

andrewlock commented Nov 22, 2024

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6335

Raw results

Slower ⚠️ in #6335

Raw results

chrisnas left a comment

[Shared] Fix bug in logger #6335

[Shared] Fix bug in logger #6335

Conversation

gleocadie commented Nov 22, 2024

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

andrewlock commented Nov 22, 2024

Execution-Time Benchmarks Report ⏱️

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

Datadog Report

❌ Failed Tests (1)

New Flaky Tests (1)

⌛ Performance Regressions vs Default Branch (1)

andrewlock commented Nov 22, 2024

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6335

Raw results

Slower ⚠️ in #6335

Raw results

chrisnas left a comment

Choose a reason for hiding this comment

datadog-ddstaging bot commented Nov 22, 2024 •

edited

Loading