Revert "[Profiler] Make `timer_create`-based CPU profiler default" #6579

gleocadie · 2025-01-21T09:57:37Z

Reverts #6315

We have to revert because when threads are shutting down, we might face crashes, deadlock because the CLR calls pthread_exit.
https://dev.azure.com/datadoghq/dd-trace-dotnet/_build/results?buildId=172042&view=logs&j=5635f724-ec42-5e82-7816-fb263b6cfcc0&t=e80b9b00-921f-539a-741c-f91926c040ef

TL;DR
pthread_exit is called by the CLR, which starts cleaning up the thread thread_locals. But at the same time, the CPU timer_create-base kicks in and tries using, indirectly, those thread_locals.

)" This reverts commit 8c82f87.

datadog-ddstaging · 2025-01-21T10:31:44Z

Datadog Report

Branch report: revert-6315-gleocadie/make-timer_create-default-cpu-profiler
Commit report: 935dce5
Test service: dd-trace-dotnet

✅ 0 Failed, 245063 Passed, 2468 Skipped, 20h 44m 55.22s Total Time

andrewlock · 2025-01-21T10:32:06Z

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (980ms)  : 955, 1004
     .   : milestone, 980,
    master - mean (980ms)  : 955, 1005
     .   : milestone, 980,

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (685ms)  : 671, 699
     .   : milestone, 685,
    master - mean (678ms)  : 661, 695
     .   : milestone, 678,

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (635ms)  : 620, 650
     .   : milestone, 635,
    master - mean (635ms)  : 615, 654
     .   : milestone, 635,

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (1,088ms)  : 1057, 1118
     .   : milestone, 1088,
    master - mean (1,088ms)  : 1056, 1119
     .   : milestone, 1088,

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (869ms)  : 843, 894
     .   : milestone, 869,
    master - mean (872ms)  : 846, 897
     .   : milestone, 872,

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

    section CallTarget+Inlining+NGEN
    This PR (6579) - mean (846ms)  : 810, 882
     .   : milestone, 846,
    master - mean (846ms)  : 814, 878
     .   : milestone, 846,

andrewlock · 2025-01-21T10:52:33Z

Benchmarks Report for tracer 🐌

Benchmarks for #6579 compared to master:

1 benchmarks are slower, with geometric mean 1.151
1 benchmarks have fewer 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μs	45.4ns	321ns	0.0157	0.00783	0	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	9.92μs	54.8ns	347ns	0.0192	0.00962	0	5.8 KB
master	`StartStopWithChild`	net472	16.3μs	64.2ns	249ns	1.05	0.314	0.0966	6.21 KB
#6579	`StartStopWithChild`	net6.0	8.09μs	45ns	302ns	0.0157	0.00783	0	5.61 KB
#6579	`StartStopWithChild`	netcoreapp3.1	10.1μs	53.9ns	319ns	0.0196	0.00982	0	5.8 KB
#6579	`StartStopWithChild`	net472	16.2μs	52.7ns	204ns	1.06	0.327	0.106	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	499μs	283ns	1.1μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	643μs	388ns	1.45μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	844μs	1.08μs	4.03μs	0.417	3.3 KB
#6579	`WriteAndFlushEnrichedTraces`	net6.0	487μs	423ns	1.64μs	0	2.7 KB
#6579	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	688μs	467ns	1.81μs	0	2.7 KB
#6579	`WriteAndFlushEnrichedTraces`	net472	843μs	533ns	2.07μs	0.419	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	128μs	482ns	1.87μs	0.127	14.47 KB
master	`SendRequest`	netcoreapp3.1	143μs	505ns	1.96μs	0.211	17.27 KB
master	`SendRequest`	net472	0.0105ns	0.00325ns	0.0126ns	0	0 b
#6579	`SendRequest`	net6.0	129μs	371ns	1.44μs	0.193	14.47 KB
#6579	`SendRequest`	netcoreapp3.1	141μs	601ns	2.25μs	0.209	17.27 KB
#6579	`SendRequest`	net472	0.00359ns	0.00126ns	0.00489ns	0	0 b

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

Fewer allocations 🎉 in #6579

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑net6.0	41.81 KB	41.54 KB	-269 B	-0.64%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	563μs	3μs	17.7μs	0.718	0	0	41.81 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	649μs	3.17μs	13.4μs	0.329	0	0	41.71 KB
master	`WriteAndFlushEnrichedTraces`	net472	848μs	4.02μs	16.6μs	8.25	2.6	0.434	53.29 KB
#6579	`WriteAndFlushEnrichedTraces`	net6.0	554μs	1.02μs	3.54μs	0.573	0	0	41.54 KB
#6579	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	655μs	3.02μs	10.9μs	0.334	0	0	41.59 KB
#6579	`WriteAndFlushEnrichedTraces`	net472	823μs	3.99μs	16μs	8.28	2.48	0.414	53.26 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.38μs	1.04ns	3.91ns	0.0145	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.79μs	1.62ns	6.07ns	0.0135	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.07μs	1.56ns	6.05ns	0.156	0.00103	987 B
#6579	`ExecuteNonQuery`	net6.0	1.27μs	1.18ns	4.58ns	0.0145	0	1.02 KB
#6579	`ExecuteNonQuery`	netcoreapp3.1	1.73μs	1.85ns	7.15ns	0.0131	0	1.02 KB
#6579	`ExecuteNonQuery`	net472	2.05μs	1.23ns	4.61ns	0.156	0.00103	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.23μs	0.42ns	1.52ns	0.0136	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.67μs	4.67ns	18.1ns	0.0132	976 B
master	`CallElasticsearch`	net472	2.51μs	1.55ns	6ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.35μs	0.841ns	3.26ns	0.0135	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.56μs	0.797ns	2.98ns	0.0134	1.02 KB
master	`CallElasticsearchAsync`	net472	2.76μs	2.19ns	8.48ns	0.166	1.05 KB
#6579	`CallElasticsearch`	net6.0	1.21μs	0.526ns	1.97ns	0.0138	976 B
#6579	`CallElasticsearch`	netcoreapp3.1	1.53μs	0.595ns	2.23ns	0.0133	976 B
#6579	`CallElasticsearch`	net472	2.58μs	1.97ns	7.65ns	0.157	995 B
#6579	`CallElasticsearchAsync`	net6.0	1.36μs	0.778ns	2.91ns	0.013	952 B
#6579	`CallElasticsearchAsync`	netcoreapp3.1	1.6μs	2.83ns	10.6ns	0.014	1.02 KB
#6579	`CallElasticsearchAsync`	net472	2.7μs	2.01ns	7.8ns	0.166	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.31μs	0.885ns	3.43ns	0.0131	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.63μs	0.929ns	3.6ns	0.0125	952 B
master	`ExecuteAsync`	net472	1.84μs	0.395ns	1.53ns	0.145	915 B
#6579	`ExecuteAsync`	net6.0	1.3μs	0.704ns	2.63ns	0.0129	952 B
#6579	`ExecuteAsync`	netcoreapp3.1	1.61μs	1.64ns	6.14ns	0.0122	952 B
#6579	`ExecuteAsync`	net472	1.85μs	0.483ns	1.81ns	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.35μs	1.84ns	6.9ns	0.0328	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.21μs	2.47ns	9.24ns	0.0367	2.85 KB
master	`SendAsync`	net472	7.44μs	1.71ns	6.61ns	0.495	3.12 KB
#6579	`SendAsync`	net6.0	4.45μs	1.03ns	3.85ns	0.0312	2.31 KB
#6579	`SendAsync`	netcoreapp3.1	5.33μs	2.07ns	8.03ns	0.0373	2.85 KB
#6579	`SendAsync`	net472	7.49μs	0.821ns	2.96ns	0.492	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.6μs	0.721ns	2.7ns	0.0231	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.23μs	0.814ns	3.15ns	0.0222	1.64 KB
master	`EnrichedLog`	net472	2.49μs	0.735ns	2.65ns	0.249	1.57 KB
#6579	`EnrichedLog`	net6.0	1.57μs	1.46ns	5.45ns	0.0228	1.64 KB
#6579	`EnrichedLog`	netcoreapp3.1	2.16μs	0.934ns	3.37ns	0.0227	1.64 KB
#6579	`EnrichedLog`	net472	2.52μs	1.05ns	4.06ns	0.25	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	94.6ns	366ns	0.0577	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	120μs	159ns	615ns	0	0	4.28 KB
master	`EnrichedLog`	net472	151μs	105ns	406ns	0.677	0.226	4.46 KB
#6579	`EnrichedLog`	net6.0	116μs	152ns	588ns	0.058	0	4.28 KB
#6579	`EnrichedLog`	netcoreapp3.1	121μs	85.2ns	319ns	0.0613	0	4.28 KB
#6579	`EnrichedLog`	net472	151μs	112ns	433ns	0.676	0.225	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.93μs	0.891ns	3.45ns	0.0305	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.02μs	2.64ns	10.2ns	0.0302	2.2 KB
master	`EnrichedLog`	net472	5.04μs	0.962ns	3.73ns	0.319	2.02 KB
#6579	`EnrichedLog`	net6.0	3.1μs	0.844ns	3.04ns	0.0311	2.2 KB
#6579	`EnrichedLog`	netcoreapp3.1	4.32μs	1.42ns	5.32ns	0.0301	2.2 KB
#6579	`EnrichedLog`	net472	4.9μs	0.964ns	3.47ns	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.38μs	0.971ns	3.76ns	0.0158	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.76μs	0.679ns	2.63ns	0.015	1.14 KB
master	`SendReceive`	net472	2.14μs	0.847ns	3.28ns	0.183	1.16 KB
#6579	`SendReceive`	net6.0	1.39μs	0.578ns	2.09ns	0.016	1.14 KB
#6579	`SendReceive`	netcoreapp3.1	1.78μs	1.09ns	4.07ns	0.0152	1.14 KB
#6579	`SendReceive`	net472	2.18μs	0.617ns	2.39ns	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.78μs	0.874ns	3.38ns	0.0223	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.99μs	1.01ns	3.89ns	0.0219	1.65 KB
master	`EnrichedLog`	net472	4.5μs	2.67ns	9.64ns	0.322	2.04 KB
#6579	`EnrichedLog`	net6.0	2.7μs	0.976ns	3.78ns	0.0216	1.6 KB
#6579	`EnrichedLog`	netcoreapp3.1	3.84μs	1.67ns	6.26ns	0.023	1.65 KB
#6579	`EnrichedLog`	net472	4.52μs	3.07ns	11.5ns	0.322	2.04 KB

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

Slower ⚠️ in #6579

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1	1.151	557.75	641.79

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	416ns	0.6ns	2.32ns	0.0081	576 B
master	`StartFinishSpan`	netcoreapp3.1	557ns	1ns	3.87ns	0.00775	576 B
master	`StartFinishSpan`	net472	590ns	1.24ns	4.8ns	0.0917	578 B
master	`StartFinishScope`	net6.0	599ns	0.827ns	3.2ns	0.00976	696 B
master	`StartFinishScope`	netcoreapp3.1	689ns	1.23ns	4.77ns	0.00947	696 B
master	`StartFinishScope`	net472	770ns	1.78ns	6.65ns	0.104	658 B
#6579	`StartFinishSpan`	net6.0	398ns	0.365ns	1.41ns	0.00796	576 B
#6579	`StartFinishSpan`	netcoreapp3.1	641ns	0.688ns	2.66ns	0.00768	576 B
#6579	`StartFinishSpan`	net472	627ns	1.04ns	4.02ns	0.0918	578 B
#6579	`StartFinishScope`	net6.0	549ns	0.536ns	2.08ns	0.00984	696 B
#6579	`StartFinishScope`	netcoreapp3.1	754ns	0.854ns	3.31ns	0.00921	696 B
#6579	`StartFinishScope`	net472	826ns	1.8ns	6.98ns	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	693ns	1.47ns	5.69ns	0.00966	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	939ns	1.31ns	5.07ns	0.00937	696 B
master	`RunOnMethodBegin`	net472	1.05μs	1.78ns	6.91ns	0.104	658 B
#6579	`RunOnMethodBegin`	net6.0	730ns	1.42ns	5.49ns	0.00974	696 B
#6579	`RunOnMethodBegin`	netcoreapp3.1	953ns	1.1ns	4.26ns	0.00948	696 B
#6579	`RunOnMethodBegin`	net472	1.12μs	2.28ns	8.83ns	0.104	658 B

Revert "[Profiler] Make timer_create-based CPU profiler default (#6315

935dce5

)" This reverts commit 8c82f87.

gleocadie requested a review from a team as a code owner January 21, 2025 09:57

github-actions bot added the area:profiler Issues related to the continous-profiler label Jan 21, 2025

andrewlock approved these changes Jan 21, 2025

View reviewed changes

kevingosse approved these changes Jan 21, 2025

View reviewed changes

andrewlock merged commit c51efd8 into master Jan 21, 2025
133 of 135 checks passed

andrewlock deleted the revert-6315-gleocadie/make-timer_create-default-cpu-profiler branch January 21, 2025 11:27

github-actions bot added this to the vNext-v3 milestone Jan 21, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Revert "[Profiler] Make `timer_create`-based CPU profiler default" #6579

Revert "[Profiler] Make `timer_create`-based CPU profiler default" #6579

gleocadie commented Jan 21, 2025 •

edited

Loading

datadog-ddstaging bot commented Jan 21, 2025 •

edited

Loading

andrewlock commented Jan 21, 2025

andrewlock commented Jan 21, 2025

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #6579

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6579

Raw results

Raw results

Revert "[Profiler] Make timer_create-based CPU profiler default" #6579

Revert "[Profiler] Make timer_create-based CPU profiler default" #6579

Conversation

gleocadie commented Jan 21, 2025 • edited Loading

datadog-ddstaging bot commented Jan 21, 2025 • edited Loading

Datadog Report

andrewlock commented Jan 21, 2025

Execution-Time Benchmarks Report ⏱️

andrewlock commented Jan 21, 2025

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #6579

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6579

Raw results

Raw results

Revert "[Profiler] Make `timer_create`-based CPU profiler default" #6579

Revert "[Profiler] Make `timer_create`-based CPU profiler default" #6579

gleocadie commented Jan 21, 2025 •

edited

Loading

datadog-ddstaging bot commented Jan 21, 2025 •

edited

Loading