[Profiler] Improve .NET Framework profiling support #5867

chrisnas · 2024-08-08T15:23:44Z

Summary of changes

Fix empty stack issue for lock contention samples
Support garbage collection events
Support allocation events

Reason for change

Improve .NET Framework profiling support

PROF-8652
PROF-6983

Implementation details

Test coverage

Other details

gleocadie

What are the changes related to GC ? (I read it in the description)

profiler/src/ProfilerEngine/Datadog.Profiler.Native/ContentionProvider.cpp

datadog-ddstaging · 2024-08-08T15:48:44Z

Datadog Report

Branch report: chrisnas/framework_gc_events
Commit report: d351e16
Test service: dd-trace-dotnet

❌ 1 Failed (0 Known Flaky), 344817 Passed, 2053 Skipped, 15h 43m 38.75s Total Time

❌ Failed Tests (1)

DontRedirectCrashHandlerIfPathNotSet - Datadog.Profiler.IntegrationTests.LinuxOnly.WrapperLibraryTest - Details
Expand for error
```
 Expected runner.WaitForExitOrCaptureDump(processHelper.Process, milliseconds: 30_000) to be true, but found False.
```

andrewlock · 2024-08-08T15:51:14Z

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).

andrewlock · 2024-08-08T17:33:02Z

Throughput/Crank Report ⚡

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 (5867) (11.558M)   : 0, 11557672
    master (11.989M)   : 0, 11988922
    benchmarks/2.9.0 (11.513M)   : 0, 11512780

    section Automatic
    This PR (5867) (7.709M)   : crit ,0, 7708941
    master (8.129M)   : 0, 8128534
    benchmarks/2.9.0 (8.207M)   : 0, 8206882

    section Trace stats
    master (8.363M)   : 0, 8362615

    section Manual
    master (12.022M)   : 0, 12022316

    section Manual + Automatic
    This PR (5867) (7.155M)   : 0, 7155247
    master (7.524M)   : 0, 7524228

    section DD_TRACE_ENABLED=0
    master (11.062M)   : 0, 11062172

gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5867) (9.466M)   : 0, 9466191
    benchmarks/2.9.0 (9.495M)   : 0, 9494663

    section Automatic
    This PR (5867) (6.637M)   : 0, 6636570

    section Manual + Automatic
    This PR (5867) (6.189M)   : 0, 6188918

gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5867) (10.352M)   : 0, 10352445

    section Automatic
    This PR (5867) (5.988M)   : 0, 5988210

    section Manual + Automatic
    This PR (5867) (6.491M)   : 0, 6490788

andrewlock · 2024-08-08T19:35:56Z

Benchmarks Report for tracer 🐌

Benchmarks for #5867 compared to master:

1 benchmarks are slower, with geometric mean 1.134
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	7.87μs	42.6ns	319ns	0.0162	0.00808	0	5.42 KB
master	`StartStopWithChild`	netcoreapp3.1	9.85μs	54.6ns	349ns	0.0145	0.00966	0	5.62 KB
master	`StartStopWithChild`	net472	16μs	39.9ns	154ns	1.03	0.318	0.0955	6.07 KB
#5867	`StartStopWithChild`	net6.0	7.55μs	41.6ns	266ns	0.0179	0.00716	0	5.42 KB
#5867	`StartStopWithChild`	netcoreapp3.1	10.1μs	43.7ns	163ns	0.0245	0.00979	0	5.62 KB
#5867	`StartStopWithChild`	net472	16.3μs	40.9ns	158ns	1.01	0.295	0.0983	6.07 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	472μs	288ns	1.12μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	632μs	224ns	838ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	855μs	505ns	1.89μs	0.428	3.3 KB
#5867	`WriteAndFlushEnrichedTraces`	net6.0	471μs	228ns	882ns	0	2.7 KB
#5867	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	647μs	259ns	935ns	0	2.7 KB
#5867	`WriteAndFlushEnrichedTraces`	net472	834μs	516ns	1.86μ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	192μs	1.02μs	6.79μs	0.184	18.45 KB
master	`SendRequest`	netcoreapp3.1	209μs	1.18μs	7.91μs	0.207	20.61 KB
master	`SendRequest`	net472	0.000596ns	0.000353ns	0.00132ns	0	0 b
#5867	`SendRequest`	net6.0	193μs	1.08μs	6.55μs	0.181	18.45 KB
#5867	`SendRequest`	netcoreapp3.1	213μs	1.2μs	8.13μs	0.218	20.61 KB
#5867	`SendRequest`	net472	0.000598ns	0.000329ns	0.00128ns	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	1.87μs	7.25μs	0.561	0	0	41.73 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	664μs	2.09μs	7.82μs	0.326	0	0	41.98 KB
master	`WriteAndFlushEnrichedTraces`	net472	855μs	4.18μs	17.7μs	8.63	2.47	0.411	53.28 KB
#5867	`WriteAndFlushEnrichedTraces`	net6.0	566μs	1.74μs	6.74μs	0.59	0	0	41.55 KB
#5867	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	674μs	3.36μs	14.6μs	0.329	0	0	41.94 KB
#5867	`WriteAndFlushEnrichedTraces`	net472	865μs	4.33μs	18.4μs	8.19	2.59	0.431	53.36 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.17μs	0.924ns	3.58ns	0.0143	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.66μs	0.756ns	2.73ns	0.0133	1.02 KB
master	`ExecuteNonQuery`	net472	2.05μs	1.8ns	6.96ns	0.157	987 B
#5867	`ExecuteNonQuery`	net6.0	1.22μs	0.962ns	3.72ns	0.0147	1.02 KB
#5867	`ExecuteNonQuery`	netcoreapp3.1	1.7μs	2.28ns	8.84ns	0.0135	1.02 KB
#5867	`ExecuteNonQuery`	net472	1.93μs	1.22ns	4.57ns	0.157	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.18μs	0.457ns	1.77ns	0.0136	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.47μs	0.46ns	1.72ns	0.0133	976 B
master	`CallElasticsearch`	net472	2.51μs	1.61ns	6.23ns	0.158	995 B
master	`CallElasticsearchAsync`	net6.0	1.21μs	0.956ns	3.7ns	0.0133	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.59μs	0.972ns	3.64ns	0.0136	1.02 KB
master	`CallElasticsearchAsync`	net472	2.65μs	1.82ns	7.06ns	0.166	1.05 KB
#5867	`CallElasticsearch`	net6.0	1.31μs	0.883ns	3.42ns	0.0138	976 B
#5867	`CallElasticsearch`	netcoreapp3.1	1.46μs	0.537ns	2.01ns	0.0131	976 B
#5867	`CallElasticsearch`	net472	2.45μs	1.47ns	5.71ns	0.158	995 B
#5867	`CallElasticsearchAsync`	net6.0	1.33μs	1.14ns	4.26ns	0.0134	952 B
#5867	`CallElasticsearchAsync`	netcoreapp3.1	1.57μs	1.1ns	4.13ns	0.0139	1.02 KB
#5867	`CallElasticsearchAsync`	net472	2.57μs	1.39ns	5ns	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.17μs	0.935ns	3.5ns	0.0134	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.68μs	0.805ns	3.12ns	0.0125	952 B
master	`ExecuteAsync`	net472	1.81μs	1.03ns	3.85ns	0.145	915 B
#5867	`ExecuteAsync`	net6.0	1.29μs	0.799ns	2.88ns	0.0129	952 B
#5867	`ExecuteAsync`	netcoreapp3.1	1.6μs	0.459ns	1.72ns	0.0129	952 B
#5867	`ExecuteAsync`	net472	1.75μs	0.266ns	0.922ns	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.08μs	1.74ns	6.5ns	0.0305	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.04μs	2.85ns	11.1ns	0.038	2.76 KB
master	`SendAsync`	net472	7.78μs	1.67ns	6.24ns	0.497	3.15 KB
#5867	`SendAsync`	net6.0	4.19μs	1.18ns	4.43ns	0.0314	2.22 KB
#5867	`SendAsync`	netcoreapp3.1	5.02μs	1.66ns	6.42ns	0.0376	2.76 KB
#5867	`SendAsync`	net472	7.84μs	1.67ns	6.46ns	0.498	3.15 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.5μs	0.663ns	2.48ns	0.0234	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.12μs	0.486ns	1.75ns	0.0221	1.64 KB
master	`EnrichedLog`	net472	2.71μs	4.48ns	17.4ns	0.249	1.57 KB
#5867	`EnrichedLog`	net6.0	1.58μs	0.785ns	2.94ns	0.0229	1.64 KB
#5867	`EnrichedLog`	netcoreapp3.1	2.21μs	1.02ns	3.81ns	0.022	1.64 KB
#5867	`EnrichedLog`	net472	2.64μs	1.01ns	3.91ns	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	163ns	630ns	0.0575	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	120μs	146ns	566ns	0	0	4.28 KB
master	`EnrichedLog`	net472	149μs	159ns	615ns	0.673	0.224	4.46 KB
#5867	`EnrichedLog`	net6.0	115μs	144ns	558ns	0.0581	0	4.28 KB
#5867	`EnrichedLog`	netcoreapp3.1	120μs	164ns	637ns	0	0	4.28 KB
#5867	`EnrichedLog`	net472	150μs	219ns	850ns	0.672	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.19μs	0.898ns	3.48ns	0.0303	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.34μs	1.63ns	6.3ns	0.0298	2.2 KB
master	`EnrichedLog`	net472	4.83μs	1.27ns	4.75ns	0.319	2.02 KB
#5867	`EnrichedLog`	net6.0	3.18μs	1.67ns	6.47ns	0.0303	2.2 KB
#5867	`EnrichedLog`	netcoreapp3.1	4.21μs	0.814ns	3.04ns	0.0295	2.2 KB
#5867	`EnrichedLog`	net472	4.91μs	1.5ns	5.8ns	0.319	2.02 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendReceive`	net6.0	1.33μs	0.654ns	2.53ns	0.016	0	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.78μs	1.33ns	5.13ns	0.0152	0	1.14 KB
master	`SendReceive`	net472	2.24μs	2.28ns	8.82ns	0.183	0.00112	1.16 KB
#5867	`SendReceive`	net6.0	1.38μs	1.55ns	6.02ns	0.0159	0	1.14 KB
#5867	`SendReceive`	netcoreapp3.1	1.73μs	0.49ns	1.7ns	0.0155	0	1.14 KB
#5867	`SendReceive`	net472	2.18μs	2.25ns	8.72ns	0.183	0.00108	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.79μs	0.556ns	2.08ns	0.0222	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.88μs	1.29ns	5ns	0.0214	1.65 KB
master	`EnrichedLog`	net472	4.43μs	1.19ns	4.46ns	0.323	2.04 KB
#5867	`EnrichedLog`	net6.0	2.8μs	1.07ns	4ns	0.0225	1.6 KB
#5867	`EnrichedLog`	netcoreapp3.1	3.92μs	1.48ns	5.72ns	0.0216	1.65 KB
#5867	`EnrichedLog`	net472	4.41μs	1.67ns	6.24ns	0.324	2.04 KB

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

Slower ⚠️ in #5867

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1	1.134	567.02	643.28

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	401ns	0.224ns	0.868ns	0.00809	576 B
master	`StartFinishSpan`	netcoreapp3.1	567ns	0.387ns	1.5ns	0.0079	576 B
master	`StartFinishSpan`	net472	598ns	0.647ns	2.5ns	0.0916	578 B
master	`StartFinishScope`	net6.0	547ns	0.227ns	0.878ns	0.00964	696 B
master	`StartFinishScope`	netcoreapp3.1	747ns	0.654ns	2.53ns	0.0093	696 B
master	`StartFinishScope`	net472	889ns	0.598ns	2.32ns	0.104	658 B
#5867	`StartFinishSpan`	net6.0	405ns	0.818ns	3.17ns	0.00814	576 B
#5867	`StartFinishSpan`	netcoreapp3.1	643ns	0.518ns	2ns	0.00768	576 B
#5867	`StartFinishSpan`	net472	609ns	0.304ns	1.14ns	0.0917	578 B
#5867	`StartFinishScope`	net6.0	546ns	0.661ns	2.56ns	0.00969	696 B
#5867	`StartFinishScope`	netcoreapp3.1	791ns	1.1ns	4.26ns	0.00951	696 B
#5867	`StartFinishScope`	net472	882ns	0.552ns	2.14ns	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	652ns	0.672ns	2.6ns	0.00986	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	929ns	0.986ns	3.82ns	0.00924	696 B
master	`RunOnMethodBegin`	net472	1.06μs	0.959ns	3.71ns	0.104	658 B
#5867	`RunOnMethodBegin`	net6.0	723ns	1.68ns	6.49ns	0.0099	696 B
#5867	`RunOnMethodBegin`	netcoreapp3.1	985ns	0.999ns	3.74ns	0.00928	696 B
#5867	`RunOnMethodBegin`	net472	1.04μs	0.728ns	2.82ns	0.104	658 B

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Windows/EtwEventsManager.cpp

chrisnas · 2024-08-16T08:46:10Z

What are the changes related to GC ? (I read it in the description)

the timestamp fix works for both (gc events were recorded by with the wrong timestamp did not appear in the timeline)

Fix empty stack issue for lock contention samples

be5162e

chrisnas requested a review from a team as a code owner August 8, 2024 15:23

github-actions bot added the area:profiler Issues related to the continous-profiler label Aug 8, 2024

gleocadie approved these changes Aug 8, 2024

View reviewed changes

profiler/src/ProfilerEngine/Datadog.Profiler.Native/ContentionProvider.cpp Outdated Show resolved Hide resolved

chrisnas added 3 commits August 9, 2024 12:15

Fix daylight saving time for lock contention

0c5643f

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

36a6369

Take feedback into account

ffebf85

r1viollet reviewed Aug 12, 2024

View reviewed changes

profiler/src/ProfilerEngine/Datadog.Profiler.Native.Windows/EtwEventsManager.cpp Show resolved Hide resolved

chrisnas added 6 commits August 12, 2024 18:39

Handle GC and allocations events for .NET Framework

30a4a1d

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

028be30

Don't send allocation size sample in .NET Framework

28afb6b

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

5dca51c

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

75c25eb

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

a4c1c9d

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

d351e16

chrisnas merged commit 24ce4c7 into master Aug 16, 2024
72 of 76 checks passed

chrisnas deleted the chrisnas/framework_gc_events branch August 16, 2024 11:53

github-actions bot added this to the vNext-v3 milestone Aug 16, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Profiler] Improve .NET Framework profiling support #5867

[Profiler] Improve .NET Framework profiling support #5867

chrisnas commented Aug 8, 2024 •

edited

Loading

gleocadie left a comment

datadog-ddstaging bot commented Aug 8, 2024 •

edited

Loading

andrewlock commented Aug 8, 2024 •

edited

Loading

andrewlock commented Aug 8, 2024

andrewlock commented Aug 8, 2024 •

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

Raw results

Raw results

chrisnas commented Aug 16, 2024

[Profiler] Improve .NET Framework profiling support #5867

[Profiler] Improve .NET Framework profiling support #5867

Conversation

chrisnas commented Aug 8, 2024 • edited Loading

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

gleocadie left a comment

Choose a reason for hiding this comment

datadog-ddstaging bot commented Aug 8, 2024 • edited Loading

Datadog Report

❌ Failed Tests (1)

andrewlock commented Aug 8, 2024 • edited Loading

Execution-Time Benchmarks Report ⏱️

andrewlock commented Aug 8, 2024

Throughput/Crank Report ⚡

andrewlock commented Aug 8, 2024 • 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 #5867

Raw results

Raw results

chrisnas commented Aug 16, 2024

chrisnas commented Aug 8, 2024 •

edited

Loading

datadog-ddstaging bot commented Aug 8, 2024 •

edited

Loading

andrewlock commented Aug 8, 2024 •

edited

Loading

andrewlock commented Aug 8, 2024 •

edited

Loading