Log an error message when the profiler is loaded multiple times #6503

kevingosse · 2025-01-06T14:05:14Z

Summary of changes

Log an error message when the profiler is loaded multiple times.

Reason for change

Despite mentioning it in our documentation, we still regularly have escalations caused by the usage of .NET Framework and .NET Core in the same pool. Adding an error log will make diagnostic easier.

We could also entirely bail out when we detect multiple initialization, but I'm afraid we might break existing customers.

Implementation details

Using the profiler field to find out if the profiler was initialized. It means we won't detect double-initialization if the first initialization failed midway through, but I don't think we really care.

Test coverage

Tested on my machine.

tracer/src/Datadog.Tracer.Native/cor_profiler.cpp

datadog-ddstaging · 2025-01-06T14:51:49Z

Datadog Report

Branch report: kevin/multiple-profilers
Commit report: 738a87c
Test service: dd-trace-dotnet

✅ 0 Failed, 239395 Passed, 2934 Skipped, 31h 54m 36.84s Total Time

andrewlock · 2025-01-06T15:00:49Z

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 (6503) - mean (69ms)  : 65, 73
     .   : milestone, 69,
    master - mean (68ms)  : 66, 71
     .   : milestone, 68,

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (974ms)  : 951, 997
     .   : milestone, 974,
    master - mean (973ms)  : 948, 998
     .   : milestone, 973,

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

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (676ms)  : 662, 690
     .   : milestone, 676,
    master - mean (678ms)  : 664, 691
     .   : milestone, 678,

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

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (635ms)  : 620, 651
     .   : milestone, 635,
    master - mean (631ms)  : 616, 645
     .   : milestone, 631,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6503) - mean (194ms)  : 190, 198
     .   : milestone, 194,
    master - mean (195ms)  : 190, 200
     .   : milestone, 195,

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (1,102ms)  : 1073, 1130
     .   : milestone, 1102,
    master - mean (1,099ms)  : 1063, 1135
     .   : milestone, 1099,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6503) - mean (278ms)  : 274, 283
     .   : milestone, 278,
    master - mean (277ms)  : 273, 282
     .   : milestone, 277,

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (877ms)  : 847, 907
     .   : milestone, 877,
    master - mean (873ms)  : 842, 903
     .   : milestone, 873,

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

    section CallTarget+Inlining+NGEN
    This PR (6503) - mean (852ms)  : 823, 881
     .   : milestone, 852,
    master - mean (851ms)  : 814, 888
     .   : milestone, 851,

andrewlock · 2025-01-06T16:12:40Z

Benchmarks Report for tracer 🐌

Benchmarks for #6503 compared to master:

1 benchmarks are faster, with geometric mean 1.151
2 benchmarks are slower, with geometric mean 1.129
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	7.99μs	44.6ns	303ns	0.016	0.00399	0	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	10.3μs	55.8ns	325ns	0.0152	0.00507	0	5.8 KB
master	`StartStopWithChild`	net472	16.4μs	68.2ns	264ns	1.04	0.307	0.0914	6.2 KB
#6503	`StartStopWithChild`	net6.0	8.11μs	44.8ns	265ns	0.0187	0.00749	0	5.61 KB
#6503	`StartStopWithChild`	netcoreapp3.1	10μs	56.7ns	393ns	0.0162	0.00541	0	5.8 KB
#6503	`StartStopWithChild`	net472	16.6μs	66.7ns	249ns	1.03	0.295	0.0901	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	503μs	624ns	2.41μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	660μs	515ns	2μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	858μs	757ns	2.93μs	0.431	3.3 KB
#6503	`WriteAndFlushEnrichedTraces`	net6.0	474μs	242ns	939ns	0	2.7 KB
#6503	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	644μs	405ns	1.57μs	0	2.7 KB
#6503	`WriteAndFlushEnrichedTraces`	net472	851μs	366ns	1.37μs	0.428	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	154μs	905ns	8.24μs	0.145	14.47 KB
master	`SendRequest`	netcoreapp3.1	177μs	1.02μs	7.96μs	0.163	17.27 KB
master	`SendRequest`	net472	0.00113ns	0.000522ns	0.00202ns	0	0 b
#6503	`SendRequest`	net6.0	156μs	1.07μs	10.7μs	0.211	14.47 KB
#6503	`SendRequest`	netcoreapp3.1	174μs	1.09μs	10.8μs	0.161	17.27 KB
#6503	`SendRequest`	net472	0.000678ns	0.000521ns	0.00195ns	0	0 b

Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ More allocations ⚠️

More allocations ⚠️ in #6503

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1	41.71 KB	42.01 KB	294 B	0.70%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	571μs	3.23μs	24.4μs	0.543	0	0	41.6 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	662μs	3.78μs	27μs	0.391	0	0	41.71 KB
master	`WriteAndFlushEnrichedTraces`	net472	852μs	3.98μs	15.4μs	8.39	2.52	0.419	53.33 KB
#6503	`WriteAndFlushEnrichedTraces`	net6.0	589μs	3.35μs	23.2μs	0.571	0	0	41.5 KB
#6503	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	691μs	3.93μs	29.6μs	0.336	0	0	42.01 KB
#6503	`WriteAndFlushEnrichedTraces`	net472	862μs	4.21μs	17.4μs	8.39	2.52	0.419	53.27 KB

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

Slower ⚠️ in #6503

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.DbCommandBenchmark.ExecuteNonQuery‑net6.0	1.122	1,204.62	1,351.92

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net6.0	1.2μs	1.4ns	5.43ns	0.0144	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.77μs	1.29ns	4.99ns	0.0132	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.1μs	3.38ns	13.1ns	0.157	0.00105	987 B
#6503	`ExecuteNonQuery`	net6.0	1.35μs	1.37ns	5.11ns	0.0142	0	1.02 KB
#6503	`ExecuteNonQuery`	netcoreapp3.1	1.76μs	1.51ns	5.84ns	0.0131	0	1.02 KB
#6503	`ExecuteNonQuery`	net472	2.11μs	2.85ns	11ns	0.156	0.00105	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.22μs	1.79ns	6.92ns	0.014	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.5μs	2.37ns	8.21ns	0.0129	976 B
master	`CallElasticsearch`	net472	2.59μs	2.4ns	9.29ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.35μs	0.501ns	1.81ns	0.0135	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.64μs	1.03ns	3.97ns	0.014	1.02 KB
master	`CallElasticsearchAsync`	net472	2.57μs	2.36ns	9.13ns	0.167	1.05 KB
#6503	`CallElasticsearch`	net6.0	1.24μs	0.414ns	1.55ns	0.0138	976 B
#6503	`CallElasticsearch`	netcoreapp3.1	1.55μs	0.936ns	3.24ns	0.0125	976 B
#6503	`CallElasticsearch`	net472	2.54μs	2.67ns	10.3ns	0.158	995 B
#6503	`CallElasticsearchAsync`	net6.0	1.42μs	0.861ns	3.33ns	0.0128	952 B
#6503	`CallElasticsearchAsync`	netcoreapp3.1	1.65μs	1.68ns	6.51ns	0.014	1.02 KB
#6503	`CallElasticsearchAsync`	net472	2.63μs	1.11ns	4.3ns	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.37μs	0.772ns	2.89ns	0.013	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.65μs	1.19ns	4.44ns	0.0124	952 B
master	`ExecuteAsync`	net472	1.77μs	0.331ns	1.24ns	0.145	915 B
#6503	`ExecuteAsync`	net6.0	1.33μs	0.907ns	3.39ns	0.0133	952 B
#6503	`ExecuteAsync`	netcoreapp3.1	1.6μs	1.81ns	7ns	0.0127	952 B
#6503	`ExecuteAsync`	net472	1.9μs	0.544ns	2.04ns	0.144	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.52μs	1.57ns	5.88ns	0.0316	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.2μs	2.32ns	9ns	0.0388	2.85 KB
master	`SendAsync`	net472	7.47μs	1.93ns	7.47ns	0.496	3.12 KB
#6503	`SendAsync`	net6.0	4.42μs	1.96ns	7.32ns	0.033	2.31 KB
#6503	`SendAsync`	netcoreapp3.1	5.48μs	20.7ns	80.2ns	0.0368	2.85 KB
#6503	`SendAsync`	net472	7.34μs	1.15ns	4.46ns	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.695ns	2.6ns	0.023	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.23μs	1.01ns	3.78ns	0.0221	1.64 KB
master	`EnrichedLog`	net472	2.82μs	1.59ns	5.93ns	0.249	1.57 KB
#6503	`EnrichedLog`	net6.0	1.54μs	0.78ns	2.92ns	0.023	1.64 KB
#6503	`EnrichedLog`	netcoreapp3.1	2.17μs	0.88ns	3.29ns	0.0216	1.64 KB
#6503	`EnrichedLog`	net472	2.7μs	1.16ns	4.2ns	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	117μs	110ns	425ns	0.0582	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	121μs	250ns	968ns	0	0	4.28 KB
master	`EnrichedLog`	net472	152μs	106ns	398ns	0.683	0.228	4.46 KB
#6503	`EnrichedLog`	net6.0	117μs	136ns	527ns	0	0	4.28 KB
#6503	`EnrichedLog`	netcoreapp3.1	120μs	89.1ns	345ns	0.0606	0	4.28 KB
#6503	`EnrichedLog`	net472	150μs	128ns	478ns	0.678	0.226	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.04μs	1.18ns	4.4ns	0.0299	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.26μs	2.26ns	8.77ns	0.0298	2.2 KB
master	`EnrichedLog`	net472	4.9μs	2.9ns	10.8ns	0.319	2.02 KB
#6503	`EnrichedLog`	net6.0	3.16μs	1.11ns	4.28ns	0.03	2.2 KB
#6503	`EnrichedLog`	netcoreapp3.1	4.17μs	2.02ns	7.84ns	0.0292	2.2 KB
#6503	`EnrichedLog`	net472	4.9μs	0.789ns	3.05ns	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.31μs	0.763ns	2.86ns	0.0164	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.82μs	0.67ns	2.42ns	0.0154	1.14 KB
master	`SendReceive`	net472	2.1μs	1.22ns	4.71ns	0.183	1.16 KB
#6503	`SendReceive`	net6.0	1.38μs	0.439ns	1.7ns	0.0158	1.14 KB
#6503	`SendReceive`	netcoreapp3.1	1.77μs	4.14ns	16ns	0.0153	1.14 KB
#6503	`SendReceive`	net472	2.14μs	0.888ns	3.44ns	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.72μs	0.802ns	3ns	0.0218	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.98μs	1.3ns	5.05ns	0.0217	1.65 KB
master	`EnrichedLog`	net472	4.39μs	3.91ns	15.1ns	0.322	2.04 KB
#6503	`EnrichedLog`	net6.0	2.82μs	1.03ns	3.99ns	0.0226	1.6 KB
#6503	`EnrichedLog`	netcoreapp3.1	3.93μs	8.52ns	33ns	0.0215	1.65 KB
#6503	`EnrichedLog`	net472	4.37μs	3.69ns	14.3ns	0.322	2.04 KB

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

Slower ⚠️ in #6503

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0	1.135	409.44	464.89

Faster 🎉 in #6503

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0	1.151	548.89	476.75

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	409ns	0.257ns	0.995ns	0.00802	576 B
master	`StartFinishSpan`	netcoreapp3.1	564ns	1.45ns	5.61ns	0.00768	576 B
master	`StartFinishSpan`	net472	636ns	0.721ns	2.79ns	0.0917	578 B
master	`StartFinishScope`	net6.0	549ns	0.265ns	0.993ns	0.00987	696 B
master	`StartFinishScope`	netcoreapp3.1	681ns	0.888ns	3.44ns	0.00929	696 B
master	`StartFinishScope`	net472	901ns	1.03ns	3.97ns	0.104	658 B
#6503	`StartFinishSpan`	net6.0	465ns	0.272ns	1.05ns	0.00801	576 B
#6503	`StartFinishSpan`	netcoreapp3.1	562ns	0.615ns	2.38ns	0.00791	576 B
#6503	`StartFinishSpan`	net472	706ns	0.28ns	1.09ns	0.0916	578 B
#6503	`StartFinishScope`	net6.0	477ns	0.102ns	0.368ns	0.00981	696 B
#6503	`StartFinishScope`	netcoreapp3.1	715ns	0.399ns	1.55ns	0.00937	696 B
#6503	`StartFinishScope`	net472	975ns	0.22ns	0.852ns	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	656ns	0.399ns	1.54ns	0.00976	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	932ns	0.652ns	2.53ns	0.00932	696 B
master	`RunOnMethodBegin`	net472	1.11μs	0.355ns	1.33ns	0.104	658 B
#6503	`RunOnMethodBegin`	net6.0	660ns	0.273ns	1.02ns	0.00983	696 B
#6503	`RunOnMethodBegin`	netcoreapp3.1	874ns	0.499ns	1.8ns	0.00953	696 B
#6503	`RunOnMethodBegin`	net472	1.14μs	0.248ns	0.96ns	0.105	658 B

Log an error message when the profiler is loaded multiple times

a497c39

kevingosse requested a review from a team as a code owner January 6, 2025 14:05

Info log when running in AAS

eea5d39

andrewlock approved these changes Jan 6, 2025

View reviewed changes

tracer/src/Datadog.Tracer.Native/cor_profiler.cpp Outdated Show resolved Hide resolved

Update cor_profiler.cpp

738a87c

kevingosse merged commit 602a928 into master Jan 7, 2025
105 of 107 checks passed

kevingosse deleted the kevin/multiple-profilers branch January 7, 2025 15:14

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Log an error message when the profiler is loaded multiple times #6503

Log an error message when the profiler is loaded multiple times #6503

kevingosse commented Jan 6, 2025

datadog-ddstaging bot commented Jan 6, 2025 •

edited

Loading

andrewlock commented Jan 6, 2025

andrewlock commented Jan 6, 2025

Raw results

Raw results

Raw results

More allocations ⚠️ in #6503

Raw results

Slower ⚠️ in #6503

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6503

Faster 🎉 in #6503

Raw results

Raw results

Log an error message when the profiler is loaded multiple times #6503

Log an error message when the profiler is loaded multiple times #6503

Conversation

kevingosse commented Jan 6, 2025

Summary of changes

Reason for change

Implementation details

Test coverage

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

Datadog Report

andrewlock commented Jan 6, 2025

Execution-Time Benchmarks Report ⏱️

andrewlock commented Jan 6, 2025

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

More allocations ⚠️ in #6503

Raw results

Slower ⚠️ in #6503

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #6503

Faster 🎉 in #6503

Raw results

Raw results

datadog-ddstaging bot commented Jan 6, 2025 •

edited

Loading