dd-trace-dotnet icon indicating copy to clipboard operation
dd-trace-dotnet copied to clipboard
verified publisher icon DataDog

Opt Datadog.Trace.Manual out of NGEN

Open andrewlock opened this issue 1 year ago • 5 comments

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 https://github.com/dotnet/runtime/issues/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.

andrewlock avatar Oct 18 '24 16:10 andrewlock

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,

github-actions[bot] avatar Oct 18 '24 16:10 github-actions[bot]

Datadog Report

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

:white_check_mark: 0 Failed, 371620 Passed, 2742 Skipped, 26h 10m 3.46s Total Time :snowflake: 2 New Flaky

New Flaky Tests (2)

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

    Expand for error 
    
xpected 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 
    
xpected var integration = latestIntegrations {empty} to contain key "CurlHandler".), but no such item was found.t found False.

datadog-ddstaging[bot] avatar Oct 18 '24 16:10 datadog-ddstaging[bot]

Execution-Time Benchmarks Report :stopwatch:

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 avatar Oct 18 '24 16:10 andrewlock

Benchmarks Report for tracer :snail:

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 :heavy_check_mark: Same allocations :heavy_check_mark:

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 :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 469μs 291ns 1.09μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 643μs 476ns 1.84μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 839μs 280ns 1.05μs 0.419 0 0 3.3 KB
#6168 WriteAndFlushEnrichedTraces net6.0 481μs 158ns 593ns 0 0 0 2.7 KB
#6168 WriteAndFlushEnrichedTraces netcoreapp3.1 639μs 326ns 1.22μs 0 0 0 2.7 KB
#6168 WriteAndFlushEnrichedTraces net472 842μs 560ns 2.17μs 0.417 0 0 3.3 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 201μs 1.15μs 9.09μs 0.212 0 0 18.45 KB
master SendRequest netcoreapp3.1 222μs 1.29μs 11μs 0.209 0 0 20.61 KB
master SendRequest net472 0.00171ns 0.000718ns 0.00259ns 0 0 0 0 b
#6168 SendRequest net6.0 199μs 1.16μs 10μs 0.203 0 0 18.45 KB
#6168 SendRequest netcoreapp3.1 225μs 1.28μs 9.49μs 0.22 0 0 20.61 KB
#6168 SendRequest net472 0ns 0ns 0ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

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 :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.22μs 0.969ns 3.49ns 0.0141 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.8μs 0.913ns 3.54ns 0.0135 0 0 1.02 KB
master ExecuteNonQuery net472 2.19μs 1.67ns 6.47ns 0.156 0 0 987 B
#6168 ExecuteNonQuery net6.0 1.24μs 5.78ns 28.3ns 0.0147 0 0 1.02 KB
#6168 ExecuteNonQuery netcoreapp3.1 1.78μs 1.22ns 4.72ns 0.0134 0 0 1.02 KB
#6168 ExecuteNonQuery net472 2.12μs 1.47ns 5.69ns 0.156 0 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.19μs 0.438ns 1.64ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.52μs 0.556ns 2.08ns 0.0129 0 0 976 B
master CallElasticsearch net472 2.44μs 1.34ns 5.18ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.27μs 0.543ns 2.1ns 0.0134 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.64μs 0.672ns 2.52ns 0.0139 0 0 1.02 KB
master CallElasticsearchAsync net472 2.56μs 1.23ns 4.61ns 0.166 0 0 1.05 KB
#6168 CallElasticsearch net6.0 1.21μs 0.669ns 2.59ns 0.014 0 0 976 B
#6168 CallElasticsearch netcoreapp3.1 1.51μs 0.798ns 2.88ns 0.0129 0 0 976 B
#6168 CallElasticsearch net472 2.58μs 1.87ns 7.24ns 0.158 0 0 995 B
#6168 CallElasticsearchAsync net6.0 1.33μs 0.631ns 2.36ns 0.0132 0 0 952 B
#6168 CallElasticsearchAsync netcoreapp3.1 1.62μs 1.12ns 4.18ns 0.0137 0 0 1.02 KB
#6168 CallElasticsearchAsync net472 2.68μs 2.88ns 11.1ns 0.167 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.33μs 0.549ns 2.13ns 0.0133 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.57μs 1.27ns 4.92ns 0.0124 0 0 952 B
master ExecuteAsync net472 1.74μs 1.04ns 4.02ns 0.145 0 0 915 B
#6168 ExecuteAsync net6.0 1.25μs 0.585ns 2.19ns 0.0133 0 0 952 B
#6168 ExecuteAsync netcoreapp3.1 1.59μs 1.2ns 4.63ns 0.0127 0 0 952 B
#6168 ExecuteAsync net472 1.74μs 0.942ns 3.53ns 0.145 0 0 915 B
Benchmarks.Trace.HttpClientBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net6.0 4.27μs 2.07ns 7.76ns 0.0299 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.17μs 2.19ns 8.49ns 0.0361 0 0 2.76 KB
master SendAsync net472 7.87μs 3.33ns 12.5ns 0.499 0 0 3.15 KB
#6168 SendAsync net6.0 4.27μs 2.07ns 7.16ns 0.03 0 0 2.22 KB
#6168 SendAsync netcoreapp3.1 4.95μs 1.79ns 6.94ns 0.0371 0 0 2.76 KB
#6168 SendAsync net472 7.67μs 2.17ns 8.39ns 0.5 0 0 3.15 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 1.55μs 1.1ns 4.27ns 0.0228 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.15μs 1.23ns 4.6ns 0.0225 0 0 1.64 KB
master EnrichedLog net472 2.6μs 1.39ns 5.38ns 0.249 0 0 1.57 KB
#6168 EnrichedLog net6.0 1.43μs 1.01ns 3.9ns 0.023 0 0 1.64 KB
#6168 EnrichedLog netcoreapp3.1 2.13μs 0.543ns 2.03ns 0.0225 0 0 1.64 KB
#6168 EnrichedLog net472 2.5μs 0.933ns 3.49ns 0.249 0 0 1.57 KB
Benchmarks.Trace.Log4netBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 116μs 96.4ns 361ns 0.0578 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 122μs 232ns 900ns 0.0602 0 0 4.28 KB
master EnrichedLog net472 152μs 166ns 644ns 0.69 0.23 0 4.46 KB
#6168 EnrichedLog net6.0 117μs 191ns 687ns 0.0591 0 0 4.28 KB
#6168 EnrichedLog netcoreapp3.1 121μs 162ns 605ns 0 0 0 4.28 KB
#6168 EnrichedLog net472 148μs 109ns 409ns 0.667 0.222 0 4.46 KB
Benchmarks.Trace.NLogBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 3.11μs 0.716ns 2.58ns 0.0313 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.33μs 1.71ns 6.61ns 0.0282 0 0 2.2 KB
master EnrichedLog net472 4.93μs 6.89ns 25.8ns 0.319 0 0 2.02 KB
#6168 EnrichedLog net6.0 3.23μs 0.902ns 3.38ns 0.0308 0 0 2.2 KB
#6168 EnrichedLog netcoreapp3.1 4.26μs 0.851ns 3.18ns 0.0298 0 0 2.2 KB
#6168 EnrichedLog net472 4.77μs 1.49ns 5.77ns 0.319 0 0 2.02 KB
Benchmarks.Trace.RedisBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.43μs 0.937ns 3.63ns 0.0157 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.71μs 0.819ns 3.17ns 0.0155 0 0 1.14 KB
master SendReceive net472 2.06μs 0.77ns 2.98ns 0.183 0 0 1.16 KB
#6168 SendReceive net6.0 1.36μs 0.734ns 2.74ns 0.0157 0 0 1.14 KB
#6168 SendReceive netcoreapp3.1 1.75μs 1.74ns 6.75ns 0.0148 0 0 1.14 KB
#6168 SendReceive net472 2.03μs 0.8ns 2.99ns 0.184 0 0 1.16 KB
Benchmarks.Trace.SerilogBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.6μs 0.915ns 3.54ns 0.0221 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.88μs 1.14ns 4.11ns 0.0213 0 0 1.65 KB
master EnrichedLog net472 4.43μs 2.41ns 9.04ns 0.323 0 0 2.04 KB
#6168 EnrichedLog net6.0 2.75μs 0.648ns 2.51ns 0.022 0 0 1.6 KB
#6168 EnrichedLog netcoreapp3.1 3.81μs 1.05ns 4.07ns 0.0209 0 0 1.65 KB
#6168 EnrichedLog net472 4.36μs 3.59ns 13.9ns 0.324 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: 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 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 399ns 0.157ns 0.586ns 0.008 0 0 576 B
master StartFinishSpan netcoreapp3.1 621ns 3.35ns 18.1ns 0.00757 0 0 576 B
master StartFinishSpan net472 699ns 1.14ns 4.4ns 0.0918 0 0 578 B
master StartFinishScope net6.0 486ns 0.18ns 0.698ns 0.00964 0 0 696 B
master StartFinishScope netcoreapp3.1 703ns 0.374ns 1.4ns 0.00913 0 0 696 B
master StartFinishScope net472 968ns 0.287ns 1.04ns 0.104 0 0 658 B
#6168 StartFinishSpan net6.0 440ns 0.265ns 1.03ns 0.00817 0 0 576 B
#6168 StartFinishSpan netcoreapp3.1 552ns 0.268ns 1ns 0.00777 0 0 576 B
#6168 StartFinishSpan net472 783ns 0.825ns 3.19ns 0.0917 0 0 578 B
#6168 StartFinishScope net6.0 535ns 0.311ns 1.2ns 0.00967 0 0 696 B
#6168 StartFinishScope netcoreapp3.1 743ns 0.88ns 3.41ns 0.00955 0 0 696 B
#6168 StartFinishScope net472 877ns 0.571ns 2.21ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

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

andrewlock avatar Oct 18 '24 18:10 andrewlock

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 (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

andrewlock avatar Oct 18 '24 18:10 andrewlock

Superseded by #6184

andrewlock avatar Oct 28 '24 16:10 andrewlock