Fix ToString and ToWString on large strings (#5930 -> v2) #5940

andrewlock · 2024-08-23T15:34:43Z

Summary of changes

Fix ToString and ToWString on large strings

Reason for change

Those two methods have a fast-path, where we try to fit the result in a pre-allocated buffer. But when the string is too long, we incorrectly assumed that WideCharToMultiByte/MultiByteToWideChar would return the needed size. In truth, it only does so when cchWideChar is 0. Because of that mistake, we were returning an empty string.

Implementation details

Added a few minor changes while I was at it:

For arrays, directly use the array instead of &array[0]
For strings, use str.data() instead of &str[0]
Don't zero the buffer since we're going to only use what is filled

Test coverage

Added a unit test for long strings.

Other details

Backport of #5930

## Summary of changes Fix ToString and ToWString on large strings ## Reason for change Those two methods have a fast-path, where we try to fit the result in a pre-allocated buffer. But when the string is too long, we incorrectly assumed that `WideCharToMultiByte`/`MultiByteToWideChar` would return the needed size. In truth, [it only does so when `cchWideChar` is 0](https://learn.microsoft.com/en-us/windows/win32/api/stringapiset/nf-stringapiset-multibytetowidechar#return-value). Because of that mistake, we were returning an empty string. ## Implementation details Added a few minor changes while I was at it: - For arrays, directly use the array instead of `&array[0]` - For strings, use `str.data()` instead of `&str[0]` - Don't zero the buffer since we're going to only use what is filled ## Test coverage Added a unit test for long strings.

daniel-romano-DD

👍

datadog-ddstaging · 2024-08-23T16:06:17Z

Datadog Report

Branch report: kevin/string_conversion-v2
Commit report: 24cf403
Test service: dd-trace-dotnet

❌ 1 Failed (1 Known Flaky), 347368 Passed, 2080 Skipped, 15h 37m 20.14s Total Time

❌ Failed Tests (1)

CheckErrorWhenNoAgentIsAvailable - Datadog.Profiler.IntegrationTests.WindowsOnly.EtwEventsTests - ❄️ Known flaky - Details
Expand for error
```
 
 Actual:   Falsemples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
```

andrewlock · 2024-08-23T16:52:35Z

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 (5940) - mean (75ms)  : 65, 84
     .   : milestone, 75,

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (1,028ms)  : 1007, 1049
     .   : milestone, 1028,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5940) - mean (110ms)  : 106, 113
     .   : milestone, 110,

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (710ms)  : 690, 729
     .   : milestone, 710,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5940) - mean (93ms)  : 91, 95
     .   : milestone, 93,

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (667ms)  : 645, 689
     .   : milestone, 667,

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

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (1,115ms)  : 1095, 1135
     .   : milestone, 1115,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5940) - mean (279ms)  : 270, 287
     .   : milestone, 279,

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (880ms)  : 858, 901
     .   : milestone, 880,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5940) - mean (264ms)  : 260, 268
     .   : milestone, 264,

    section CallTarget+Inlining+NGEN
    This PR (5940) - mean (866ms)  : 840, 892
     .   : milestone, 866,

andrewlock · 2024-08-23T21:44:02Z

Benchmarks Report for tracer 🐌

Benchmarks for #5940 compared to master:

2 benchmarks are faster, with geometric mean 1.132
1 benchmarks are slower, with geometric mean 1.114
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.69μs	43.4ns	310ns	0.0145	0.00727	0	5.42 KB
master	`StartStopWithChild`	netcoreapp3.1	9.85μs	52.3ns	272ns	0.0197	0.00983	0	5.62 KB
master	`StartStopWithChild`	net472	16.5μs	82.9ns	531ns	1.03	0.307	0.105	6.07 KB
#5940	`StartStopWithChild`	net6.0	7.97μs	44.2ns	290ns	0.0121	0.00403	0	5.43 KB
#5940	`StartStopWithChild`	netcoreapp3.1	9.97μs	53.8ns	299ns	0.0198	0.00988	0	5.61 KB
#5940	`StartStopWithChild`	net472	16.2μs	63ns	244ns	1.02	0.31	0.0896	6.07 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	455μs	312ns	1.21μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	669μs	408ns	1.53μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	836μs	541ns	2.02μs	0.417	3.3 KB
#5940	`WriteAndFlushEnrichedTraces`	net6.0	497μs	324ns	1.25μs	0	2.7 KB
#5940	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	639μs	433ns	1.68μs	0	2.7 KB
#5940	`WriteAndFlushEnrichedTraces`	net472	849μs	628ns	2.35μ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	191μs	1.01μs	7.63μs	0.187	18.45 KB
master	`SendRequest`	netcoreapp3.1	220μs	1.19μs	10.4μs	0.222	20.61 KB
master	`SendRequest`	net472	0.00193ns	0.000701ns	0.00271ns	0	0 b
#5940	`SendRequest`	net6.0	193μs	1.12μs	9.14μs	0.196	18.45 KB
#5940	`SendRequest`	netcoreapp3.1	213μs	1.24μs	9.97μs	0.202	20.61 KB
#5940	`SendRequest`	net472	0.000801ns	0.000381ns	0.00148ns	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	576μs	2.37μs	10.8μs	0.573	0	0	41.71 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	697μs	3.94μs	26.8μs	0.332	0	0	41.73 KB
master	`WriteAndFlushEnrichedTraces`	net472	869μs	4μs	16μs	8.25	2.6	0.434	53.36 KB
#5940	`WriteAndFlushEnrichedTraces`	net6.0	541μs	2.12μs	8.22μs	0.543	0	0	41.67 KB
#5940	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	669μs	2.9μs	10.8μs	0.351	0	0	41.8 KB
#5940	`WriteAndFlushEnrichedTraces`	net472	872μs	4.38μs	19.1μs	8.86	2.33	0.466	53.32 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.22μs	1.26ns	4.88ns	0.0141	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.68μs	1.06ns	4.12ns	0.0134	1.02 KB
master	`ExecuteNonQuery`	net472	2.01μs	2.21ns	8.58ns	0.156	987 B
#5940	`ExecuteNonQuery`	net6.0	1.26μs	1.59ns	6.17ns	0.0144	1.02 KB
#5940	`ExecuteNonQuery`	netcoreapp3.1	1.8μs	1.09ns	4.22ns	0.0134	1.02 KB
#5940	`ExecuteNonQuery`	net472	1.97μs	2.9ns	11.2ns	0.156	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.17μs	0.506ns	1.89ns	0.0135	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.47μs	0.565ns	2.11ns	0.0134	976 B
master	`CallElasticsearch`	net472	2.45μs	1.19ns	4.14ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.29μs	0.487ns	1.82ns	0.0129	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.67μs	1.01ns	3.77ns	0.0133	1.02 KB
master	`CallElasticsearchAsync`	net472	2.56μs	1.51ns	5.66ns	0.167	1.05 KB
#5940	`CallElasticsearch`	net6.0	1.23μs	0.755ns	2.92ns	0.0135	976 B
#5940	`CallElasticsearch`	netcoreapp3.1	1.54μs	0.565ns	2.11ns	0.0132	976 B
#5940	`CallElasticsearch`	net472	2.46μs	2.2ns	8.53ns	0.157	995 B
#5940	`CallElasticsearchAsync`	net6.0	1.32μs	0.765ns	2.86ns	0.0132	952 B
#5940	`CallElasticsearchAsync`	netcoreapp3.1	1.63μs	0.441ns	1.71ns	0.014	1.02 KB
#5940	`CallElasticsearchAsync`	net472	2.48μs	1.93ns	7.47ns	0.167	1.05 KB

Benchmarks.Trace.GraphQLBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #5940

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑netcoreapp3.1	1.114	1,519.07	1,692.65

Faster 🎉 in #5940

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0	1.143	1,293.25	1,131.48

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net6.0	1.29μs	1.03ns	4.01ns	0.0136	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.52μs	1.27ns	4.76ns	0.0128	952 B
master	`ExecuteAsync`	net472	1.79μs	0.964ns	3.61ns	0.145	915 B
#5940	`ExecuteAsync`	net6.0	1.13μs	0.522ns	2.02ns	0.0136	952 B
#5940	`ExecuteAsync`	netcoreapp3.1	1.69μs	0.601ns	2.25ns	0.0127	952 B
#5940	`ExecuteAsync`	net472	1.75μs	0.583ns	2.26ns	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.13μs	1.69ns	6.31ns	0.0311	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.08μs	1.83ns	7.09ns	0.0356	2.76 KB
master	`SendAsync`	net472	7.92μs	8.94ns	34.6ns	0.498	3.15 KB
#5940	`SendAsync`	net6.0	4.15μs	2.06ns	7.97ns	0.031	2.22 KB
#5940	`SendAsync`	netcoreapp3.1	5.25μs	4.75ns	18.4ns	0.0367	2.76 KB
#5940	`SendAsync`	net472	7.81μs	1.24ns	4.8ns	0.497	3.15 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.48μs	0.987ns	3.82ns	0.0231	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.37μs	1.04ns	3.88ns	0.0225	1.64 KB
master	`EnrichedLog`	net472	2.77μs	1.52ns	5.69ns	0.249	1.57 KB
#5940	`EnrichedLog`	net6.0	1.53μs	0.537ns	2.08ns	0.0231	1.64 KB
#5940	`EnrichedLog`	netcoreapp3.1	2.17μs	1.57ns	5.87ns	0.0228	1.64 KB
#5940	`EnrichedLog`	net472	2.82μs	1.61ns	6.25ns	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	116μs	148ns	575ns	0.0584	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	121μs	261ns	1.01μs	0	0	4.28 KB
master	`EnrichedLog`	net472	150μs	260ns	1.01μs	0.67	0.223	4.46 KB
#5940	`EnrichedLog`	net6.0	116μs	189ns	731ns	0.0581	0	4.28 KB
#5940	`EnrichedLog`	netcoreapp3.1	117μs	199ns	772ns	0.0583	0	4.28 KB
#5940	`EnrichedLog`	net472	150μs	347ns	1.34μs	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	2.98μs	0.767ns	2.87ns	0.0311	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.19μs	1.95ns	7.29ns	0.0294	2.2 KB
master	`EnrichedLog`	net472	4.84μs	0.795ns	2.87ns	0.32	2.02 KB
#5940	`EnrichedLog`	net6.0	3.03μs	0.854ns	3.31ns	0.0303	2.2 KB
#5940	`EnrichedLog`	netcoreapp3.1	4.26μs	1.59ns	5.96ns	0.0299	2.2 KB
#5940	`EnrichedLog`	net472	4.99μs	1.57ns	5.44ns	0.319	2.02 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendReceive`	net6.0	1.33μs	1.3ns	5.04ns	0.016	0	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.74μs	0.728ns	2.62ns	0.0156	0	1.14 KB
master	`SendReceive`	net472	2.21μs	1.04ns	4.04ns	0.183	0.0011	1.16 KB
#5940	`SendReceive`	net6.0	1.44μs	0.651ns	2.44ns	0.0159	0	1.14 KB
#5940	`SendReceive`	netcoreapp3.1	1.73μs	2.79ns	10.8ns	0.015	0	1.14 KB
#5940	`SendReceive`	net472	2.16μs	2.56ns	9.93ns	0.183	0	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.74μs	0.858ns	3.21ns	0.0219	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.83μs	2ns	7.75ns	0.021	1.65 KB
master	`EnrichedLog`	net472	4.44μs	2.7ns	10.5ns	0.323	2.04 KB
#5940	`EnrichedLog`	net6.0	2.79μs	1.02ns	3.95ns	0.0224	1.6 KB
#5940	`EnrichedLog`	netcoreapp3.1	3.86μs	1.5ns	5.6ns	0.0213	1.65 KB
#5940	`EnrichedLog`	net472	4.33μs	1.15ns	4.3ns	0.323	2.04 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	408ns	0.917ns	3.55ns	0.00808	576 B
master	`StartFinishSpan`	netcoreapp3.1	560ns	0.289ns	1.12ns	0.00766	576 B
master	`StartFinishSpan`	net472	581ns	0.615ns	2.22ns	0.0917	578 B
master	`StartFinishScope`	net6.0	487ns	0.474ns	1.77ns	0.00969	696 B
master	`StartFinishScope`	netcoreapp3.1	732ns	0.497ns	1.92ns	0.00924	696 B
master	`StartFinishScope`	net472	947ns	2.16ns	8.08ns	0.104	658 B
#5940	`StartFinishSpan`	net6.0	394ns	0.14ns	0.523ns	0.0081	576 B
#5940	`StartFinishSpan`	netcoreapp3.1	564ns	0.211ns	0.817ns	0.00765	576 B
#5940	`StartFinishSpan`	net472	644ns	0.61ns	2.36ns	0.0916	578 B
#5940	`StartFinishScope`	net6.0	513ns	0.246ns	0.922ns	0.00967	696 B
#5940	`StartFinishScope`	netcoreapp3.1	748ns	0.259ns	0.967ns	0.00927	696 B
#5940	`StartFinishScope`	net472	941ns	0.575ns	2.23ns	0.105	658 B

Benchmarks.Trace.TraceAnnotationsBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5940

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0	1.122	673.93	600.81

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	674ns	0.341ns	1.32ns	0.00973	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	958ns	1.64ns	6.13ns	0.00948	696 B
master	`RunOnMethodBegin`	net472	1.14μs	5.01ns	19.4ns	0.104	658 B
#5940	`RunOnMethodBegin`	net6.0	601ns	0.162ns	0.627ns	0.0096	696 B
#5940	`RunOnMethodBegin`	netcoreapp3.1	941ns	0.541ns	2.03ns	0.00926	696 B
#5940	`RunOnMethodBegin`	net472	1.1μs	0.392ns	1.41ns	0.104	658 B

andrewlock added area:native-library Automatic instrumentation native C++ code (Datadog.Trace.ClrProfiler.Native) area:shared-components labels Aug 23, 2024

andrewlock requested a review from a team as a code owner August 23, 2024 15:34

daniel-romano-DD approved these changes Aug 23, 2024

View reviewed changes

bouwkast approved these changes Aug 23, 2024

View reviewed changes

andrewlock merged commit 2972c44 into release/2.x Aug 23, 2024
57 of 62 checks passed

andrewlock deleted the kevin/string_conversion-v2 branch August 23, 2024 22:14

github-actions bot added this to the vNext-v2 milestone Aug 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix ToString and ToWString on large strings (#5930 -> v2) #5940

Fix ToString and ToWString on large strings (#5930 -> v2) #5940

andrewlock commented Aug 23, 2024

daniel-romano-DD left a comment

datadog-ddstaging bot commented Aug 23, 2024 •

edited

Loading

andrewlock commented Aug 23, 2024

andrewlock commented Aug 23, 2024

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5940

Faster 🎉 in #5940

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #5940

Raw results

Fix ToString and ToWString on large strings (#5930 -> v2) #5940

Fix ToString and ToWString on large strings (#5930 -> v2) #5940

Conversation

andrewlock commented Aug 23, 2024

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

daniel-romano-DD left a comment

Choose a reason for hiding this comment

datadog-ddstaging bot commented Aug 23, 2024 • edited Loading

Datadog Report

❌ Failed Tests (1)

andrewlock commented Aug 23, 2024

Execution-Time Benchmarks Report ⏱️

andrewlock commented Aug 23, 2024

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5940

Faster 🎉 in #5940

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #5940

Raw results

datadog-ddstaging bot commented Aug 23, 2024 •

edited

Loading