Fix - Change DelegateInstrumentation set continuations behaviour to copy Calltarget #5049

tonyredondo · 2024-01-11T15:29:46Z

Summary of changes

This PR changes the set continuations behaviour of the delegate instrumentation to copy the same behaviour used in CallTarget instrumentation.

Reason for change

AWS instrumentations wraps an async delegate (return Task) that can throw when is called, in those cases the Delegate Instrumentation were not calling the OnDelegateEndAsync method, so opened spans were not getting close.

This scenario only occurs when the delegate returns a Task but it doesn't await anything so there's no State Machine in the method.

Implementation details

Just moved the set continuation call inside the finally clause and before calling the OnDelegateEnd.

Test coverage

2 new unit tests catch the scenario of throwing inside the target async delegate and calling the OnDelegateEndAsync method.

…lTarget

datadog-ddstaging · 2024-01-11T15:52:48Z

Datadog Report

Branch report: tony/fix-delegateinstrumentation-continuations
Commit report: 4b2f7a9
Test service: dd-trace-dotnet

✅ 0 Failed, 301243 Passed, 1014 Skipped, 33m 55.47s Wall Time

andrewlock · 2024-01-11T16:01:09Z

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 (5049) - mean (71ms)  : 63, 80
     .   : milestone, 71,
    master - mean (71ms)  : 60, 81
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (1,031ms)  : 1011, 1051
     .   : milestone, 1031,
    master - mean (1,024ms)  : 1002, 1047
     .   : milestone, 1024,

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

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (724ms)  : 708, 741
     .   : milestone, 724,
    master - mean (726ms)  : 704, 748
     .   : milestone, 726,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5049) - mean (90ms)  : 85, 94
     .   : milestone, 90,
    master - mean (88ms)  : 83, 92
     .   : milestone, 88,

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (697ms)  : 679, 716
     .   : milestone, 697,
    master - mean (689ms)  : 663, 715
     .   : milestone, 689,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5049) - mean (188ms)  : 184, 191
     .   : milestone, 188,
    master - mean (188ms)  : 185, 190
     .   : milestone, 188,

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (1,139ms)  : 1114, 1163
     .   : milestone, 1139,
    master - mean (1,142ms)  : 1122, 1163
     .   : milestone, 1142,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5049) - mean (272ms)  : 267, 277
     .   : milestone, 272,
    master - mean (271ms)  : 267, 275
     .   : milestone, 271,

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (1,097ms)  : 1076, 1118
     .   : milestone, 1097,
    master - mean (1,102ms)  : 1080, 1124
     .   : milestone, 1102,

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

    section CallTarget+Inlining+NGEN
    This PR (5049) - mean (1,058ms)  : 1039, 1077
     .   : milestone, 1058,
    master - mean (1,063ms)  : 1045, 1080
     .   : milestone, 1063,

andrewlock

Awesome, this seems to fix the issue we were seeing, thanks 👍

zacharycmontoya · 2024-01-11T17:34:16Z

tracer/test/Datadog.Trace.Tests/Util/Delegates/FuncInstrumentationTests.cs

+                result = new StrongBox<int>(await func("Arg01").ConfigureAwait(false));
+            }).ConfigureAwait(false);
+
+        callbacks.Count.Value.Should().Be(4);


So just to make sure I'm understanding this part of the unit test, the result is 4 because we're calling Count.Value++ in the following sequence right?

OnDelegateBegin

original func delegate

⚠️ Exception happens ⚠️

OnDelegateEndAsync

OnDelegateEnd

Edit: Changed to list OnDelegateEndAsync then OnDelegateEnd

Yes the execution order will depend if the target delegate has finished or not. If when we are setting the continuation the task has been completed we call the continuation directly. If not, we set the continuation so the execution can occur after the OnDelegateEnd. In the case of an exception because the initial Task is completed (faulted) we run the EndAsync before End.

andrewlock · 2024-01-11T21:26:45Z

Benchmarks Report 🐌

Benchmarks for #5049 compared to master:

4 benchmarks are faster, with geometric mean 1.163
3 benchmarks are slower, with geometric mean 1.193
1 benchmarks have more 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.7μs	47.7ns	282ns	0.0226	0.00905	0	7.48 KB
master	`StartStopWithChild`	netcoreapp3.1	11μs	61.6ns	408ns	0.0275	0.011	0	7.57 KB
master	`StartStopWithChild`	net472	17.2μs	60.1ns	233ns	1.35	0.369	0.12	7.95 KB
#5049	`StartStopWithChild`	net6.0	8.81μs	49.4ns	313ns	0.0307	0.0132	0	7.48 KB
#5049	`StartStopWithChild`	netcoreapp3.1	10.8μs	59.1ns	359ns	0.0276	0.011	0	7.57 KB
#5049	`StartStopWithChild`	net472	17.5μs	49.9ns	193ns	1.33	0.345	0.124	7.94 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	463μs	197ns	763ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	632μs	195ns	731ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	786μs	250ns	936ns	0.393	3.3 KB
#5049	`WriteAndFlushEnrichedTraces`	net6.0	477μs	273ns	1.06μs	0	2.7 KB
#5049	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	634μs	347ns	1.34μs	0	2.7 KB
#5049	`WriteAndFlushEnrichedTraces`	net472	789μs	176ns	633ns	0.393	3.3 KB

Benchmarks.Trace.Asm.AppSecBodyBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #5049

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑net472	1.275	168.94	215.43
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorMoreComplexBody‑net472	1.177	3,874.40	4,560.20

Faster 🎉 in #5049

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑netcoreapp3.1	1.143	223.55	195.51

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`AllCycleSimpleBody`	net6.0	38.7μs	22.5ns	87.3ns	0.0194	0	1.77 KB
master	`AllCycleSimpleBody`	netcoreapp3.1	41.3μs	41.2ns	154ns	0.0206	0	1.74 KB
master	`AllCycleSimpleBody`	net472	44.7μs	9.62ns	36ns	0.269	0	1.81 KB
master	`AllCycleMoreComplexBody`	net6.0	200μs	71.9ns	259ns	0.0994	0	9.25 KB
master	`AllCycleMoreComplexBody`	netcoreapp3.1	210μs	183ns	660ns	0.105	0	9.14 KB
master	`AllCycleMoreComplexBody`	net472	226μs	272ns	1.02μs	1.48	0	9.32 KB
master	`ObjectExtractorSimpleBody`	net6.0	141ns	0.0521ns	0.195ns	0.00393	0	280 B
master	`ObjectExtractorSimpleBody`	netcoreapp3.1	224ns	0.174ns	0.673ns	0.00373	0	272 B
master	`ObjectExtractorSimpleBody`	net472	169ns	0.225ns	0.873ns	0.0446	0	281 B
master	`ObjectExtractorMoreComplexBody`	net6.0	2.91μs	0.609ns	2.28ns	0.0527	0	3.78 KB
master	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	4.01μs	0.8ns	2.99ns	0.0502	0	3.69 KB
master	`ObjectExtractorMoreComplexBody`	net472	3.88μs	2.71ns	10.5ns	0.602	0.00579	3.8 KB
#5049	`AllCycleSimpleBody`	net6.0	38.9μs	18.1ns	65.4ns	0.0193	0	1.77 KB
#5049	`AllCycleSimpleBody`	netcoreapp3.1	41.9μs	15.9ns	57.2ns	0.0208	0	1.74 KB
#5049	`AllCycleSimpleBody`	net472	44.6μs	42.9ns	160ns	0.288	0	1.81 KB
#5049	`AllCycleMoreComplexBody`	net6.0	199μs	156ns	585ns	0.0992	0	9.25 KB
#5049	`AllCycleMoreComplexBody`	netcoreapp3.1	212μs	195ns	729ns	0.105	0	9.14 KB
#5049	`AllCycleMoreComplexBody`	net472	226μs	203ns	758ns	1.46	0	9.32 KB
#5049	`ObjectExtractorSimpleBody`	net6.0	140ns	0.0573ns	0.198ns	0.00395	0	280 B
#5049	`ObjectExtractorSimpleBody`	netcoreapp3.1	196ns	0.114ns	0.428ns	0.00366	0	272 B
#5049	`ObjectExtractorSimpleBody`	net472	215ns	0.12ns	0.464ns	0.0446	0	281 B
#5049	`ObjectExtractorMoreComplexBody`	net6.0	2.97μs	3.18ns	11.9ns	0.0533	0	3.78 KB
#5049	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	3.91μs	1.63ns	5.66ns	0.0507	0	3.69 KB
#5049	`ObjectExtractorMoreComplexBody`	net472	4.56μs	2.09ns	8.1ns	0.602	0.00454	3.8 KB

Benchmarks.Trace.Asm.AppSecWafBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`RunWaf(args=NestedMap (10))`	net6.0	55.1μs	38ns	132ns	0.222	0	16.06 KB
master	`RunWaf(args=NestedMap (10))`	netcoreapp3.1	70.6μs	371ns	1.89μs	0.202	0	16.06 KB
master	`RunWaf(args=NestedMap (10))`	net472	102μs	133ns	516ns	2.54	0.0959	16.14 KB
master	`RunWafTwice(args=NestedMap (10))`	net6.0	59.1μs	39.9ns	155ns	0.212	0	16.6 KB
master	`RunWafTwice(args=NestedMap (10))`	netcoreapp3.1	73.3μs	404ns	2.36μs	0.209	0	16.58 KB
master	`RunWafTwice(args=NestedMap (10))`	net472	106μs	57.5ns	223ns	2.64	0.103	16.69 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	109μs	483ns	1.87μs	0.321	0	22.41 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	131μs	625ns	2.5μs	0.258	0	22.36 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	160μs	181ns	701ns	3.55	0.161	22.7 KB
master	`RunWaf(args=NestedMap (100))`	net6.0	99μs	144ns	518ns	0.445	0	32.76 KB
master	`RunWaf(args=NestedMap (100))`	netcoreapp3.1	137μs	379ns	1.47μs	0.402	0	33.33 KB
master	`RunWaf(args=NestedMap (100))`	net472	191μs	929ns	3.71μs	5.26	0.369	33.67 KB
master	`RunWafTwice(args=NestedMap (100))`	net6.0	111μs	626ns	4.2μs	0.453	0	33.3 KB
master	`RunWafTwice(args=NestedMap (100))`	netcoreapp3.1	142μs	801ns	5.49μs	0.461	0	33.86 KB
master	`RunWafTwice(args=NestedMap (100))`	net472	196μs	917ns	3.55μs	5.39	0.385	34.22 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	net6.0	170μs	953ns	6.39μs	0.554	0	39.1 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	netcoreapp3.1	203μs	848ns	3.28μs	0.479	0	39.63 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	net472	260μs	1.09μs	4.21μs	6.35	0.508	40.23 KB
master	`RunWaf(args=NestedMap (20))`	net6.0	100μs	363ns	2.41μs	0.447	0	32.18 KB
master	`RunWaf(args=NestedMap (20))`	netcoreapp3.1	135μs	746ns	4.78μs	0.379	0	32.3 KB
master	`RunWaf(args=NestedMap (20))`	net472	186μs	73.1ns	283ns	5.19	0.37	32.63 KB
master	`RunWafTwice(args=NestedMap (20))`	net6.0	112μs	57.6ns	223ns	0.451	0	32.72 KB
master	`RunWafTwice(args=NestedMap (20))`	netcoreapp3.1	139μs	403ns	1.56μs	0.39	0	32.83 KB
master	`RunWafTwice(args=NestedMap (20))`	net472	193μs	60.4ns	226ns	5.2	0.385	33.19 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	167μs	658ns	2.46μs	0.475	0	38.53 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	196μs	974ns	4.36μs	0.487	0	38.6 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	254μs	134ns	503ns	6.21	0.507	39.2 KB
#5049	`RunWaf(args=NestedMap (10))`	net6.0	57.4μs	221ns	857ns	0.226	0	16.06 KB
#5049	`RunWaf(args=NestedMap (10))`	netcoreapp3.1	68.9μs	395ns	2.93μs	0.195	0	16.06 KB
#5049	`RunWaf(args=NestedMap (10))`	net472	99.2μs	488ns	2.24μs	2.55	0.0946	16.14 KB
#5049	`RunWafTwice(args=NestedMap (10))`	net6.0	54.6μs	272ns	1.56μs	0.214	0	16.6 KB
#5049	`RunWafTwice(args=NestedMap (10))`	netcoreapp3.1	71.8μs	347ns	1.39μs	0.213	0	16.58 KB
#5049	`RunWafTwice(args=NestedMap (10))`	net472	103μs	84.5ns	316ns	2.63	0.103	16.69 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	107μs	87.2ns	338ns	0.268	0	22.41 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	130μs	600ns	2.32μs	0.249	0	22.36 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	158μs	210ns	758ns	3.57	0.159	22.7 KB
#5049	`RunWaf(args=NestedMap (100))`	net6.0	109μs	25.1ns	93.9ns	0.44	0	32.76 KB
#5049	`RunWaf(args=NestedMap (100))`	netcoreapp3.1	139μs	788ns	5.74μs	0.423	0	33.33 KB
#5049	`RunWaf(args=NestedMap (100))`	net472	186μs	192ns	742ns	5.28	0.37	33.67 KB
#5049	`RunWafTwice(args=NestedMap (100))`	net6.0	112μs	30.7ns	119ns	0.439	0	33.3 KB
#5049	`RunWafTwice(args=NestedMap (100))`	netcoreapp3.1	137μs	757ns	4.41μs	0.465	0	33.86 KB
#5049	`RunWafTwice(args=NestedMap (100))`	net472	193μs	111ns	414ns	5.41	0.386	34.23 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [23])`	net6.0	169μs	245ns	951ns	0.553	0	39.1 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [23])`	netcoreapp3.1	199μs	1.08μs	5.7μs	0.508	0	39.63 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [23])`	net472	254μs	130ns	503ns	6.34	0.507	40.23 KB
#5049	`RunWaf(args=NestedMap (20))`	net6.0	110μs	35.8ns	138ns	0.444	0	32.18 KB
#5049	`RunWaf(args=NestedMap (20))`	netcoreapp3.1	129μs	718ns	4.65μs	0.397	0	32.3 KB
#5049	`RunWaf(args=NestedMap (20))`	net472	188μs	83.3ns	323ns	5.12	0.373	32.63 KB
#5049	`RunWafTwice(args=NestedMap (20))`	net6.0	112μs	44.7ns	173ns	0.449	0	32.72 KB
#5049	`RunWafTwice(args=NestedMap (20))`	netcoreapp3.1	138μs	679ns	3.04μs	0.401	0	32.82 KB
#5049	`RunWafTwice(args=NestedMap (20))`	net472	197μs	945ns	3.66μs	5.27	0.383	33.19 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	162μs	816ns	3.83μs	0.499	0	38.53 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	194μs	939ns	3.76μs	0.484	0	38.6 KB
#5049	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	262μs	666ns	2.49μs	6.19	0.505	39.2 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	172μs	167ns	647ns	0.171	18.25 KB
master	`SendRequest`	netcoreapp3.1	194μs	277ns	1.07μs	0.193	20.41 KB
master	`SendRequest`	net472	0.000137ns	0.000114ns	0.00041ns	0	0 b
#5049	`SendRequest`	net6.0	174μs	204ns	789ns	0.174	18.25 KB
#5049	`SendRequest`	netcoreapp3.1	194μs	353ns	1.37μs	0.193	20.41 KB
#5049	`SendRequest`	net472	0.000214ns	0.000119ns	0.000461ns	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	540μs	355ns	1.33μs	0.541	0	0	41.49 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	656μs	2.07μs	8.01μs	0.327	0	0	41.9 KB
master	`WriteAndFlushEnrichedTraces`	net472	854μs	3.64μs	14.1μs	8.36	2.64	0.44	53.25 KB
#5049	`WriteAndFlushEnrichedTraces`	net6.0	531μs	562ns	2.18μs	0.527	0	0	41.45 KB
#5049	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	643μs	854ns	3.31μs	0.322	0	0	41.87 KB
#5049	`WriteAndFlushEnrichedTraces`	net472	861μs	4.02μs	15.6μs	8.33	2.5	0.417	53.24 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.04μs	0.408ns	1.47ns	0.0109	768 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.5μs	0.334ns	1.21ns	0.0105	768 B
master	`ExecuteNonQuery`	net472	1.89μs	0.869ns	3.37ns	0.116	730 B
#5049	`ExecuteNonQuery`	net6.0	1.04μs	1.02ns	3.95ns	0.0109	768 B
#5049	`ExecuteNonQuery`	netcoreapp3.1	1.43μs	0.415ns	1.61ns	0.0101	768 B
#5049	`ExecuteNonQuery`	net472	1.79μs	1.13ns	4.06ns	0.116	730 B

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

Faster 🎉 in #5049

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑net6.0	1.162	1,479.74	1,273.12

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net6.0	1.29μs	0.517ns	2ns	0.0129	0	936 B
master	`CallElasticsearch`	netcoreapp3.1	1.46μs	0.625ns	2.34ns	0.0128	0	936 B
master	`CallElasticsearch`	net472	2.59μs	0.68ns	2.64ns	0.151	0	955 B
master	`CallElasticsearchAsync`	net6.0	1.48μs	0.561ns	2.17ns	0.0126	0	912 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.68μs	0.861ns	3.22ns	0.0136	0	984 B
master	`CallElasticsearchAsync`	net472	2.78μs	1.72ns	6.66ns	0.16	0	1.01 KB
#5049	`CallElasticsearch`	net6.0	1.2μs	0.794ns	2.97ns	0.0133	0	936 B
#5049	`CallElasticsearch`	netcoreapp3.1	1.45μs	6.38ns	24.7ns	0.0126	0	936 B
#5049	`CallElasticsearch`	net472	2.55μs	0.606ns	2.27ns	0.152	0.00127	955 B
#5049	`CallElasticsearchAsync`	net6.0	1.27μs	0.461ns	1.72ns	0.0123	0	912 B
#5049	`CallElasticsearchAsync`	netcoreapp3.1	1.6μs	0.759ns	2.94ns	0.0128	0	984 B
#5049	`CallElasticsearchAsync`	net472	2.69μs	0.424ns	1.64ns	0.159	0	1.01 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net6.0	1.35μs	0.896ns	3.35ns	0.0127	912 B
master	`ExecuteAsync`	netcoreapp3.1	1.65μs	0.93ns	3.35ns	0.0116	912 B
master	`ExecuteAsync`	net472	1.86μs	0.836ns	3.24ns	0.138	875 B
#5049	`ExecuteAsync`	net6.0	1.36μs	1.05ns	4.08ns	0.0122	912 B
#5049	`ExecuteAsync`	netcoreapp3.1	1.65μs	0.714ns	2.67ns	0.0125	912 B
#5049	`ExecuteAsync`	net472	1.9μs	1.1ns	4.12ns	0.138	875 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendAsync`	net6.0	4.03μs	2.16ns	8.09ns	0.0281	0	2.1 KB
master	`SendAsync`	netcoreapp3.1	4.93μs	1.54ns	5.75ns	0.0344	0	2.63 KB
master	`SendAsync`	net472	7.73μs	3.4ns	13.2ns	0.523	0	3.31 KB
#5049	`SendAsync`	net6.0	4.19μs	1.74ns	6.5ns	0.0293	0	2.1 KB
#5049	`SendAsync`	netcoreapp3.1	5.08μs	1.81ns	6.76ns	0.0356	0	2.63 KB
#5049	`SendAsync`	net472	7.96μs	3.49ns	13.1ns	0.524	0.00397	3.31 KB

Benchmarks.Trace.Iast.StringAspectsBenchmark - Same speed ✔️ More allocations ⚠️

More allocations ⚠️ in #5049

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑net472	58.52 KB	59.81 KB	1.29 KB	2.20%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Allocated
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net6.0	59.4μs	735ns	7.31μs	43.44 KB
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	53μs	199ns	743ns	42.64 KB
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net472	39.1μs	200ns	894ns	58.52 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net6.0	88.8μs	2.95μs	29.3μs	43.29 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	102μs	3.94μs	39.1μs	42.64 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net472	62.9μs	352ns	2.2μs	57.34 KB
#5049	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net6.0	55.1μs	290ns	1.39μs	43.44 KB
#5049	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	58.2μs	639ns	6.26μs	42.64 KB
#5049	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net472	37.9μs	144ns	540ns	59.81 KB
#5049	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net6.0	88.7μs	2.13μs	21.3μs	43.29 KB
#5049	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	71.9μs	325ns	1.21μs	42.64 KB
#5049	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net472	63.2μs	332ns	1.73μs	57.34 KB

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

Faster 🎉 in #5049

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ILoggerBenchmark.EnrichedLog‑net6.0	1.234	1,794.11	1,453.90

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.87μs	26.1ns	257ns	0.0218	1.57 KB
master	`EnrichedLog`	netcoreapp3.1	2.12μs	2.52ns	9.75ns	0.0211	1.57 KB
master	`EnrichedLog`	net472	2.51μs	1.5ns	5.82ns	0.238	1.5 KB
#5049	`EnrichedLog`	net6.0	1.45μs	0.681ns	2.46ns	0.0218	1.57 KB
#5049	`EnrichedLog`	netcoreapp3.1	2.24μs	1.02ns	3.67ns	0.0212	1.57 KB
#5049	`EnrichedLog`	net472	2.55μs	2.72ns	10.5ns	0.237	1.5 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	115μs	197ns	762ns	0.0566	0	4.21 KB
master	`EnrichedLog`	netcoreapp3.1	118μs	172ns	665ns	0	0	4.21 KB
master	`EnrichedLog`	net472	148μs	204ns	791ns	0.662	0.221	4.39 KB
#5049	`EnrichedLog`	net6.0	114μs	149ns	577ns	0.0564	0	4.21 KB
#5049	`EnrichedLog`	netcoreapp3.1	118μs	128ns	495ns	0.0591	0	4.21 KB
#5049	`EnrichedLog`	net472	148μs	75.6ns	283ns	0.663	0.221	4.39 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	3μs	0.866ns	3.35ns	0.0302	2.13 KB
master	`EnrichedLog`	netcoreapp3.1	4.12μs	1.39ns	5.39ns	0.0268	2.13 KB
master	`EnrichedLog`	net472	4.79μs	1.92ns	7.45ns	0.308	1.95 KB
#5049	`EnrichedLog`	net6.0	3.11μs	0.997ns	3.6ns	0.0297	2.13 KB
#5049	`EnrichedLog`	netcoreapp3.1	4.2μs	1.3ns	5.05ns	0.0273	2.13 KB
#5049	`EnrichedLog`	net472	4.73μs	2.05ns	7.38ns	0.307	1.95 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net6.0	1.37μs	0.704ns	2.64ns	0.015	1.1 KB
master	`SendReceive`	netcoreapp3.1	1.77μs	2.33ns	9.01ns	0.0143	1.1 KB
master	`SendReceive`	net472	2.19μs	1.76ns	6.81ns	0.177	1.12 KB
#5049	`SendReceive`	net6.0	1.29μs	1.17ns	4.52ns	0.0154	1.1 KB
#5049	`SendReceive`	netcoreapp3.1	1.74μs	0.758ns	2.73ns	0.0147	1.1 KB
#5049	`SendReceive`	net472	2.18μs	2.34ns	9.08ns	0.177	1.12 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.8μs	0.717ns	2.59ns	0.0209	1.53 KB
master	`EnrichedLog`	netcoreapp3.1	3.85μs	1.2ns	4.65ns	0.021	1.58 KB
master	`EnrichedLog`	net472	4.3μs	5.27ns	19.7ns	0.311	1.97 KB
#5049	`EnrichedLog`	net6.0	2.84μs	5.3ns	20.5ns	0.0214	1.53 KB
#5049	`EnrichedLog`	netcoreapp3.1	3.93μs	1.31ns	4.9ns	0.0215	1.58 KB
#5049	`EnrichedLog`	net472	4.32μs	1.41ns	5.27ns	0.311	1.97 KB

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

Slower ⚠️ in #5049

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472	1.131	706.90	799.35

Faster 🎉 in #5049

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0	1.117	596.50	533.89

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	466ns	0.268ns	1ns	0.00744	536 B
master	`StartFinishSpan`	netcoreapp3.1	740ns	0.417ns	1.56ns	0.00717	536 B
master	`StartFinishSpan`	net472	707ns	0.337ns	1.3ns	0.0851	538 B
master	`StartFinishScope`	net6.0	596ns	0.336ns	1.3ns	0.00928	656 B
master	`StartFinishScope`	netcoreapp3.1	834ns	0.805ns	2.9ns	0.00879	656 B
master	`StartFinishScope`	net472	1.01μs	0.684ns	2.65ns	0.098	618 B
#5049	`StartFinishSpan`	net6.0	515ns	0.373ns	1.44ns	0.0075	536 B
#5049	`StartFinishSpan`	netcoreapp3.1	775ns	0.123ns	0.462ns	0.00711	536 B
#5049	`StartFinishSpan`	net472	798ns	0.529ns	2.05ns	0.0851	538 B
#5049	`StartFinishScope`	net6.0	534ns	0.195ns	0.703ns	0.00925	656 B
#5049	`StartFinishScope`	netcoreapp3.1	877ns	0.558ns	2.16ns	0.00879	656 B
#5049	`StartFinishScope`	net472	1.01μs	2.21ns	8.55ns	0.0982	618 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	659ns	0.172ns	0.667ns	0.00906	656 B
master	`RunOnMethodBegin`	netcoreapp3.1	991ns	0.834ns	3.12ns	0.00887	656 B
master	`RunOnMethodBegin`	net472	1.12μs	0.409ns	1.58ns	0.0982	618 B
#5049	`RunOnMethodBegin`	net6.0	638ns	0.266ns	1.03ns	0.00934	656 B
#5049	`RunOnMethodBegin`	netcoreapp3.1	980ns	0.674ns	2.61ns	0.00865	656 B
#5049	`RunOnMethodBegin`	net472	1.16μs	0.411ns	1.54ns	0.0982	618 B

Change DelegateInstrumentation set continuations behavior to copy Cal…

4b2f7a9

…lTarget

tonyredondo self-assigned this Jan 11, 2024

tonyredondo requested a review from a team as a code owner January 11, 2024 15:29

andrewlock approved these changes Jan 11, 2024

View reviewed changes

zacharycmontoya reviewed Jan 11, 2024

View reviewed changes

zacharycmontoya approved these changes Jan 11, 2024

View reviewed changes

tonyredondo merged commit d5011be into master Jan 11, 2024
53 of 55 checks passed

tonyredondo deleted the tony/fix-delegateinstrumentation-continuations branch January 11, 2024 22:50

github-actions bot added this to the vNext milestone Jan 11, 2024

andrewlock mentioned this pull request Jan 12, 2024

Fix AWS Lambda tests #5050

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix - Change DelegateInstrumentation set continuations behaviour to copy Calltarget #5049

Fix - Change DelegateInstrumentation set continuations behaviour to copy Calltarget #5049

tonyredondo commented Jan 11, 2024 •

edited

Loading

datadog-ddstaging bot commented Jan 11, 2024 •

edited

Loading

andrewlock commented Jan 11, 2024

andrewlock left a comment

zacharycmontoya Jan 11, 2024 •

edited

Loading

tonyredondo Jan 11, 2024 •

edited

Loading

andrewlock commented Jan 11, 2024

Raw results

Raw results

Slower ⚠️ in #5049

Faster 🎉 in #5049

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #5049

Raw results

Raw results

Raw results

More allocations ⚠️ in #5049

Raw results

Faster 🎉 in #5049

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5049

Faster 🎉 in #5049

Raw results

Raw results

Fix - Change DelegateInstrumentation set continuations behaviour to copy Calltarget #5049

Fix - Change DelegateInstrumentation set continuations behaviour to copy Calltarget #5049

Conversation

tonyredondo commented Jan 11, 2024 • edited Loading

Summary of changes

Reason for change

Implementation details

Test coverage

datadog-ddstaging bot commented Jan 11, 2024 • edited Loading

Datadog Report

andrewlock commented Jan 11, 2024

Execution-Time Benchmarks Report ⏱️

andrewlock left a comment

Choose a reason for hiding this comment

zacharycmontoya Jan 11, 2024 • edited Loading

Choose a reason for hiding this comment

tonyredondo Jan 11, 2024 • edited Loading

Choose a reason for hiding this comment

andrewlock commented Jan 11, 2024

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Slower ⚠️ in #5049

Faster 🎉 in #5049

Raw results

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #5049

Raw results

Raw results

Raw results

More allocations ⚠️ in #5049

Raw results

Faster 🎉 in #5049

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #5049

Faster 🎉 in #5049

Raw results

Raw results

tonyredondo commented Jan 11, 2024 •

edited

Loading

datadog-ddstaging bot commented Jan 11, 2024 •

edited

Loading

zacharycmontoya Jan 11, 2024 •

edited

Loading

tonyredondo Jan 11, 2024 •

edited

Loading