[Dynamic Instrumentation] DEBUG-3492 Remove duration from non method snapshots #6735

dudikeleti · 2025-03-03T16:46:52Z

Summary of changes

Removes the duration property from non method snapshots

Reason for change

We have seen customers used @duration in the expression. It seems they wanted to know how much it took for the selected line to execute and have a metric on that. Since @duration works only for method probes (where it shows the execution time time in milliseconds of the method) and in line probes it’s not useful (and I’m not sure why it’s even there) since the line is executed similar to a breakpoint in the IDE - before the line executes. It does not surround the method in any way - then @duration means nothing.

andrewlock · 2025-03-03T17:37:03Z

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 (6735) - mean (69ms)  : 66, 72
     .   : milestone, 69,
    master - mean (70ms)  : 65, 74
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (1,001ms)  : 980, 1022
     .   : milestone, 1001,
    master - mean (1,003ms)  : 977, 1029
     .   : milestone, 1003,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6735) - mean (102ms)  : 100, 104
     .   : milestone, 102,
    master - mean (102ms)  : 100, 105
     .   : milestone, 102,

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (685ms)  : 668, 702
     .   : milestone, 685,
    master - mean (688ms)  : 664, 711
     .   : milestone, 688,

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

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (641ms)  : 624, 659
     .   : milestone, 641,
    master - mean (640ms)  : 626, 654
     .   : milestone, 640,

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

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (1,112ms)  : 1084, 1139
     .   : milestone, 1112,
    master - mean (1,107ms)  : 1081, 1133
     .   : milestone, 1107,

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

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (878ms)  : 850, 906
     .   : milestone, 878,
    master - mean (877ms)  : 842, 913
     .   : milestone, 877,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6735) - mean (261ms)  : 256, 267
     .   : milestone, 261,
    master - mean (262ms)  : 259, 266
     .   : milestone, 262,

    section CallTarget+Inlining+NGEN
    This PR (6735) - mean (861ms)  : 825, 896
     .   : milestone, 861,
    master - mean (855ms)  : 817, 892
     .   : milestone, 855,

datadog-datadog-prod-us1 · 2025-03-03T18:27:41Z

Datadog Report

All test runs 5bd2c29 🔗

❌ 2 Total Test Services: 1 Failed, 1 Passed

Test Services

Service Name	Failed	Known Flaky	New Flaky	Passed	Skipped	Total Time	Test Service View
`dd-trace-dotnet`	1320	0	0	258236	3372	32h 25m 9.15s	Link
`exploration_tests`	0	0	0	22085	3	1h 29m 58.11s	Link

❌ Failed Tests (1320)

This report shows up to 5 failed tests.

LineProbeUnboundProbeBecomesBoundTest - Datadog.Trace.Debugger.IntegrationTests.ProbesTests
LineProbeUnboundProbeBecomesBoundTest - Datadog.Trace.Debugger.IntegrationTests.ProbesTests
LineProbeUnboundProbeBecomesBoundTest - Datadog.Trace.Debugger.IntegrationTests.ProbesTests
LineProbeUnboundProbeBecomesBoundTest - Datadog.Trace.Debugger.IntegrationTests.ProbesTests
LineProbeUnboundProbeBecomesBoundTest - Datadog.Trace.Debugger.IntegrationTests.ProbesTests

andrewlock · 2025-03-03T20:41:27Z

Benchmarks Report for tracer 🐌

Benchmarks for #6735 compared to master:

1 benchmarks are slower, with geometric mean 1.157
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	8.19μs	46.8ns	338ns	0.0119	0.00398	0	5.6 KB
master	`StartStopWithChild`	netcoreapp3.1	10.7μs	60.3ns	435ns	0.015	0.00499	0	5.81 KB
master	`StartStopWithChild`	net472	16.2μs	47.8ns	185ns	1.04	0.299	0.0969	6.2 KB
#6735	`StartStopWithChild`	net6.0	8.42μs	49.4ns	481ns	0.0174	0.0087	0	5.61 KB
#6735	`StartStopWithChild`	netcoreapp3.1	10.6μs	57.9ns	467ns	0.0156	0.00521	0	5.8 KB
#6735	`StartStopWithChild`	net472	16.4μs	45.6ns	170ns	1.03	0.293	0.0975	6.21 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	483μs	358ns	1.39μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	644μs	635ns	2.46μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	849μs	397ns	1.54μs	0.422	3.3 KB
#6735	`WriteAndFlushEnrichedTraces`	net6.0	478μs	337ns	1.26μs	0	2.7 KB
#6735	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	644μs	202ns	700ns	0	2.7 KB
#6735	`WriteAndFlushEnrichedTraces`	net472	837μs	617ns	2.39μ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	133μs	411ns	1.59μs	0.199	14.47 KB
master	`SendRequest`	netcoreapp3.1	151μs	212ns	794ns	0.227	17.27 KB
master	`SendRequest`	net472	0.000146ns	9.84E‑05ns	0.000368ns	0	0 b
#6735	`SendRequest`	net6.0	131μs	512ns	1.98μs	0.198	14.47 KB
#6735	`SendRequest`	netcoreapp3.1	150μs	245ns	948ns	0.222	17.27 KB
#6735	`SendRequest`	net472	0.00137ns	0.000297ns	0.00115ns	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	549μs	2.62μs	10.5μs	0.543	0	0	41.47 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	683μs	3.34μs	13.8μs	0.324	0	0	41.84 KB
master	`WriteAndFlushEnrichedTraces`	net472	878μs	3.73μs	13.9μs	8.19	2.59	0.431	53.32 KB
#6735	`WriteAndFlushEnrichedTraces`	net6.0	556μs	1.15μs	4.16μs	0.576	0	0	41.55 KB
#6735	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	675μs	2.58μs	9.66μs	0.324	0	0	41.79 KB
#6735	`WriteAndFlushEnrichedTraces`	net472	860μs	4.14μs	17.6μs	8.28	2.48	0.414	53.28 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net6.0	1.33μs	1.28ns	4.97ns	0.014	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.82μs	1.88ns	7.28ns	0.0133	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.12μs	1.29ns	4.81ns	0.156	0.00106	987 B
#6735	`ExecuteNonQuery`	net6.0	1.38μs	1.08ns	4.17ns	0.0145	0	1.02 KB
#6735	`ExecuteNonQuery`	netcoreapp3.1	1.71μs	0.846ns	3.28ns	0.0137	0	1.02 KB
#6735	`ExecuteNonQuery`	net472	2.15μs	2.31ns	8.95ns	0.156	0.00108	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.26μs	0.7ns	2.62ns	0.0139	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.55μs	3.3ns	12.3ns	0.0131	976 B
master	`CallElasticsearch`	net472	2.47μs	0.758ns	2.73ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.24μs	1.08ns	4.18ns	0.0131	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.64μs	1.06ns	3.95ns	0.0131	1.02 KB
master	`CallElasticsearchAsync`	net472	2.64μs	1ns	3.62ns	0.166	1.05 KB
#6735	`CallElasticsearch`	net6.0	1.27μs	0.671ns	2.6ns	0.014	976 B
#6735	`CallElasticsearch`	netcoreapp3.1	1.54μs	1.7ns	6.14ns	0.0132	976 B
#6735	`CallElasticsearch`	net472	2.48μs	2ns	7.75ns	0.157	995 B
#6735	`CallElasticsearchAsync`	net6.0	1.28μs	0.67ns	2.51ns	0.0134	952 B
#6735	`CallElasticsearchAsync`	netcoreapp3.1	1.81μs	0.744ns	2.78ns	0.0135	1.02 KB
#6735	`CallElasticsearchAsync`	net472	2.54μs	1.56ns	5.82ns	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.34μs	1.58ns	5.9ns	0.0133	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.69μs	1.57ns	6.08ns	0.0128	952 B
master	`ExecuteAsync`	net472	1.85μs	0.672ns	2.6ns	0.145	915 B
#6735	`ExecuteAsync`	net6.0	1.27μs	0.492ns	1.77ns	0.0133	952 B
#6735	`ExecuteAsync`	netcoreapp3.1	1.64μs	0.681ns	2.64ns	0.0128	952 B
#6735	`ExecuteAsync`	net472	1.83μs	0.615ns	2.38ns	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.36μs	1.04ns	3.75ns	0.0325	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.22μs	2.2ns	7.94ns	0.0393	2.85 KB
master	`SendAsync`	net472	7.45μs	2.36ns	9.15ns	0.492	3.12 KB
#6735	`SendAsync`	net6.0	4.51μs	0.939ns	3.51ns	0.0336	2.31 KB
#6735	`SendAsync`	netcoreapp3.1	5.38μs	1.78ns	6.9ns	0.0376	2.85 KB
#6735	`SendAsync`	net472	7.51μs	1.98ns	7.65ns	0.495	3.12 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.47μs	0.781ns	3.03ns	0.0234	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.14μs	5.9ns	22.9ns	0.0223	1.64 KB
master	`EnrichedLog`	net472	2.63μs	2.01ns	7.8ns	0.25	1.57 KB
#6735	`EnrichedLog`	net6.0	1.62μs	4.48ns	17.3ns	0.0233	1.64 KB
#6735	`EnrichedLog`	netcoreapp3.1	2.33μs	1.98ns	7.42ns	0.0221	1.64 KB
#6735	`EnrichedLog`	net472	2.63μs	0.64ns	2.48ns	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	114μs	158ns	612ns	0.0563	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	118μs	179ns	692ns	0	0	4.28 KB
master	`EnrichedLog`	net472	149μs	211ns	817ns	0.668	0.223	4.46 KB
#6735	`EnrichedLog`	net6.0	113μs	156ns	602ns	0	0	4.28 KB
#6735	`EnrichedLog`	netcoreapp3.1	116μs	100ns	348ns	0.0581	0	4.28 KB
#6735	`EnrichedLog`	net472	149μs	144ns	558ns	0.669	0.223	4.46 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.9μs	0.691ns	2.59ns	0.0318	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.16μs	3.18ns	11.5ns	0.029	2.2 KB
master	`EnrichedLog`	net472	5.01μs	1.69ns	6.54ns	0.32	2.02 KB
#6735	`EnrichedLog`	net6.0	3.03μs	0.963ns	3.73ns	0.0302	2.2 KB
#6735	`EnrichedLog`	netcoreapp3.1	4.25μs	2.21ns	8.55ns	0.0297	2.2 KB
#6735	`EnrichedLog`	net472	4.93μs	1.77ns	6.64ns	0.32	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.36μs	0.605ns	2.34ns	0.0156	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.74μs	0.624ns	2.41ns	0.0155	1.14 KB
master	`SendReceive`	net472	2.11μs	1.34ns	5.2ns	0.183	1.16 KB
#6735	`SendReceive`	net6.0	1.41μs	0.478ns	1.72ns	0.0162	1.14 KB
#6735	`SendReceive`	netcoreapp3.1	1.78μs	0.629ns	2.44ns	0.0152	1.14 KB
#6735	`SendReceive`	net472	2.07μs	0.947ns	3.67ns	0.183	1.16 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.74μs	0.565ns	2.19ns	0.022	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.9μs	2.99ns	11.6ns	0.0216	1.65 KB
master	`EnrichedLog`	net472	4.46μs	2.17ns	8.11ns	0.324	2.04 KB
#6735	`EnrichedLog`	net6.0	2.76μs	2.59ns	9.69ns	0.022	1.6 KB
#6735	`EnrichedLog`	netcoreapp3.1	3.93μs	2.24ns	8.39ns	0.0214	1.65 KB
#6735	`EnrichedLog`	net472	4.17μs	3.32ns	12.9ns	0.322	2.04 KB

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

Slower ⚠️ in #6735

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0	1.157	481.86	557.59

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	392ns	0.434ns	1.68ns	0.00798	576 B
master	`StartFinishSpan`	netcoreapp3.1	606ns	1.38ns	5.36ns	0.0079	576 B
master	`StartFinishSpan`	net472	589ns	0.892ns	3.46ns	0.0916	578 B
master	`StartFinishScope`	net6.0	481ns	0.798ns	3.09ns	0.00986	696 B
master	`StartFinishScope`	netcoreapp3.1	725ns	1.74ns	6.72ns	0.00921	696 B
master	`StartFinishScope`	net472	842ns	1.98ns	7.67ns	0.104	658 B
#6735	`StartFinishSpan`	net6.0	396ns	0.139ns	0.52ns	0.00813	576 B
#6735	`StartFinishSpan`	netcoreapp3.1	558ns	0.341ns	1.32ns	0.00784	576 B
#6735	`StartFinishSpan`	net472	640ns	0.22ns	0.792ns	0.0915	578 B
#6735	`StartFinishScope`	net6.0	558ns	0.338ns	1.27ns	0.00964	696 B
#6735	`StartFinishScope`	netcoreapp3.1	706ns	0.746ns	2.79ns	0.00941	696 B
#6735	`StartFinishScope`	net472	822ns	2.31ns	8.93ns	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	615ns	1.18ns	4.58ns	0.00981	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	922ns	1.49ns	5.78ns	0.00937	696 B
master	`RunOnMethodBegin`	net472	1.06μs	2.1ns	8.12ns	0.104	658 B
#6735	`RunOnMethodBegin`	net6.0	660ns	0.292ns	1.13ns	0.00987	696 B
#6735	`RunOnMethodBegin`	netcoreapp3.1	1.01μs	0.418ns	1.62ns	0.00953	696 B
#6735	`RunOnMethodBegin`	net472	1.09μs	0.336ns	1.3ns	0.104	658 B

remove duration from non method snapshots

5bd2c29

dudikeleti requested a review from a team as a code owner March 3, 2025 16:46

github-actions bot added the area:debugger label Mar 3, 2025

dudikeleti requested a review from GreenMatan March 6, 2025 15:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Dynamic Instrumentation] DEBUG-3492 Remove duration from non method snapshots #6735

[Dynamic Instrumentation] DEBUG-3492 Remove duration from non method snapshots #6735

dudikeleti commented Mar 3, 2025

andrewlock commented Mar 3, 2025

datadog-datadog-prod-us1 bot commented Mar 3, 2025 •

edited

Loading

andrewlock commented Mar 3, 2025

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

Raw results

Raw results

[Dynamic Instrumentation] DEBUG-3492 Remove duration from non method snapshots #6735

Are you sure you want to change the base?

[Dynamic Instrumentation] DEBUG-3492 Remove duration from non method snapshots #6735

Conversation

dudikeleti commented Mar 3, 2025

Summary of changes

Reason for change

andrewlock commented Mar 3, 2025

Execution-Time Benchmarks Report ⏱️

datadog-datadog-prod-us1 bot commented Mar 3, 2025 • edited Loading

Datadog Report

❌ Failed Tests (1320)

andrewlock commented Mar 3, 2025

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

Raw results

Raw results

datadog-datadog-prod-us1 bot commented Mar 3, 2025 •

edited

Loading