[Profiler] Add logs for the different profilers configuration #6739

chrisnas · 2025-03-04T12:30:37Z

Summary of changes

Log the value of env vars used to configure the different profilers

Reason for change

This should help during investigations when samples are missing

Implementation details

Log specific env var retrieval; focusing on public ones (just ETW is not documented)

Test coverage

New tests are added

Other details

andrewlock · 2025-03-04T13:11:29Z

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (1,003ms)  : 982, 1024
     .   : milestone, 1003,
    master - mean (1,003ms)  : 976, 1030
     .   : milestone, 1003,

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (692ms)  : 676, 709
     .   : milestone, 692,
    master - mean (687ms)  : 670, 703
     .   : milestone, 687,

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (643ms)  : 629, 657
     .   : milestone, 643,
    master - mean (645ms)  : 628, 661
     .   : milestone, 645,

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (1,113ms)  : 1089, 1138
     .   : milestone, 1113,
    master - mean (1,106ms)  : 1078, 1134
     .   : milestone, 1106,

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (882ms)  : 851, 914
     .   : milestone, 882,
    master - mean (876ms)  : 847, 905
     .   : milestone, 876,

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

    section CallTarget+Inlining+NGEN
    This PR (6739) - mean (860ms)  : 827, 892
     .   : milestone, 860,
    master - mean (855ms)  : 826, 884
     .   : milestone, 855,

datadog-datadog-prod-us1 · 2025-03-04T13:11:51Z

Datadog Report

All test runs 0de0e79 🔗

✅ 2 Total Test Services: 0 Failed, 2 Passed
⌛ 1 with Regressions

Test Services

Service Name	Failed	Known Flaky	New Flaky	Passed	Skipped	Total Time	Performance Regressions	Test Service View
`dd-trace-dotnet`	0	0	0	247725	2943	21h 30m 25.2s	1	Link
`exploration_tests`	0	0	0	22085	3	2m 8.66s	0	Link

⌛ Performance Regressions vs Default Branch (1)

Baseline_exception - scenarios 4.05s (+149.1ms, +4%) - Details

andrewlock · 2025-03-04T13:55:54Z

Benchmarks Report for tracer 🐌

Benchmarks for #6739 compared to master:

1 benchmarks are faster, with geometric mean 1.189
1 benchmarks are slower, with geometric mean 1.149
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.49μs	49.3ns	455ns	0.0164	0.00819	0	5.61 KB
master	`StartStopWithChild`	netcoreapp3.1	10.8μs	61.6ns	508ns	0.0158	0.00527	0	5.8 KB
master	`StartStopWithChild`	net472	16.2μs	53.4ns	192ns	1.04	0.312	0.0961	6.21 KB
#6739	`StartStopWithChild`	net6.0	8.29μs	48ns	399ns	0.0119	0.00396	0	5.62 KB
#6739	`StartStopWithChild`	netcoreapp3.1	10.3μs	59.6ns	461ns	0.0149	0.00497	0	5.81 KB
#6739	`StartStopWithChild`	net472	16.3μs	46.1ns	173ns	1.05	0.311	0.106	6.2 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	498μs	360ns	1.3μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	678μs	180ns	649ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	871μs	836ns	3.13μs	0.437	3.3 KB
#6739	`WriteAndFlushEnrichedTraces`	net6.0	502μs	372ns	1.34μs	0	2.7 KB
#6739	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	645μs	583ns	2.18μs	0	2.7 KB
#6739	`WriteAndFlushEnrichedTraces`	net472	860μs	439ns	1.64μ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	131μs	364ns	1.41μs	0.199	14.48 KB
master	`SendRequest`	netcoreapp3.1	146μs	276ns	1.07μs	0.215	17.27 KB
master	`SendRequest`	net472	0.000119ns	6.65E‑05ns	0.000258ns	0	0 b
#6739	`SendRequest`	net6.0	131μs	560ns	2.17μs	0.2	14.47 KB
#6739	`SendRequest`	netcoreapp3.1	147μs	164ns	636ns	0.22	17.27 KB
#6739	`SendRequest`	net472	0.000522ns	0.000184ns	0.000689ns	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	566μs	3.03μs	16.3μs	0.584	0	0	41.57 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	702μs	3.93μs	32.4μs	0.342	0	0	41.74 KB
master	`WriteAndFlushEnrichedTraces`	net472	844μs	4.03μs	15.6μs	8.39	2.52	0.419	53.26 KB
#6739	`WriteAndFlushEnrichedTraces`	net6.0	570μs	3.24μs	23.2μs	0.581	0	0	41.48 KB
#6739	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	670μs	3.48μs	17.4μs	0.334	0	0	41.81 KB
#6739	`WriteAndFlushEnrichedTraces`	net472	838μs	2.93μs	10.1μs	8.69	2.48	0.414	53.31 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.28μs	0.63ns	2.27ns	0.0142	0	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.81μs	1.48ns	5.32ns	0.0137	0	1.02 KB
master	`ExecuteNonQuery`	net472	2.1μs	3.26ns	12.6ns	0.156	0.00105	987 B
#6739	`ExecuteNonQuery`	net6.0	1.3μs	1.31ns	5.06ns	0.0145	0	1.02 KB
#6739	`ExecuteNonQuery`	netcoreapp3.1	1.68μs	2.1ns	8.12ns	0.0134	0	1.02 KB
#6739	`ExecuteNonQuery`	net472	2.12μs	2.34ns	8.76ns	0.157	0.00106	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.28μs	0.307ns	1.11ns	0.0134	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.66μs	0.608ns	2.28ns	0.0133	976 B
master	`CallElasticsearch`	net472	2.59μs	1.32ns	4.93ns	0.157	995 B
master	`CallElasticsearchAsync`	net6.0	1.27μs	0.699ns	2.71ns	0.0134	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.53μs	0.588ns	2.12ns	0.0139	1.02 KB
master	`CallElasticsearchAsync`	net472	2.64μs	3.53ns	13.7ns	0.167	1.05 KB
#6739	`CallElasticsearch`	net6.0	1.3μs	0.567ns	2.12ns	0.0135	976 B
#6739	`CallElasticsearch`	netcoreapp3.1	1.6μs	0.773ns	2.89ns	0.0136	976 B
#6739	`CallElasticsearch`	net472	2.46μs	1.06ns	3.96ns	0.157	995 B
#6739	`CallElasticsearchAsync`	net6.0	1.27μs	1.38ns	5.17ns	0.0134	952 B
#6739	`CallElasticsearchAsync`	netcoreapp3.1	1.61μs	0.829ns	3.1ns	0.0138	1.02 KB
#6739	`CallElasticsearchAsync`	net472	2.54μs	1.06ns	4.12ns	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.32μs	0.607ns	2.27ns	0.0132	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.67μs	0.489ns	1.69ns	0.0125	952 B
master	`ExecuteAsync`	net472	1.85μs	0.478ns	1.72ns	0.145	915 B
#6739	`ExecuteAsync`	net6.0	1.33μs	0.91ns	3.41ns	0.0133	952 B
#6739	`ExecuteAsync`	netcoreapp3.1	1.6μs	0.83ns	3.11ns	0.013	952 B
#6739	`ExecuteAsync`	net472	1.86μs	0.449ns	1.68ns	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.26μs	1.24ns	4.28ns	0.032	2.31 KB
master	`SendAsync`	netcoreapp3.1	5.34μs	1.27ns	4.57ns	0.0373	2.85 KB
master	`SendAsync`	net472	7.45μs	2.51ns	9.73ns	0.496	3.12 KB
#6739	`SendAsync`	net6.0	4.39μs	1.65ns	6.38ns	0.0307	2.31 KB
#6739	`SendAsync`	netcoreapp3.1	5.43μs	1.92ns	7.2ns	0.0379	2.85 KB
#6739	`SendAsync`	net472	7.43μs	1.32ns	4.93ns	0.494	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.48μs	1.2ns	4.48ns	0.0229	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.19μs	0.963ns	3.6ns	0.0229	1.64 KB
master	`EnrichedLog`	net472	2.63μs	0.704ns	2.64ns	0.249	1.57 KB
#6739	`EnrichedLog`	net6.0	1.58μs	0.512ns	1.92ns	0.023	1.64 KB
#6739	`EnrichedLog`	netcoreapp3.1	2.1μs	1.68ns	6.06ns	0.022	1.64 KB
#6739	`EnrichedLog`	net472	2.46μs	1.02ns	3.94ns	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	112μs	213ns	824ns	0.0553	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	118μs	165ns	640ns	0.0587	0	4.28 KB
master	`EnrichedLog`	net472	149μs	180ns	698ns	0.663	0.221	4.46 KB
#6739	`EnrichedLog`	net6.0	112μs	174ns	651ns	0.0557	0	4.28 KB
#6739	`EnrichedLog`	netcoreapp3.1	116μs	233ns	901ns	0	0	4.28 KB
#6739	`EnrichedLog`	net472	149μs	238ns	920ns	0.673	0.224	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.03μs	0.9ns	3.48ns	0.0318	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.22μs	1.48ns	5.35ns	0.0296	2.2 KB
master	`EnrichedLog`	net472	4.98μs	0.908ns	3.4ns	0.32	2.02 KB
#6739	`EnrichedLog`	net6.0	3.03μs	0.901ns	3.49ns	0.0304	2.2 KB
#6739	`EnrichedLog`	netcoreapp3.1	4.13μs	1.38ns	4.98ns	0.029	2.2 KB
#6739	`EnrichedLog`	net472	5.01μs	1.04ns	4.03ns	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.49μs	1.37ns	5.3ns	0.0157	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.8μs	0.741ns	2.77ns	0.0153	1.14 KB
master	`SendReceive`	net472	2.09μs	0.741ns	2.87ns	0.184	1.16 KB
#6739	`SendReceive`	net6.0	1.36μs	1.14ns	3.96ns	0.0158	1.14 KB
#6739	`SendReceive`	netcoreapp3.1	1.79μs	1.13ns	4.37ns	0.0151	1.14 KB
#6739	`SendReceive`	net472	2.05μs	3.11ns	11.2ns	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.78μs	0.736ns	2.75ns	0.0222	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.94μs	2.1ns	8.11ns	0.0218	1.65 KB
master	`EnrichedLog`	net472	4.26μs	2.41ns	9.32ns	0.323	2.04 KB
#6739	`EnrichedLog`	net6.0	2.7μs	1.48ns	5.73ns	0.0217	1.6 KB
#6739	`EnrichedLog`	netcoreapp3.1	3.78μs	2.21ns	7.66ns	0.0227	1.65 KB
#6739	`EnrichedLog`	net472	4.18μs	1.67ns	6.24ns	0.322	2.04 KB

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

Slower ⚠️ in #6739

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1	1.149	696.24	799.84

Faster 🎉 in #6739

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0	1.189	467.85	393.42

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	468ns	0.142ns	0.513ns	0.00813	576 B
master	`StartFinishSpan`	netcoreapp3.1	587ns	0.343ns	1.33ns	0.00764	576 B
master	`StartFinishSpan`	net472	635ns	0.279ns	1.08ns	0.0916	578 B
master	`StartFinishScope`	net6.0	481ns	0.128ns	0.496ns	0.00979	696 B
master	`StartFinishScope`	netcoreapp3.1	695ns	1.89ns	7.3ns	0.00938	696 B
master	`StartFinishScope`	net472	811ns	0.679ns	2.63ns	0.104	658 B
#6739	`StartFinishSpan`	net6.0	393ns	0.12ns	0.447ns	0.00807	576 B
#6739	`StartFinishSpan`	netcoreapp3.1	584ns	1.22ns	4.71ns	0.00783	576 B
#6739	`StartFinishSpan`	net472	647ns	0.21ns	0.815ns	0.0918	578 B
#6739	`StartFinishScope`	net6.0	506ns	0.176ns	0.636ns	0.00968	696 B
#6739	`StartFinishScope`	netcoreapp3.1	800ns	0.505ns	1.96ns	0.00925	696 B
#6739	`StartFinishScope`	net472	869ns	0.454ns	1.64ns	0.105	658 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	613ns	0.304ns	1.18ns	0.00994	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	928ns	0.298ns	1.11ns	0.00909	696 B
master	`RunOnMethodBegin`	net472	1.1μs	0.364ns	1.41ns	0.104	658 B
#6739	`RunOnMethodBegin`	net6.0	667ns	0.287ns	1.11ns	0.00967	696 B
#6739	`RunOnMethodBegin`	netcoreapp3.1	909ns	0.28ns	1.01ns	0.00909	696 B
#6739	`RunOnMethodBegin`	net472	1.01μs	0.397ns	1.49ns	0.104	658 B

gleocadie

LGTM

Add logs for the different profilers configuration

4f05ff2

chrisnas requested a review from a team as a code owner March 4, 2025 12:30

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

chrisnas added 3 commits March 4, 2025 15:14

Add integration tests

2480748

Merge remote-tracking branch 'origin' into chrisnas/add_config_logs

8d324a0

merge

0bd58ae

gleocadie approved these changes Mar 5, 2025

View reviewed changes

Merge remote-tracking branch 'origin' into chrisnas/add_config_logs

0de0e79

chrisnas merged commit 211f267 into master Mar 6, 2025
72 of 77 checks passed

chrisnas deleted the chrisnas/add_config_logs branch March 6, 2025 15:54

github-actions bot added this to the vNext-v3 milestone Mar 6, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Profiler] Add logs for the different profilers configuration #6739

[Profiler] Add logs for the different profilers configuration #6739

chrisnas commented Mar 4, 2025 •

edited

Loading

andrewlock commented Mar 4, 2025 •

edited

Loading

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

edited

Loading

andrewlock commented Mar 4, 2025 •

edited

Loading

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

Faster 🎉 in #6739

Raw results

Raw results

gleocadie left a comment

[Profiler] Add logs for the different profilers configuration #6739

[Profiler] Add logs for the different profilers configuration #6739

Conversation

chrisnas commented Mar 4, 2025 • edited Loading

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

andrewlock commented Mar 4, 2025 • edited Loading

Execution-Time Benchmarks Report ⏱️

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

Datadog Report

⌛ Performance Regressions vs Default Branch (1)

andrewlock commented Mar 4, 2025 • edited Loading

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

Faster 🎉 in #6739

Raw results

Raw results

gleocadie left a comment

Choose a reason for hiding this comment

chrisnas commented Mar 4, 2025 •

edited

Loading

andrewlock commented Mar 4, 2025 •

edited

Loading

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

edited

Loading

andrewlock commented Mar 4, 2025 •

edited

Loading