Opt Datadog.Trace.Manual out of NGEN by andrewlock · Pull Request #6168 · DataDog/dd-trace-dotnet

andrewlock · 2024-10-18T16:05:34Z

Summary of changes

Adds a test that uses manual instrumentation with Ready-to-run (r2r)
Disable using the ngen images of Datadog.Trace.Manual

Reason for change

In #6124 we have narrowed down the root cause of a failure to get manual instrumentation to an interaction with r2r images. In this scenario, some of the methods in Datadog.Trace.Manual (GetAutomaticTracer() specifically) do not get rejitted, even though a rejit is requested and we request rejitting of the inliner (Tracer.Instance). This causes manual instrumenation in v3 to break in this scenario).

It's still not clear exactly why this is happening. It only happens in some scenarios. For example the following Program.cs (compiled with r2r for any platform) reproduces the issue

await Task.Yield();

using(Tracer.Instance.StartActive("manual"))
{
}

Omitting the Task.Yield() means the problem does not reproduce. Adding additional methods at the end of this also can cause the method to not reproduce.

Additionally, we rewrite some methods directly (rather than using calltarget rewriting) in TryRejitModule (we rewrite IsManualInstrumentationOnly()). However, the rewritten method is not used. This is likely because JITCachedFunctionSearchStarted runs after this, and we return useCachedMethod=true for the method, so the rewritten method is never used.

Implementation details

We have explored various approaches (@tonyredondo is actively exploring in #6165), but the simplest is to simply disable NGEN for the Datadog.Trace.Manual module. The vast majority of this assembly is rewritten anyway (for v3 manual instrumentation) so the perf impact will be low, and it solves all of the reproduction cases.

We're pretty sure there's a more generic problem/solution here, but as it's not clear exactly what that is, this is the simplest solution to the immediate issue.

Test coverage

Added a new test that uses an r2r version of Samples.ManualInstrumentation. Prior to this fix, the test fails. With the fix, the test passes.

One (strange) caveat is that the test was previously reading a property, IsManualInstrumentationOnly, via reflection. This property is rewritten by the profiler, but with r2r we consistently return the old value. This happens whether we rewrite it directly using the profiler API (in TryRejitModule, as we do now) or if we use a CallTarget integration instead. The good news is that this doesn't happen in practice, so I think we can chalk this up to "weird" for now, and look into it further later if the need arises.

Other details

Fixes #6124

We briefly looked into reenabling RequestReJITWithInliners as in here (which was removed due to a crashing bug dotnet/runtime#77973), as this has been fixed in .NET 7+, however that simple change didn't resolve the problem + the problem exists on earlier runtimes anyway, so we need a fix that works everywhere.

github-actions · 2024-10-18T16:06:26Z

Snapshots difference summary

The following differences have been observed in committed snapshots. It is meant to help the reviewer.
The diff is simplistic, so please check some files anyway while we improve it.

1 occurrences of :

+    Name: initial,
+    Resource: initial,
+    Service: Samples.ManualInstrumentation,
+    Tags: {
+      env: integration_tests,
+      language: dotnet,
+      runtime-id: Guid_1
+    },
+    Metrics: {
+      process_id: 0,
+      _dd.top_level: 1.0,
+      _dd.tracer_kr: 1.0,
+      _sampling_priority_v1: 1.0
+    }
+  },
+  {
+    TraceId: Id_3,
+    SpanId: Id_4,

1 occurrences of :

-    TraceId: Id_1,
-    SpanId: Id_3,
+    TraceId: Id_3,
+    SpanId: Id_5,
[...]
-    ParentId: Id_2,
+    ParentId: Id_4,
[...]
-    TraceId: Id_1,
-    SpanId: Id_4,
+    TraceId: Id_3,
+    SpanId: Id_6,
[...]
-    ParentId: Id_3,
+    ParentId: Id_5,

1 occurrences of :

-    TraceId: Id_5,
-    SpanId: Id_6,
+    TraceId: Id_7,
+    SpanId: Id_8,

1 occurrences of :

-    TraceId: Id_7,
-    SpanId: Id_8,
+    TraceId: Id_9,
+    SpanId: Id_10,

1 occurrences of :

-    TraceId: Id_7,
-    SpanId: Id_9,
+    TraceId: Id_9,
+    SpanId: Id_11,
[...]
-    ParentId: Id_8,
+    ParentId: Id_10,

1 occurrences of :

-    TraceId: Id_7,
-    SpanId: Id_10,
+    TraceId: Id_9,
+    SpanId: Id_12,
[...]
-    ParentId: Id_9,
+    ParentId: Id_11,

1 occurrences of :

-    TraceId: Id_11,
-    SpanId: Id_12,
+    TraceId: Id_13,
+    SpanId: Id_14,

1 occurrences of :

-    TraceId: Id_13,
-    SpanId: Id_14,
+    TraceId: Id_15,
+    SpanId: Id_16,

1 occurrences of :

-    TraceId: Id_13,
-    SpanId: Id_15,
+    TraceId: Id_15,
+    SpanId: Id_17,
[...]
-    ParentId: Id_14,
+    ParentId: Id_16,
[...]
-    TraceId: Id_16,
-    SpanId: Id_17,
+    TraceId: Id_18,
+    SpanId: Id_19,

1 occurrences of :

-    TraceId: Id_18,
-    SpanId: Id_19,
+    TraceId: Id_20,
+    SpanId: Id_21,

1 occurrences of :

-    TraceId: Id_18,
-    SpanId: Id_20,
+    TraceId: Id_20,
+    SpanId: Id_22,
[...]
-    ParentId: Id_19,
+    ParentId: Id_21,
[...]
-    TraceId: Id_18,
-    SpanId: Id_21,
+    TraceId: Id_20,
+    SpanId: Id_23,
[...]
-    ParentId: Id_20,
+    ParentId: Id_22,

1 occurrences of :

-    TraceId: Id_22,
-    SpanId: Id_23,
+    TraceId: Id_24,
+    SpanId: Id_25,

1 occurrences of :

-    TraceId: Id_24,
-    SpanId: Id_25,
+    TraceId: Id_26,
+    SpanId: Id_27,

1 occurrences of :

-    TraceId: Id_26,
-    SpanId: Id_27,
+    TraceId: Id_28,
+    SpanId: Id_29,

1 occurrences of :

-    TraceId: Id_26,
-    SpanId: Id_28,
+    TraceId: Id_28,
+    SpanId: Id_30,
[...]
-    ParentId: Id_27,
+    ParentId: Id_29,

1 occurrences of :

-    TraceId: Id_26,
-    SpanId: Id_29,
+    TraceId: Id_28,
+    SpanId: Id_31,
[...]
-    ParentId: Id_28,
+    ParentId: Id_30,
[...]
-    TraceId: Id_26,
-    SpanId: Id_30,
+    TraceId: Id_28,
+    SpanId: Id_32,
[...]
-    ParentId: Id_29,
+    ParentId: Id_31,

1 occurrences of :

-    TraceId: Id_31,
-    SpanId: Id_32,
+    TraceId: Id_33,
+    SpanId: Id_34,

1 occurrences of :

-    TraceId: Id_31,
-    SpanId: Id_33,
+    TraceId: Id_33,
+    SpanId: Id_35,
[...]
-    ParentId: Id_32,
+    ParentId: Id_34,
[...]
-    TraceId: Id_31,
-    SpanId: Id_34,
+    TraceId: Id_33,
+    SpanId: Id_36,
[...]
-    ParentId: Id_33,
+    ParentId: Id_35,
[...]
-    TraceId: Id_31,
-    SpanId: Id_35,
+    TraceId: Id_33,
+    SpanId: Id_37,
[...]
-    ParentId: Id_34,
+    ParentId: Id_36,

1 occurrences of :

-    TraceId: Id_36,
-    SpanId: Id_37,
+    TraceId: Id_38,
+    SpanId: Id_39,

1 occurrences of :

-    TraceId: Id_38,
-    SpanId: Id_39,
+    TraceId: Id_40,
+    SpanId: Id_41,

1 occurrences of :

-    TraceId: Id_38,
-    SpanId: Id_40,
+    TraceId: Id_40,
+    SpanId: Id_42,
[...]
-    ParentId: Id_39,
+    ParentId: Id_41,
[...]
-    TraceId: Id_38,
-    SpanId: Id_41,
+    TraceId: Id_40,
+    SpanId: Id_43,
[...]
-    ParentId: Id_40,
+    ParentId: Id_42,
[...]
-    TraceId: Id_38,
-    SpanId: Id_42,
+    TraceId: Id_40,
+    SpanId: Id_44,
[...]
-    ParentId: Id_41,
+    ParentId: Id_43,

1 occurrences of :

-    TraceId: Id_43,
-    SpanId: Id_44,
+    TraceId: Id_45,
+    SpanId: Id_46,

1 occurrences of :

-    TraceId: Id_45,
-    SpanId: Id_46,
+    TraceId: Id_47,
+    SpanId: Id_48,

1 occurrences of :

-    TraceId: Id_45,
-    SpanId: Id_47,
+    TraceId: Id_47,
+    SpanId: Id_49,
[...]
-    ParentId: Id_46,
+    ParentId: Id_48,
[...]
-    TraceId: Id_45,
-    SpanId: Id_48,
+    TraceId: Id_47,
+    SpanId: Id_50,
[...]
-    ParentId: Id_47,
+    ParentId: Id_49,
[...]
-    TraceId: Id_45,
-    SpanId: Id_49,
+    TraceId: Id_47,
+    SpanId: Id_51,
[...]
-    ParentId: Id_48,
+    ParentId: Id_50,

1 occurrences of :

-    TraceId: Id_50,
-    SpanId: Id_51,
+    TraceId: Id_52,
+    SpanId: Id_53,

1 occurrences of :

-    TraceId: Id_52,
-    SpanId: Id_53,
+    TraceId: Id_54,
+    SpanId: Id_55,

tonyredondo

LGTM as a temporal fix of the issue. We need to keep digging and work on a general solution.

datadog-ddstaging · 2024-10-18T16:14:10Z

Datadog Report

Branch report: andrew/ready-to-run
Commit report: 1072d93
Test service: dd-trace-dotnet

✅ 0 Failed, 371620 Passed, 2742 Skipped, 26h 10m 3.46s Total Time
❄️ 2 New Flaky

New Flaky Tests (2)

HttpClient_SubmitsTraces - Datadog.Trace.ClrProfiler.IntegrationTests.HttpMessageHandlerTests - Last Failure

Expand for error

 
 Expected var integration = latestIntegrations {empty} to contain key "CurlHandler".), but no such item was found.t found False.

HttpClient_SubmitsTraces - Datadog.Trace.ClrProfiler.IntegrationTests.HttpMessageHandlerTests - Last Failure

Expand for error

 
 Expected var integration = latestIntegrations {empty} to contain key "CurlHandler".), but no such item was found.t found False.

andrewlock · 2024-10-18T16:51:05Z

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 (6168) - mean (72ms)  : 67, 78
     .   : milestone, 72,
    master - mean (71ms)  : 68, 75
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (1,118ms)  : 1097, 1139
     .   : milestone, 1118,
    master - mean (1,120ms)  : 1092, 1149
     .   : milestone, 1120,

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

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (777ms)  : 763, 792
     .   : milestone, 777,
    master - mean (776ms)  : 757, 795
     .   : milestone, 776,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6168) - mean (93ms)  : 90, 96
     .   : milestone, 93,
    master - mean (93ms)  : 89, 97
     .   : milestone, 93,

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (734ms)  : 712, 755
     .   : milestone, 734,
    master - mean (728ms)  : 710, 746
     .   : milestone, 728,

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

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (1,201ms)  : 1180, 1222
     .   : milestone, 1201,
    master - mean (1,193ms)  : 1168, 1218
     .   : milestone, 1193,

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

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (948ms)  : 932, 965
     .   : milestone, 948,
    master - mean (943ms)  : 924, 961
     .   : milestone, 943,

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

    section CallTarget+Inlining+NGEN
    This PR (6168) - mean (928ms)  : 907, 948
     .   : milestone, 928,
    master - mean (923ms)  : 907, 938
     .   : milestone, 923,

andrewlock · 2024-10-18T17:17:56Z

  {
    TraceId: Id_1,
    SpanId: Id_2,
+    Name: initial,


This is the only actual change in the snapshot, the rest are just bumping of IDs

andrewlock · 2024-10-18T17:19:08Z

    public async Task ManualAndAutomatic()
    {
-        const int expectedSpans = 36;
+        const int expectedSpans = 37;


Not a fan of this test re-using the sample and duplicating this - I'd rather just move the extra assertions to ManualInstrumentationTests - will do that in a separate PR

andrewlock · 2024-10-18T18:55:44Z

Benchmarks Report for tracer 🐌

Benchmarks for #6168 compared to master:

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.93μs	45.4ns	340ns	0.0115	0.00384	0	5.43 KB
master	`StartStopWithChild`	netcoreapp3.1	9.91μs	54ns	305ns	0.0196	0.0098	0	5.61 KB
master	`StartStopWithChild`	net472	16.1μs	50.7ns	190ns	1.03	0.317	0.0974	6.07 KB
#6168	`StartStopWithChild`	net6.0	7.64μs	42.3ns	268ns	0.0185	0.00738	0	5.43 KB
#6168	`StartStopWithChild`	netcoreapp3.1	10.1μs	53.9ns	300ns	0.0246	0.00985	0	5.61 KB
#6168	`StartStopWithChild`	net472	16.6μs	65.4ns	253ns	1.01	0.295	0.0903	6.06 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	469μs	291ns	1.09μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	643μs	476ns	1.84μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	839μs	280ns	1.05μs	0.419	3.3 KB
#6168	`WriteAndFlushEnrichedTraces`	net6.0	481μs	158ns	593ns	0	2.7 KB
#6168	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	639μs	326ns	1.22μs	0	2.7 KB
#6168	`WriteAndFlushEnrichedTraces`	net472	842μs	560ns	2.17μs	0.417	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	201μs	1.15μs	9.09μs	0.212	18.45 KB
master	`SendRequest`	netcoreapp3.1	222μs	1.29μs	11μs	0.209	20.61 KB
master	`SendRequest`	net472	0.00171ns	0.000718ns	0.00259ns	0	0 b
#6168	`SendRequest`	net6.0	199μs	1.16μs	10μs	0.203	18.45 KB
#6168	`SendRequest`	netcoreapp3.1	225μs	1.28μs	9.49μs	0.22	20.61 KB
#6168	`SendRequest`	net472	0ns	0ns	0ns	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	568μs	2.69μs	10.8μs	0.587	0	0	41.79 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	687μs	3.08μs	13μs	0.338	0	0	41.84 KB
master	`WriteAndFlushEnrichedTraces`	net472	875μs	3.41μs	13.2μs	8.25	2.6	0.434	53.3 KB
#6168	`WriteAndFlushEnrichedTraces`	net6.0	583μs	3.08μs	15.1μs	0.563	0	0	41.61 KB
#6168	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	663μs	2.46μs	8.86μs	0.332	0	0	41.77 KB
#6168	`WriteAndFlushEnrichedTraces`	net472	864μs	3.61μs	13.5μs	8.13	2.57	0.428	53.29 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	0.969ns	3.49ns	0.0141	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.8μs	0.913ns	3.54ns	0.0135	1.02 KB
master	`ExecuteNonQuery`	net472	2.19μs	1.67ns	6.47ns	0.156	987 B
#6168	`ExecuteNonQuery`	net6.0	1.24μs	5.78ns	28.3ns	0.0147	1.02 KB
#6168	`ExecuteNonQuery`	netcoreapp3.1	1.78μs	1.22ns	4.72ns	0.0134	1.02 KB
#6168	`ExecuteNonQuery`	net472	2.12μs	1.47ns	5.69ns	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.19μs	0.438ns	1.64ns	0.0138	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.52μs	0.556ns	2.08ns	0.0129	976 B
master	`CallElasticsearch`	net472	2.44μs	1.34ns	5.18ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.27μs	0.543ns	2.1ns	0.0134	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.64μs	0.672ns	2.52ns	0.0139	1.02 KB
master	`CallElasticsearchAsync`	net472	2.56μs	1.23ns	4.61ns	0.166	1.05 KB
#6168	`CallElasticsearch`	net6.0	1.21μs	0.669ns	2.59ns	0.014	976 B
#6168	`CallElasticsearch`	netcoreapp3.1	1.51μs	0.798ns	2.88ns	0.0129	976 B
#6168	`CallElasticsearch`	net472	2.58μs	1.87ns	7.24ns	0.158	995 B
#6168	`CallElasticsearchAsync`	net6.0	1.33μs	0.631ns	2.36ns	0.0132	952 B
#6168	`CallElasticsearchAsync`	netcoreapp3.1	1.62μs	1.12ns	4.18ns	0.0137	1.02 KB
#6168	`CallElasticsearchAsync`	net472	2.68μs	2.88ns	11.1ns	0.167	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.33μs	0.549ns	2.13ns	0.0133	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.57μs	1.27ns	4.92ns	0.0124	952 B
master	`ExecuteAsync`	net472	1.74μs	1.04ns	4.02ns	0.145	915 B
#6168	`ExecuteAsync`	net6.0	1.25μs	0.585ns	2.19ns	0.0133	952 B
#6168	`ExecuteAsync`	netcoreapp3.1	1.59μs	1.2ns	4.63ns	0.0127	952 B
#6168	`ExecuteAsync`	net472	1.74μs	0.942ns	3.53ns	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.27μs	2.07ns	7.76ns	0.0299	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.17μs	2.19ns	8.49ns	0.0361	2.76 KB
master	`SendAsync`	net472	7.87μs	3.33ns	12.5ns	0.499	3.15 KB
#6168	`SendAsync`	net6.0	4.27μs	2.07ns	7.16ns	0.03	2.22 KB
#6168	`SendAsync`	netcoreapp3.1	4.95μs	1.79ns	6.94ns	0.0371	2.76 KB
#6168	`SendAsync`	net472	7.67μs	2.17ns	8.39ns	0.5	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.55μs	1.1ns	4.27ns	0.0228	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.15μs	1.23ns	4.6ns	0.0225	1.64 KB
master	`EnrichedLog`	net472	2.6μs	1.39ns	5.38ns	0.249	1.57 KB
#6168	`EnrichedLog`	net6.0	1.43μs	1.01ns	3.9ns	0.023	1.64 KB
#6168	`EnrichedLog`	netcoreapp3.1	2.13μs	0.543ns	2.03ns	0.0225	1.64 KB
#6168	`EnrichedLog`	net472	2.5μs	0.933ns	3.49ns	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	96.4ns	361ns	0.0578	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	122μs	232ns	900ns	0.0602	0	4.28 KB
master	`EnrichedLog`	net472	152μs	166ns	644ns	0.69	0.23	4.46 KB
#6168	`EnrichedLog`	net6.0	117μs	191ns	687ns	0.0591	0	4.28 KB
#6168	`EnrichedLog`	netcoreapp3.1	121μs	162ns	605ns	0	0	4.28 KB
#6168	`EnrichedLog`	net472	148μs	109ns	409ns	0.667	0.222	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.11μs	0.716ns	2.58ns	0.0313	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.33μs	1.71ns	6.61ns	0.0282	2.2 KB
master	`EnrichedLog`	net472	4.93μs	6.89ns	25.8ns	0.319	2.02 KB
#6168	`EnrichedLog`	net6.0	3.23μs	0.902ns	3.38ns	0.0308	2.2 KB
#6168	`EnrichedLog`	netcoreapp3.1	4.26μs	0.851ns	3.18ns	0.0298	2.2 KB
#6168	`EnrichedLog`	net472	4.77μs	1.49ns	5.77ns	0.319	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.43μs	0.937ns	3.63ns	0.0157	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.71μs	0.819ns	3.17ns	0.0155	1.14 KB
master	`SendReceive`	net472	2.06μs	0.77ns	2.98ns	0.183	1.16 KB
#6168	`SendReceive`	net6.0	1.36μs	0.734ns	2.74ns	0.0157	1.14 KB
#6168	`SendReceive`	netcoreapp3.1	1.75μs	1.74ns	6.75ns	0.0148	1.14 KB
#6168	`SendReceive`	net472	2.03μs	0.8ns	2.99ns	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.6μs	0.915ns	3.54ns	0.0221	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.88μs	1.14ns	4.11ns	0.0213	1.65 KB
master	`EnrichedLog`	net472	4.43μs	2.41ns	9.04ns	0.323	2.04 KB
#6168	`EnrichedLog`	net6.0	2.75μs	0.648ns	2.51ns	0.022	1.6 KB
#6168	`EnrichedLog`	netcoreapp3.1	3.81μs	1.05ns	4.07ns	0.0209	1.65 KB
#6168	`EnrichedLog`	net472	4.36μs	3.59ns	13.9ns	0.324	2.04 KB

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

Slower ⚠️ in #6168

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472	1.114	701.48	781.75

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	399ns	0.157ns	0.586ns	0.008	576 B
master	`StartFinishSpan`	netcoreapp3.1	621ns	3.35ns	18.1ns	0.00757	576 B
master	`StartFinishSpan`	net472	699ns	1.14ns	4.4ns	0.0918	578 B
master	`StartFinishScope`	net6.0	486ns	0.18ns	0.698ns	0.00964	696 B
master	`StartFinishScope`	netcoreapp3.1	703ns	0.374ns	1.4ns	0.00913	696 B
master	`StartFinishScope`	net472	968ns	0.287ns	1.04ns	0.104	658 B
#6168	`StartFinishSpan`	net6.0	440ns	0.265ns	1.03ns	0.00817	576 B
#6168	`StartFinishSpan`	netcoreapp3.1	552ns	0.268ns	1ns	0.00777	576 B
#6168	`StartFinishSpan`	net472	783ns	0.825ns	3.19ns	0.0917	578 B
#6168	`StartFinishScope`	net6.0	535ns	0.311ns	1.2ns	0.00967	696 B
#6168	`StartFinishScope`	netcoreapp3.1	743ns	0.88ns	3.41ns	0.00955	696 B
#6168	`StartFinishScope`	net472	877ns	0.571ns	2.21ns	0.104	658 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	652ns	0.414ns	1.6ns	0.00985	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	906ns	0.628ns	2.35ns	0.00949	696 B
master	`RunOnMethodBegin`	net472	1.14μs	0.206ns	0.744ns	0.105	658 B
#6168	`RunOnMethodBegin`	net6.0	687ns	0.235ns	0.909ns	0.01	696 B
#6168	`RunOnMethodBegin`	netcoreapp3.1	907ns	0.506ns	1.89ns	0.00925	696 B
#6168	`RunOnMethodBegin`	net472	1.13μs	0.384ns	1.49ns	0.105	658 B

andrewlock · 2024-10-18T18:57:47Z

Throughput/Crank Report ⚡

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 (6168) (11.097M)   : 0, 11097394
    master (11.202M)   : 0, 11201555
    benchmarks/2.9.0 (11.081M)   : 0, 11080577

    section Automatic
    This PR (6168) (7.422M)   : 0, 7421987
    master (7.284M)   : 0, 7284215
    benchmarks/2.9.0 (7.732M)   : 0, 7732233

    section Trace stats
    master (7.733M)   : 0, 7732535

    section Manual
    master (11.196M)   : 0, 11195858

    section Manual + Automatic
    This PR (6168) (6.819M)   : 0, 6819252
    master (6.748M)   : 0, 6748246

    section DD_TRACE_ENABLED=0
    master (10.333M)   : 0, 10333224

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6168) (9.521M)   : 0, 9520888
    master (9.643M)   : 0, 9643431
    benchmarks/2.9.0 (9.798M)   : 0, 9798067

    section Automatic
    This PR (6168) (6.642M)   : 0, 6641734
    master (6.577M)   : 0, 6577390

    section Trace stats
    master (6.845M)   : 0, 6845170

    section Manual
    master (9.511M)   : 0, 9511409

    section Manual + Automatic
    This PR (6168) (6.056M)   : 0, 6055972
    master (6.185M)   : 0, 6185194

    section DD_TRACE_ENABLED=0
    master (8.810M)   : 0, 8810462

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6168) (9.714M)   : 0, 9714474
    benchmarks/2.9.0 (10.067M)   : 0, 10067315

    section Automatic
    This PR (6168) (6.365M)   : 0, 6365092
    benchmarks/2.9.0 (7.552M)   : 0, 7552193

    section Manual + Automatic
    This PR (6168) (6.111M)   : 0, 6111426

This currently fails

This reverts commit c62c192.

bouwkast

Looks good to me!

One question, do we know if the Ready to Run stuff impacts Serverless folks?

…ation (#6169) ## Summary of changes Check `instance.AutomaticTracer` for `null` before using it instead of casting ## Reason for change In #6124, we were seeing null reference exceptions. This was indicative of a separate (major) issue related to r2r (see #6168), but we still shouldn't have been throwing null refs in this case. ## Implementation details - Mark the property as nullable - Stop casting directly with `(Datadog.Trace.Tracer)instance.AutomaticTracer` - Use pattern matching to check for `null` - Log an error in `StartActiveImplementationIntegration` if we can't match, so that we still have visibility that _something_ went wrong on the managed side. ## Test coverage Tested locally to confirm it fixes the error in the tests introduced in #6168, but as those fix the root cause anyway, we won't be able to easily test for this invalid scenario ## Other details Relates to #6124

andrewlock · 2024-10-28T16:53:39Z

Superseded by #6184

andrewlock requested review from a team as code owners October 18, 2024 16:05

tonyredondo approved these changes Oct 18, 2024

View reviewed changes

andrewlock mentioned this pull request Oct 18, 2024

Ensure we don't throw a null reference exception in Manual instrumentation #6169

Merged

andrewlock commented Oct 18, 2024

View reviewed changes

Comment thread tracer/test/snapshots/ManualInstrumentationTests.ReadyToRunManualAndAutomatic.verified.txt Outdated

andrewlock commented Oct 18, 2024

View reviewed changes

andrewlock force-pushed the andrew/ready-to-run branch from 4905268 to 5ca53ec Compare October 21, 2024 07:58

andrewlock requested a review from a team as a code owner October 21, 2024 07:58

andrewlock force-pushed the andrew/ready-to-run branch 4 times, most recently from a645a7a to cfcc9ff Compare October 21, 2024 11:27

andrewlock added 7 commits October 22, 2024 14:24

Add a Ready2Run test for the manual instrumentation scenario

08342a3

This currently fails

Don't allow Datadog.Trace.Manual to be NGEN'd

20007ec

Disable the assert, see what happens

5b77c23

Replace explicit rewriting with calltarget instrumentation

c62c192

Revert "Replace explicit rewriting with calltarget instrumentation"

01d549a

This reverts commit c62c192.

Fix building of trimmed apps on x86

da4a113

fix tests

cc03595

andrewlock force-pushed the andrew/ready-to-run branch from cfcc9ff to cc03595 Compare October 22, 2024 14:24

bouwkast approved these changes Oct 22, 2024

View reviewed changes

lucaspimentel approved these changes Oct 22, 2024

View reviewed changes

Fix the r2r build

1072d93

kevingosse approved these changes Oct 23, 2024

View reviewed changes

andrewlock closed this Oct 28, 2024

Uh oh!

Conversation

andrewlock commented Oct 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

Uh oh!

github-actions Bot commented Oct 18, 2024

Snapshots difference summary

Uh oh!

tonyredondo left a comment

Choose a reason for hiding this comment

Uh oh!

datadog-ddstaging Bot commented Oct 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Datadog Report

New Flaky Tests (2)

Uh oh!

andrewlock commented Oct 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Execution-Time Benchmarks Report ⏱️

Uh oh!

andrewlock Oct 18, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

andrewlock Oct 18, 2024

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Oct 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

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 #6168

Raw results

Raw results

Uh oh!

andrewlock commented Oct 18, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Throughput/Crank Report ⚡

Uh oh!

bouwkast left a comment

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Oct 28, 2024

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

andrewlock commented Oct 18, 2024 •

edited

Loading

datadog-ddstaging Bot commented Oct 18, 2024 •

edited

Loading

andrewlock commented Oct 18, 2024 •

edited

Loading

andrewlock commented Oct 18, 2024 •

edited

Loading

andrewlock commented Oct 18, 2024 •

edited

Loading