Add manual+automatic instrumentation tests + fix `SetUser` bug #4938

andrewlock · 2023-11-29T15:10:42Z

Summary of changes

Adds integration tests (i.e. snapshots etc) for manual only and manual+automatic instrumentation
Fix a bug in SetUser when used in non-aspnetcore scenario

Reason for change

I wanted to add these integration tests as part of the v3 work, but found that if you call span.SetUser() from an app that doesn't reference ASP.NET Core, you'd get an exception:

17:39:18 [DBG]  StandardError:
17:39:18 [DBG]  Unhandled exception. System.IO.FileNotFoundException: Could not load file or assembly 'Microsoft.AspNetCore.Http.Abstractions, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'. The system cannot find the file specified.
17:39:18 [DBG]  File name: 'Microsoft.AspNetCore.Http.Abstractions, Version=2.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'
17:39:18 [DBG]     at Datadog.Trace.SpanExtensions.RunBlockingCheck(Span span, String userId)
17:39:18 [DBG]     at Datadog.Trace.SpanExtensions.SetUserInternal(ISpan span, UserDetails userDetails) in C:\repos\dd-trace-dotnet\tracer\src\Datadog.Trace\SpanExtensions.cs:line 88
17:39:18 [DBG]     at Datadog.Trace.SpanExtensions.SetUser(ISpan span, UserDetails userDetails) in C:\repos\dd-trace-dotnet\tracer\src\Datadog.Trace\SpanExtensions.cs:line 34
17:39:18 [DBG]     at Program.<Main>$(String[] args) in C:\repos\dd-trace-dotnet\tracer\test\test-applications\integrations\Samples.ManualInstrumentation\Program.cs:line 49
17:39:18 [DBG]     at Program.<Main>(String[] args)

This was reproduced in the sample app, whether or not ASM was enabled.

Note that this is only an issue in the public APIs, because while we access the types directly in integrations, and in the AspNetCoreDiagnosticObserver, those code paths are only called when we know aspnetcore is available.

Implementation details

Attempt to load the HttpContext type before we first use it. Only do the check once for performance reasons, though this does have a small chance of returning a false negative, and effectively disabling the blocking here.

A "safe" alternative would be to keep checking on every call if you get a negative result, but then you pay the type load perf hit everytime, instead of just once. The tradeoff seemed reasonable to me, but also happy to rethink if others disagree.

Test coverage

Adds testing for the "manual only" and "manual+automatic" scenarios. Incidentally tests the ASM fix too.

Other details

There was some rare, slightly concerning, flake in the tags added to the spans. Sometimes, the custom ServiceVersion tag is omitted 🤷

I'm pretty sure the issue is down to the fact we're "reconfiguring" the tracer after sending spans. When we reconfigure the tracer, we schedule the "old" tracer to shutdown in the background. That means that briefly there's an overlap between the new and old tracers. My theory is that somewhere we're using the static Tracer.Instance tracer during serialization, instead of the ITracer and/or the associated settings that was used to create the Span (and is stored in TraceContext).

datadog-ddstaging · 2023-11-29T15:28:01Z

Datadog Report

Branch report: andrew/add-manual-instrumentation-integration-test
Commit report: 95fbc97

❄️ dd-trace-dotnet: 0 Failed, 1 New Flaky, 300415 Passed, 951 Skipped, 45m 57.02s Wall Time

New Flaky Tests (1)

WebHttp - Datadog.Trace.ClrProfiler.IntegrationTests.WcfTests - Last Failure

Expand for error

 Expected collection to contain at least 5 item(s) because we want to ensure that we don't timeout while waiting for spans from the mock tracer agent, but found 4: {TraceId: 2734742635932660053, SpanId: 6573835534523284529, Name: wcf.request, Resource: /ServerSyncAddJson/?/n2=2, Service: Samples.Wcf, TraceId: 2734742635932660053, SpanId: 10267786574666302650, Name: wcf.request, Resource: /ServerSyncAddXml/?/n2=2, Service: Samples.Wcf, TraceId: 2734742635932660053, SpanId: 985710579655892228, Name: wcf.request, Resource: /ServerTaskAddPost, Service: Samples.Wcf, TraceId: 2734742635932660053, SpanId: 13335222856492759458, Name: internal, Resource: WebClient, Service: Samples.Wcf}.

andrewlock · 2023-11-29T15:41: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 (4938) - mean (73ms)  : 60, 87
     .   : milestone, 73,
    master - mean (71ms)  : 60, 83
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (1,001ms)  : 980, 1022
     .   : milestone, 1001,
    master - mean (998ms)  : 972, 1023
     .   : milestone, 998,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4938) - mean (106ms)  : 103, 109
     .   : milestone, 106,
    master - mean (107ms)  : 102, 112
     .   : milestone, 107,

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (689ms)  : 671, 707
     .   : milestone, 689,
    master - mean (691ms)  : 668, 714
     .   : milestone, 691,

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

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (664ms)  : 639, 688
     .   : milestone, 664,
    master - mean (660ms)  : 638, 682
     .   : milestone, 660,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4938) - mean (189ms)  : 186, 192
     .   : milestone, 189,
    master - mean (189ms)  : 186, 192
     .   : milestone, 189,

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (1,138ms)  : 1122, 1154
     .   : milestone, 1138,
    master - mean (1,137ms)  : 1112, 1161
     .   : milestone, 1137,

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

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (1,095ms)  : 1070, 1119
     .   : milestone, 1095,
    master - mean (1,088ms)  : 1062, 1115
     .   : milestone, 1088,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4938) - mean (262ms)  : 259, 265
     .   : milestone, 262,
    master - mean (262ms)  : 259, 264
     .   : milestone, 262,

    section CallTarget+Inlining+NGEN
    This PR (4938) - mean (1,061ms)  : 1043, 1080
     .   : milestone, 1061,
    master - mean (1,062ms)  : 1033, 1091
     .   : milestone, 1062,

robertpi

changes to SetUser() look correct.

andrewlock · 2023-11-29T16:54:11Z

Benchmarks Report 🐌

Benchmarks for #4938 compared to master:

2 benchmarks are faster, with geometric mean 1.219
2 benchmarks are slower, with geometric mean 1.188
2 benchmarks have fewer allocations
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.87μs	49.2ns	311ns	0.019	0.00951	0	7.48 KB
master	`StartStopWithChild`	netcoreapp3.1	11.2μs	62.4ns	419ns	0.0278	0.0111	0	7.57 KB
master	`StartStopWithChild`	net472	17.7μs	61.2ns	237ns	1.34	0.357	0.113	7.96 KB
#4938	`StartStopWithChild`	net6.0	8.76μs	46.3ns	232ns	0.0211	0.00843	0	7.48 KB
#4938	`StartStopWithChild`	netcoreapp3.1	10.6μs	58.5ns	351ns	0.0256	0.0103	0	7.58 KB
#4938	`StartStopWithChild`	net472	17.1μs	61.7ns	239ns	1.34	0.352	0.0978	7.95 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	454μs	154ns	577ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	663μs	1.85μs	7.15μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	776μs	343ns	1.24μs	0.386	3.3 KB
#4938	`WriteAndFlushEnrichedTraces`	net6.0	462μs	125ns	434ns	0	2.7 KB
#4938	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	609μs	223ns	834ns	0	2.7 KB
#4938	`WriteAndFlushEnrichedTraces`	net472	775μs	246ns	920ns	0.386	3.3 KB

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

Slower ⚠️ in #4938

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑netcoreapp3.1	1.199	187.83	225.23

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`AllCycleSimpleBody`	net6.0	44.2μs	25.7ns	96.1ns	0.0223	0	1.77 KB
master	`AllCycleSimpleBody`	netcoreapp3.1	47.3μs	204ns	791ns	0.0235	0	1.74 KB
master	`AllCycleSimpleBody`	net472	49.4μs	22.6ns	87.5ns	0.273	0	1.81 KB
master	`AllCycleMoreComplexBody`	net6.0	213μs	198ns	767ns	0.106	0	9.25 KB
master	`AllCycleMoreComplexBody`	netcoreapp3.1	228μs	161ns	602ns	0.113	0	9.14 KB
master	`AllCycleMoreComplexBody`	net472	237μs	69.6ns	251ns	1.42	0	9.32 KB
master	`ObjectExtractorSimpleBody`	net6.0	129ns	0.0422ns	0.146ns	0.00396	0	280 B
master	`ObjectExtractorSimpleBody`	netcoreapp3.1	188ns	0.201ns	1ns	0.00369	0	272 B
master	`ObjectExtractorSimpleBody`	net472	152ns	0.115ns	0.432ns	0.0446	0	281 B
master	`ObjectExtractorMoreComplexBody`	net6.0	2.81μs	1.39ns	5.21ns	0.0537	0	3.78 KB
master	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	3.66μs	1.54ns	5.96ns	0.0493	0	3.69 KB
master	`ObjectExtractorMoreComplexBody`	net472	3.42μs	2.57ns	9.95ns	0.602	0.00513	3.8 KB
#4938	`AllCycleSimpleBody`	net6.0	44μs	30.9ns	120ns	0.0218	0	1.77 KB
#4938	`AllCycleSimpleBody`	netcoreapp3.1	46.9μs	22.6ns	81.6ns	0.0236	0	1.74 KB
#4938	`AllCycleSimpleBody`	net472	49.7μs	124ns	482ns	0.273	0	1.81 KB
#4938	`AllCycleMoreComplexBody`	net6.0	214μs	125ns	468ns	0.107	0	9.25 KB
#4938	`AllCycleMoreComplexBody`	netcoreapp3.1	226μs	297ns	1.15μs	0.112	0	9.14 KB
#4938	`AllCycleMoreComplexBody`	net472	239μs	61.4ns	230ns	1.44	0	9.32 KB
#4938	`ObjectExtractorSimpleBody`	net6.0	136ns	0.0898ns	0.348ns	0.00398	0	280 B
#4938	`ObjectExtractorSimpleBody`	netcoreapp3.1	225ns	0.181ns	0.7ns	0.00364	0	272 B
#4938	`ObjectExtractorSimpleBody`	net472	152ns	0.0384ns	0.133ns	0.0446	0	281 B
#4938	`ObjectExtractorMoreComplexBody`	net6.0	2.81μs	1.35ns	5.03ns	0.0535	0	3.78 KB
#4938	`ObjectExtractorMoreComplexBody`	netcoreapp3.1	3.74μs	1.07ns	4.02ns	0.0507	0	3.69 KB
#4938	`ObjectExtractorMoreComplexBody`	net472	3.74μs	2.46ns	9.21ns	0.603	0.0056	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	54.3μs	20.6ns	77.1ns	0.22	0	16.06 KB
master	`RunWaf(args=NestedMap (10))`	netcoreapp3.1	68.1μs	355ns	1.85μs	0.2	0	16.06 KB
master	`RunWaf(args=NestedMap (10))`	net472	97.5μs	419ns	1.62μs	2.52	0.0935	16.14 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	114μs	36.9ns	138ns	0.302	0	22.41 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	139μs	614ns	3.79μs	0.27	0	22.36 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	172μs	96.4ns	361ns	3.58	0.166	22.7 KB
master	`RunWaf(args=NestedMap (100))`	net6.0	93.1μs	25.4ns	98.4ns	0.425	0	32.76 KB
master	`RunWaf(args=NestedMap (100))`	netcoreapp3.1	125μs	372ns	1.34μs	0.457	0	33.33 KB
master	`RunWaf(args=NestedMap (100))`	net472	184μs	128ns	497ns	5.29	0.365	33.67 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	net6.0	165μs	83.6ns	324ns	0.497	0	39.1 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	netcoreapp3.1	210μs	82.8ns	299ns	0.526	0	39.63 KB
master	`RunWafWithAttack(args=Neste(...)tack) [23])`	net472	261μs	128ns	480ns	6.39	0.522	40.23 KB
master	`RunWaf(args=NestedMap (20))`	net6.0	97.1μs	158ns	610ns	0.455	0	32.18 KB
master	`RunWaf(args=NestedMap (20))`	netcoreapp3.1	135μs	209ns	810ns	0.4	0	32.3 KB
master	`RunWaf(args=NestedMap (20))`	net472	188μs	202ns	784ns	5.19	0.37	32.63 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	165μs	674ns	2.61μs	0.488	0	38.53 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	215μs	206ns	797ns	0.523	0	38.6 KB
master	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	265μs	849ns	3.29μs	6.16	0.513	39.2 KB
#4938	`RunWaf(args=NestedMap (10))`	net6.0	50.5μs	20.6ns	79.7ns	0.21	0	16.06 KB
#4938	`RunWaf(args=NestedMap (10))`	netcoreapp3.1	72.7μs	400ns	2.47μs	0.186	0	16.06 KB
#4938	`RunWaf(args=NestedMap (10))`	net472	94.4μs	29ns	112ns	2.54	0.0941	16.14 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	113μs	167ns	604ns	0.282	0	22.41 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	139μs	648ns	3.94μs	0.277	0	22.36 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	167μs	311ns	1.21μs	3.53	0.164	22.7 KB
#4938	`RunWaf(args=NestedMap (100))`	net6.0	94.4μs	33.8ns	131ns	0.417	0	32.76 KB
#4938	`RunWaf(args=NestedMap (100))`	netcoreapp3.1	131μs	702ns	3.84μs	0.438	0	33.33 KB
#4938	`RunWaf(args=NestedMap (100))`	net472	181μs	54.6ns	189ns	5.34	0.362	33.67 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [23])`	net6.0	166μs	95.7ns	371ns	0.492	0	39.1 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [23])`	netcoreapp3.1	209μs	727ns	2.81μs	0.502	0	39.63 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [23])`	net472	259μs	65.9ns	238ns	6.33	0.517	40.23 KB
#4938	`RunWaf(args=NestedMap (20))`	net6.0	103μs	23.8ns	89.2ns	0.437	0	32.18 KB
#4938	`RunWaf(args=NestedMap (20))`	netcoreapp3.1	129μs	623ns	2.64μs	0.383	0	32.3 KB
#4938	`RunWaf(args=NestedMap (20))`	net472	189μs	93.7ns	363ns	5.16	0.362	32.63 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	net6.0	175μs	917ns	4.3μs	0.517	0	38.53 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	netcoreapp3.1	203μs	1μs	4.13μs	0.496	0	38.6 KB
#4938	`RunWafWithAttack(args=Neste(...)tack) [22])`	net472	259μs	140ns	544ns	6.2	0.517	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	175μs	205ns	793ns	0.175	18.25 KB
master	`SendRequest`	netcoreapp3.1	191μs	423ns	1.64μs	0.19	20.41 KB
master	`SendRequest`	net472	0.00148ns	0.000362ns	0.0014ns	0	0 b
#4938	`SendRequest`	net6.0	173μs	244ns	946ns	0.174	18.25 KB
#4938	`SendRequest`	netcoreapp3.1	194μs	427ns	1.65μs	0.196	20.41 KB
#4938	`SendRequest`	net472	0.000493ns	0.000224ns	0.000867ns	0	0 b

Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Fewer allocations 🎉

Fewer allocations 🎉 in #4938

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1	41.92 KB	41.69 KB	-224 B	-0.53%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	544μs	617ns	2.31μs	0.556	0	0	41.51 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	661μs	586ns	2.27μs	0.327	0	0	41.92 KB
master	`WriteAndFlushEnrichedTraces`	net472	854μs	4.13μs	16.5μs	8.13	2.57	0.428	53.22 KB
#4938	`WriteAndFlushEnrichedTraces`	net6.0	545μs	872ns	3.38μs	0.532	0	0	41.5 KB
#4938	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	702μs	1.84μs	7.12μs	0.343	0	0	41.69 KB
#4938	`WriteAndFlushEnrichedTraces`	net472	812μs	2.8μs	10.8μs	8.36	2.39	0.398	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.01μs	0.427ns	1.65ns	0.0106	768 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.47μs	0.595ns	2.3ns	0.0102	768 B
master	`ExecuteNonQuery`	net472	1.79μs	3.66ns	14.2ns	0.116	730 B
#4938	`ExecuteNonQuery`	net6.0	1.05μs	0.633ns	2.45ns	0.011	768 B
#4938	`ExecuteNonQuery`	netcoreapp3.1	1.45μs	0.827ns	3.2ns	0.0102	768 B
#4938	`ExecuteNonQuery`	net472	1.82μs	0.73ns	2.73ns	0.116	730 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net6.0	1.22μs	0.865ns	3.24ns	0.0135	0	936 B
master	`CallElasticsearch`	netcoreapp3.1	1.54μs	0.942ns	3.52ns	0.0131	0	936 B
master	`CallElasticsearch`	net472	2.51μs	0.596ns	2.23ns	0.151	0	955 B
master	`CallElasticsearchAsync`	net6.0	1.24μs	0.521ns	2.02ns	0.013	0	912 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.64μs	0.349ns	1.31ns	0.013	0	984 B
master	`CallElasticsearchAsync`	net472	2.67μs	1.58ns	6.11ns	0.16	0	1.01 KB
#4938	`CallElasticsearch`	net6.0	1.17μs	1.08ns	4.16ns	0.0131	0	936 B
#4938	`CallElasticsearch`	netcoreapp3.1	1.45μs	0.49ns	1.9ns	0.0122	0	936 B
#4938	`CallElasticsearch`	net472	2.39μs	0.446ns	1.67ns	0.152	0	955 B
#4938	`CallElasticsearchAsync`	net6.0	1.26μs	0.455ns	1.7ns	0.0127	0	912 B
#4938	`CallElasticsearchAsync`	netcoreapp3.1	1.67μs	0.683ns	2.65ns	0.0137	0	984 B
#4938	`CallElasticsearchAsync`	net472	2.58μs	1.78ns	6.88ns	0.16	0.00129	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.29μs	1.51ns	5.85ns	0.0124	912 B
master	`ExecuteAsync`	netcoreapp3.1	1.57μs	0.761ns	2.85ns	0.012	912 B
master	`ExecuteAsync`	net472	1.81μs	1.15ns	4.45ns	0.139	875 B
#4938	`ExecuteAsync`	net6.0	1.38μs	0.625ns	2.34ns	0.0132	912 B
#4938	`ExecuteAsync`	netcoreapp3.1	1.57μs	2.08ns	7.78ns	0.0124	912 B
#4938	`ExecuteAsync`	net472	1.78μs	0.688ns	2.57ns	0.139	875 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	4.12μs	6.68ns	25ns	0.0287	2.1 KB
master	`SendAsync`	netcoreapp3.1	4.83μs	2.11ns	8.17ns	0.0363	2.63 KB
master	`SendAsync`	net472	7.82μs	2.5ns	9.35ns	0.522	3.31 KB
#4938	`SendAsync`	net6.0	3.98μs	1.87ns	7.24ns	0.0279	2.1 KB
#4938	`SendAsync`	netcoreapp3.1	4.88μs	2.31ns	8.93ns	0.0364	2.63 KB
#4938	`SendAsync`	net472	7.69μs	4ns	15.5ns	0.523	3.31 KB

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

More allocations ⚠️ in #4938

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑net472	59.66 KB	62.37 KB	2.7 KB	4.53%

Fewer allocations 🎉 in #4938

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑net472	65.54 KB	57.34 KB	-8.19 KB	-12.50%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Allocated
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net6.0	60.4μs	777ns	7.77μs	43.44 KB
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	57.5μs	738ns	7.12μs	42.64 KB
master	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net472	37.8μs	96.9ns	363ns	59.66 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net6.0	65.2μs	319ns	1.31μs	43.29 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	97.9μs	3.06μs	30.6μs	42.64 KB
master	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net472	57.3μs	902ns	8.84μs	65.54 KB
#4938	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net6.0	54.9μs	278ns	1.18μs	43.44 KB
#4938	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	61.9μs	721ns	7.07μs	42.64 KB
#4938	`StringConcatBenchmark(parameters=Syste(...)ring] [48])`	net472	37.4μs	119ns	445ns	62.37 KB
#4938	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net6.0	96.3μs	2.96μs	29.6μs	43.29 KB
#4938	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	netcoreapp3.1	95.6μs	3.3μs	32.7μs	42.64 KB
#4938	`StringConcatAspectBenchmark(parameters=Syste(...)ring] [48])`	net472	63.3μs	296ns	1.19μs	57.34 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.52μs	0.591ns	2.29ns	0.0221	1.57 KB
master	`EnrichedLog`	netcoreapp3.1	2.17μs	0.943ns	3.53ns	0.0208	1.57 KB
master	`EnrichedLog`	net472	2.66μs	1.07ns	3.85ns	0.238	1.5 KB
#4938	`EnrichedLog`	net6.0	1.48μs	0.883ns	3.3ns	0.0223	1.57 KB
#4938	`EnrichedLog`	netcoreapp3.1	2.16μs	1.47ns	5.68ns	0.0207	1.57 KB
#4938	`EnrichedLog`	net472	2.53μs	2.31ns	8.63ns	0.238	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	113μs	140ns	542ns	0.0563	0	4.21 KB
master	`EnrichedLog`	netcoreapp3.1	119μs	296ns	1.15μs	0.0587	0	4.21 KB
master	`EnrichedLog`	net472	149μs	277ns	1.07μs	0.667	0.222	4.39 KB
#4938	`EnrichedLog`	net6.0	115μs	194ns	751ns	0	0	4.21 KB
#4938	`EnrichedLog`	netcoreapp3.1	120μs	168ns	650ns	0	0	4.21 KB
#4938	`EnrichedLog`	net472	149μs	115ns	445ns	0.669	0.223	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.03μs	1.11ns	4.28ns	0.0288	2.13 KB
master	`EnrichedLog`	netcoreapp3.1	4.13μs	1.76ns	6.81ns	0.0288	2.13 KB
master	`EnrichedLog`	net472	4.89μs	3.71ns	14.4ns	0.308	1.95 KB
#4938	`EnrichedLog`	net6.0	3.08μs	0.674ns	2.52ns	0.0294	2.13 KB
#4938	`EnrichedLog`	netcoreapp3.1	4.34μs	1.43ns	5.35ns	0.0284	2.13 KB
#4938	`EnrichedLog`	net472	4.98μs	3.41ns	13.2ns	0.308	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.33μs	0.84ns	3.14ns	0.0158	1.1 KB
master	`SendReceive`	netcoreapp3.1	1.78μs	0.908ns	3.52ns	0.0152	1.1 KB
master	`SendReceive`	net472	2.01μs	1.22ns	4.72ns	0.177	1.12 KB
#4938	`SendReceive`	net6.0	1.26μs	0.424ns	1.53ns	0.0156	1.1 KB
#4938	`SendReceive`	netcoreapp3.1	1.8μs	0.681ns	2.64ns	0.0152	1.1 KB
#4938	`SendReceive`	net472	2.18μs	2.41ns	9.35ns	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.73μs	3.2ns	12.4ns	0.0204	1.53 KB
master	`EnrichedLog`	netcoreapp3.1	3.87μs	1.41ns	4.89ns	0.0214	1.58 KB
master	`EnrichedLog`	net472	4.33μs	1.26ns	4.87ns	0.312	1.97 KB
#4938	`EnrichedLog`	net6.0	2.73μs	0.853ns	3.07ns	0.0206	1.53 KB
#4938	`EnrichedLog`	netcoreapp3.1	3.79μs	2.28ns	8.51ns	0.0207	1.58 KB
#4938	`EnrichedLog`	net472	4.27μs	15.2ns	58.8ns	0.312	1.97 KB

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

Slower ⚠️ in #4938

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0	1.177	461.31	542.86

Faster 🎉 in #4938

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net472	1.162	1,050.35	904.02

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	461ns	0.401ns	1.55ns	0.00759	536 B
master	`StartFinishSpan`	netcoreapp3.1	694ns	0.455ns	1.64ns	0.00704	536 B
master	`StartFinishSpan`	net472	728ns	0.915ns	3.42ns	0.0854	538 B
master	`StartFinishScope`	net6.0	572ns	0.705ns	2.73ns	0.00908	656 B
master	`StartFinishScope`	netcoreapp3.1	857ns	0.47ns	1.82ns	0.00864	656 B
master	`StartFinishScope`	net472	1.05μs	1.32ns	5.09ns	0.0977	618 B
#4938	`StartFinishSpan`	net6.0	543ns	0.432ns	1.67ns	0.0075	536 B
#4938	`StartFinishSpan`	netcoreapp3.1	760ns	0.228ns	0.852ns	0.00714	536 B
#4938	`StartFinishSpan`	net472	769ns	0.291ns	1.09ns	0.0852	538 B
#4938	`StartFinishScope`	net6.0	550ns	0.313ns	1.21ns	0.0091	656 B
#4938	`StartFinishScope`	netcoreapp3.1	944ns	0.291ns	1.13ns	0.00889	656 B
#4938	`StartFinishScope`	net472	907ns	2.12ns	7.92ns	0.0978	618 B

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

Faster 🎉 in #4938

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0	1.280	834.89	652.39

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	836ns	1.11ns	4.3ns	0.00929	656 B
master	`RunOnMethodBegin`	netcoreapp3.1	988ns	0.798ns	3.09ns	0.00908	656 B
master	`RunOnMethodBegin`	net472	1.16μs	1.24ns	4.81ns	0.098	618 B
#4938	`RunOnMethodBegin`	net6.0	653ns	0.484ns	1.87ns	0.00905	656 B
#4938	`RunOnMethodBegin`	netcoreapp3.1	996ns	0.294ns	1.06ns	0.00909	656 B
#4938	`RunOnMethodBegin`	net472	1.06μs	0.364ns	1.36ns	0.0978	618 B

andrewlock · 2023-11-29T17:09:37Z

Throughput/Crank Report:zap:

Throughput results for AspNetCoreSimpleController comparing the following branches/commits:

Cases where throughput results for the PR are worse than latest master (5% drop or greater), results are shown in red.

Note that these results are based on a single point-in-time result for each branch. For full results, see one of the many, many dashboards!

gantt
    title Throughput Linux x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4938) (11.122M)   : 0, 11121803
    master (11.333M)   : 0, 11332518
    benchmarks/2.9.0 (11.258M)   : 0, 11257868

    section Automatic
    This PR (4938) (7.601M)   : 0, 7600519
    master (7.657M)   : 0, 7657438
    benchmarks/2.9.0 (8.046M)   : 0, 8046105

    section Trace stats
    This PR (4938) (7.923M)   : 0, 7922771
    master (8.054M)   : 0, 8053668

    section Manual
    This PR (4938) (9.515M)   : 0, 9515222
    master (10.004M)   : 0, 10003794

    section Manual + Automatic
    This PR (4938) (7.229M)   : 0, 7228579
    master (7.437M)   : 0, 7436536

    section Version Conflict
    This PR (4938) (6.451M)   : 0, 6450889
    master (6.771M)   : 0, 6770626

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4938) (9.684M)   : 0, 9684065
    master (9.642M)   : 0, 9641863
    benchmarks/2.9.0 (9.571M)   : 0, 9571091

    section Automatic
    This PR (4938) (6.690M)   : 0, 6690421
    master (6.503M)   : 0, 6503245

    section Trace stats
    This PR (4938) (6.694M)   : 0, 6693776
    master (6.987M)   : 0, 6987377

    section Manual
    This PR (4938) (8.259M)   : 0, 8259425
    master (8.537M)   : 0, 8536637

    section Manual + Automatic
    This PR (4938) (6.129M)   : 0, 6128939
    master (6.089M)   : 0, 6089321

    section Version Conflict
    This PR (4938) (5.795M)   : 0, 5795448
    master (5.724M)   : 0, 5723643

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4938) (10.824M)   : 0, 10824003
    master (10.254M)   : 0, 10253707
    benchmarks/2.9.0 (8.981M)   : 0, 8981100

    section Automatic
    This PR (4938) (7.661M)   : 0, 7661277
    master (6.421M)   : 0, 6420836
    benchmarks/2.9.0 (6.621M)   : 0, 6621015

    section Trace stats
    This PR (4938) (8.098M)   : 0, 8097800
    master (6.589M)   : 0, 6589319

    section Manual
    This PR (4938) (9.773M)   : 0, 9773304
    master (7.901M)   : 0, 7900787

    section Manual + Automatic
    This PR (4938) (7.381M)   : 0, 7380600
    master (6.157M)   : 0, 6157174

    section Version Conflict
    This PR (4938) (6.655M)   : 0, 6655176
    master (5.598M)   : 0, 5598196

gantt
    title Throughput Linux x64 (ASM) (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    master (7.353M)   : 0, 7352773
    benchmarks/2.9.0 (7.805M)   : 0, 7805126

    section No attack
    master (1.971M)   : 0, 1971063
    benchmarks/2.9.0 (3.177M)   : 0, 3177224

    section Attack
    master (1.553M)   : 0, 1553355
    benchmarks/2.9.0 (2.505M)   : 0, 2504790

    section Blocking
    master (3.237M)   : 0, 3236693

    section IAST default
    master (6.655M)   : 0, 6654796

    section IAST full
    master (5.949M)   : 0, 5949094

    section Base vuln
    master (0.974M)   : 0, 974472

    section IAST vuln
    master (0.921M)   : 0, 920725

lucaspimentel · 2023-11-30T14:54:47Z

tracer/src/Datadog.Trace/SpanExtensions.Core.cs

+                RunBlockingCheckUnsafe(security, span, userId);
+            }
+
+            // Don't inline this, so we don't load the aspnetcore types if they're not available


Nice trick.

andrewlock added 3 commits November 29, 2023 15:01

Add integration tests + sample for manual instrumentation

19135ae

Add fix for calling SetUser outside of an ASP.NET Core context

6fc7171

Add workaround for the flake

e8d958e

andrewlock added type:bug area:tests unit tests, integration tests labels Nov 29, 2023

andrewlock requested review from a team as code owners November 29, 2023 15:10

robertpi approved these changes Nov 29, 2023

View reviewed changes

Fix manual snapshots

95fbc97

lucaspimentel reviewed Nov 30, 2023

View reviewed changes

lucaspimentel approved these changes Nov 30, 2023

View reviewed changes

kevingosse approved these changes Nov 30, 2023

View reviewed changes

andrewlock merged commit a1a1a81 into master Dec 1, 2023
54 checks passed

andrewlock deleted the andrew/add-manual-instrumentation-integration-test branch December 1, 2023 10:44

github-actions bot added this to the vNext milestone Dec 1, 2023

andrewlock mentioned this pull request Dec 7, 2023

Un-skip manual instrumentation tests and fix flake #4960

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add manual+automatic instrumentation tests + fix `SetUser` bug #4938

Add manual+automatic instrumentation tests + fix `SetUser` bug #4938

andrewlock commented Nov 29, 2023

datadog-ddstaging bot commented Nov 29, 2023 •

edited

Loading

andrewlock commented Nov 29, 2023 •

edited

Loading

robertpi left a comment

andrewlock commented Nov 29, 2023 •

edited

Loading

Raw results

Raw results

Slower ⚠️ in #4938

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #4938

Raw results

Raw results

Raw results

Raw results

Raw results

More allocations ⚠️ in #4938

Fewer allocations 🎉 in #4938

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #4938

Faster 🎉 in #4938

Raw results

Faster 🎉 in #4938

Raw results

andrewlock commented Nov 29, 2023 •

edited

Loading

lucaspimentel Nov 30, 2023

Add manual+automatic instrumentation tests + fix SetUser bug #4938

Add manual+automatic instrumentation tests + fix SetUser bug #4938

Conversation

andrewlock commented Nov 29, 2023

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

datadog-ddstaging bot commented Nov 29, 2023 • edited Loading

Datadog Report

New Flaky Tests (1)

andrewlock commented Nov 29, 2023 • edited Loading

Execution-Time Benchmarks Report ⏱️

robertpi left a comment

Choose a reason for hiding this comment

andrewlock commented Nov 29, 2023 • edited Loading

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Slower ⚠️ in #4938

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #4938

Raw results

Raw results

Raw results

Raw results

Raw results

More allocations ⚠️ in #4938

Fewer allocations 🎉 in #4938

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #4938

Faster 🎉 in #4938

Raw results

Faster 🎉 in #4938

Raw results

andrewlock commented Nov 29, 2023 • edited Loading

Throughput/Crank Report:zap:

lucaspimentel Nov 30, 2023

Choose a reason for hiding this comment

Add manual+automatic instrumentation tests + fix `SetUser` bug #4938

Add manual+automatic instrumentation tests + fix `SetUser` bug #4938

datadog-ddstaging bot commented Nov 29, 2023 •

edited

Loading

andrewlock commented Nov 29, 2023 •

edited

Loading

andrewlock commented Nov 29, 2023 •

edited

Loading

andrewlock commented Nov 29, 2023 •

edited

Loading