Prevent the native loader from being unloaded while sending telemetry by kevingosse · Pull Request #5944 · DataDog/dd-trace-dotnet

kevingosse · 2024-08-26T13:12:40Z

Summary of changes

Prevent the native loader from being unloaded while sending telemetry.

Reason for change

We send telemetry when we decide not to instrument a process (for instance because of an EOL runtime). To send the telemetry, we spawn the telemetry forwarder. This is done in a background thread to avoid blocking the startup of the process. However, .NET unloads the profiler when the CorProfilerInfo::Initialize method returns, even if the background thread is still running, causing a segfault.

Implementation details

We increment the reference count of the module to prevent it from being unloaded by the .NET runtime.

Two different implementations:

On Windows, we use GetModuleHandleEx to increment the reference count. Then, when we're done sending the telemetry, we use FreeLibraryAndExitThread to safely unload the module.
On Linux, we use dlopen to increment the reference count. Unfortunately there is no safe way to unload the module from within itself, so we keep it in memory.

If for some reason we failed to increment the reference count, we give up on sending telemetry.

Test coverage

OnEolFrameworkInSsi_WhenForwarderPathExists_CallsForwarderWithExpectedTelemetry segfaults on 3.0 without this change.

tonyredondo · 2024-08-26T13:18:00Z

+#else
+    // Use dlopen to increment the reference count of the module
+    void* handle = 0;
+    Dl_info info;
+    if (dladdr((void*)&GetRuntimeId, &info))
+    {
+        handle = dlopen(info.dli_fname, RTLD_LAZY);
+    }
+#endif


I think yes but are we sure this works as intended on macOS?

Do we need some tests?

OSX has dlopen so that should work 🤔

andrewlock · 2024-08-26T13:38: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).

datadog-ddstaging · 2024-08-26T13:40:56Z

Datadog Report

Branch report: kevin/safe_unload
Commit report: 8db81ca
Test service: dd-trace-dotnet

✅ 0 Failed, 298016 Passed, 1851 Skipped, 13h 34m 21.57s Total Time
⌛ 1 Performance Regression

⌛ Performance Regressions vs Default Branch (1)

Baseline_liveheap - scenarios 2.84s (+99.93ms, +4%) - Details

andrewlock · 2024-08-26T14:44:15Z

Benchmarks Report for tracer 🐌

Benchmarks for #5944 compared to master:

1 benchmarks are faster, with geometric mean 1.120
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.69μs	44ns	317ns	0.0151	0.00754	0	5.42 KB
master	`StartStopWithChild`	netcoreapp3.1	9.99μs	53.8ns	284ns	0.0248	0.00991	0	5.62 KB
master	`StartStopWithChild`	net472	15.9μs	48.3ns	181ns	1.02	0.302	0.0952	6.07 KB
#5944	`StartStopWithChild`	net6.0	7.83μs	44.6ns	331ns	0.0118	0.00394	0	5.43 KB
#5944	`StartStopWithChild`	netcoreapp3.1	9.93μs	53.8ns	305ns	0.0191	0.00956	0	5.61 KB
#5944	`StartStopWithChild`	net472	16.3μs	53.3ns	207ns	1.04	0.324	0.0971	6.08 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	470μs	261ns	1.01μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	651μs	275ns	1.03μs	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	838μs	644ns	2.49μs	0.419	3.3 KB
#5944	`WriteAndFlushEnrichedTraces`	net6.0	475μs	149ns	515ns	0	2.7 KB
#5944	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	668μs	532ns	2.06μs	0	2.7 KB
#5944	`WriteAndFlushEnrichedTraces`	net472	835μs	345ns	1.29μ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	189μs	1.06μs	6.78μs	0.188	18.45 KB
master	`SendRequest`	netcoreapp3.1	210μs	1E+03ns	5.66μs	0.21	20.61 KB
master	`SendRequest`	net472	0.000126ns	0.000126ns	0.000454ns	0	0 b
#5944	`SendRequest`	net6.0	190μs	1.1μs	9.21μs	0.18	18.45 KB
#5944	`SendRequest`	netcoreapp3.1	206μs	1.04μs	4.98μs	0.212	20.61 KB
#5944	`SendRequest`	net472	0.00597ns	0.00106ns	0.00397ns	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	555μs	1.06μs	3.67μs	0.566	0	0	41.6 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	672μs	3.19μs	12.4μs	0.327	0	0	41.83 KB
master	`WriteAndFlushEnrichedTraces`	net472	890μs	3.36μs	13μs	8.13	2.57	0.428	53.34 KB
#5944	`WriteAndFlushEnrichedTraces`	net6.0	548μs	1.61μs	5.81μs	0.556	0	0	41.45 KB
#5944	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	666μs	2.33μs	9.04μs	0.331	0	0	41.79 KB
#5944	`WriteAndFlushEnrichedTraces`	net472	853μs	3.75μs	14.5μs	8.25	2.6	0.434	53.28 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.25μs	1.18ns	4.57ns	0.0142	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.72μs	1.1ns	4.26ns	0.0137	1.02 KB
master	`ExecuteNonQuery`	net472	2.1μs	1.69ns	6.32ns	0.157	987 B
#5944	`ExecuteNonQuery`	net6.0	1.23μs	2.97ns	11.5ns	0.0147	1.02 KB
#5944	`ExecuteNonQuery`	netcoreapp3.1	1.7μs	1.04ns	3.88ns	0.0136	1.02 KB
#5944	`ExecuteNonQuery`	net472	2.03μs	1.04ns	4.01ns	0.156	987 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net6.0	1.24μs	0.842ns	3.15ns	0.0135	0	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.46μs	0.942ns	3.53ns	0.0134	0	976 B
master	`CallElasticsearch`	net472	2.37μs	1.87ns	7.24ns	0.158	0.00119	995 B
master	`CallElasticsearchAsync`	net6.0	1.26μs	0.695ns	2.51ns	0.0132	0	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.7μs	0.858ns	3.21ns	0.0136	0	1.02 KB
master	`CallElasticsearchAsync`	net472	2.62μs	2.13ns	8.25ns	0.167	0.00131	1.05 KB
#5944	`CallElasticsearch`	net6.0	1.25μs	0.858ns	3.32ns	0.0138	0	976 B
#5944	`CallElasticsearch`	netcoreapp3.1	1.51μs	0.482ns	1.87ns	0.0136	0	976 B
#5944	`CallElasticsearch`	net472	2.42μs	1.34ns	5.18ns	0.158	0.00122	995 B
#5944	`CallElasticsearchAsync`	net6.0	1.35μs	0.545ns	2.11ns	0.0134	0	952 B
#5944	`CallElasticsearchAsync`	netcoreapp3.1	1.67μs	0.476ns	1.72ns	0.0134	0	1.02 KB
#5944	`CallElasticsearchAsync`	net472	2.59μs	1.87ns	7.25ns	0.167	0	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.27μs	0.881ns	3.41ns	0.0134	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.66μs	0.531ns	2.06ns	0.0124	952 B
master	`ExecuteAsync`	net472	1.79μs	0.888ns	3.44ns	0.145	915 B
#5944	`ExecuteAsync`	net6.0	1.32μs	2.53ns	9.79ns	0.013	952 B
#5944	`ExecuteAsync`	netcoreapp3.1	1.63μs	0.957ns	3.71ns	0.013	952 B
#5944	`ExecuteAsync`	net472	1.65μs	0.982ns	3.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.05μs	1.36ns	5.08ns	0.0308	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.08μs	2.25ns	8.73ns	0.0356	2.76 KB
master	`SendAsync`	net472	8.09μs	1.89ns	7.3ns	0.499	3.15 KB
#5944	`SendAsync`	net6.0	4.03μs	1.59ns	6.16ns	0.0302	2.22 KB
#5944	`SendAsync`	netcoreapp3.1	5.09μs	2.04ns	7.35ns	0.0358	2.76 KB
#5944	`SendAsync`	net472	7.8μs	3.48ns	13.5ns	0.497	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.64μs	5.49ns	21.3ns	0.0226	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.28μs	1.76ns	6.57ns	0.022	1.64 KB
master	`EnrichedLog`	net472	2.74μs	2.65ns	9.9ns	0.249	1.57 KB
#5944	`EnrichedLog`	net6.0	1.55μs	0.647ns	2.42ns	0.0231	1.64 KB
#5944	`EnrichedLog`	netcoreapp3.1	2.28μs	1.52ns	5.67ns	0.0215	1.64 KB
#5944	`EnrichedLog`	net472	2.67μs	1.89ns	7.32ns	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	254ns	984ns	0.0584	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	121μs	198ns	766ns	0	0	4.28 KB
master	`EnrichedLog`	net472	149μs	424ns	1.64μs	0.666	0.222	4.46 KB
#5944	`EnrichedLog`	net6.0	118μs	157ns	589ns	0.0587	0	4.28 KB
#5944	`EnrichedLog`	netcoreapp3.1	119μs	208ns	806ns	0	0	4.28 KB
#5944	`EnrichedLog`	net472	151μs	205ns	794ns	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	3μs	3.36ns	13ns	0.0302	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.33μs	4.36ns	16.3ns	0.0282	2.2 KB
master	`EnrichedLog`	net472	4.87μs	2.62ns	10.2ns	0.319	2.02 KB
#5944	`EnrichedLog`	net6.0	2.94μs	1.12ns	4.34ns	0.0308	2.2 KB
#5944	`EnrichedLog`	netcoreapp3.1	4.19μs	3.11ns	11.6ns	0.0294	2.2 KB
#5944	`EnrichedLog`	net472	4.85μs	1.32ns	5.11ns	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.37μs	0.77ns	2.98ns	0.0158	0	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.82μs	2.19ns	7.9ns	0.0155	0	1.14 KB
master	`SendReceive`	net472	2.21μs	1.7ns	6.58ns	0.183	0	1.16 KB
#5944	`SendReceive`	net6.0	1.34μs	1.16ns	4.35ns	0.016	0	1.14 KB
#5944	`SendReceive`	netcoreapp3.1	1.76μs	0.954ns	3.69ns	0.0157	0	1.14 KB
#5944	`SendReceive`	net472	2.23μs	1.72ns	6.65ns	0.183	0.00112	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.7μs	0.749ns	2.9ns	0.023	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.9μs	2.57ns	9.63ns	0.0214	1.65 KB
master	`EnrichedLog`	net472	4.38μs	3.36ns	13ns	0.324	2.04 KB
#5944	`EnrichedLog`	net6.0	2.78μs	0.909ns	3.52ns	0.0223	1.6 KB
#5944	`EnrichedLog`	netcoreapp3.1	3.79μs	1.32ns	4.94ns	0.0211	1.65 KB
#5944	`EnrichedLog`	net472	4.43μs	3.6ns	13.9ns	0.322	2.04 KB

Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5944

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net472	1.120	939.28	838.58

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	397ns	0.195ns	0.755ns	0.0081	576 B
master	`StartFinishSpan`	netcoreapp3.1	596ns	0.379ns	1.47ns	0.00785	576 B
master	`StartFinishSpan`	net472	624ns	0.719ns	2.78ns	0.0917	578 B
master	`StartFinishScope`	net6.0	512ns	0.19ns	0.734ns	0.00974	696 B
master	`StartFinishScope`	netcoreapp3.1	695ns	0.547ns	2.12ns	0.00935	696 B
master	`StartFinishScope`	net472	939ns	1.39ns	5.38ns	0.104	658 B
#5944	`StartFinishSpan`	net6.0	410ns	0.174ns	0.675ns	0.00813	576 B
#5944	`StartFinishSpan`	netcoreapp3.1	554ns	0.192ns	0.719ns	0.00783	576 B
#5944	`StartFinishSpan`	net472	631ns	0.3ns	1.16ns	0.0915	578 B
#5944	`StartFinishScope`	net6.0	470ns	0.182ns	0.703ns	0.0098	696 B
#5944	`StartFinishScope`	netcoreapp3.1	761ns	0.269ns	0.971ns	0.00948	696 B
#5944	`StartFinishScope`	net472	838ns	0.418ns	1.62ns	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	648ns	0.316ns	1.22ns	0.00974	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	984ns	1.46ns	5.65ns	0.00932	696 B
master	`RunOnMethodBegin`	net472	1.09μs	1.21ns	4.68ns	0.105	658 B
#5944	`RunOnMethodBegin`	net6.0	668ns	0.127ns	0.493ns	0.00972	696 B
#5944	`RunOnMethodBegin`	netcoreapp3.1	913ns	0.398ns	1.44ns	0.00926	696 B
#5944	`RunOnMethodBegin`	net472	1.1μs	2.33ns	9.03ns	0.104	658 B

andrewlock

Taking your word for it, but it LGTM

…#5944) ## Summary of changes Prevent the native loader from being unloaded while sending telemetry. ## Reason for change We send telemetry when we decide not to instrument a process (for instance because of an EOL runtime). To send the telemetry, we spawn the telemetry forwarder. This is done in a background thread to avoid blocking the startup of the process. However, .NET unloads the profiler when the `CorProfilerInfo::Initialize` method returns, even if the background thread is still running, causing a segfault. ## Implementation details We increment the reference count of the module to prevent it from being unloaded by the .NET runtime. Two different implementations: - On Windows, we use `GetModuleHandleEx` to increment the reference count. Then, when we're done sending the telemetry, we use `FreeLibraryAndExitThread` to safely unload the module. - On Linux, we use `dlopen` to increment the reference count. Unfortunately there is no safe way to unload the module from within itself, so we keep it in memory. If for some reason we failed to increment the reference count, we give up on sending telemetry. ## Test coverage `OnEolFrameworkInSsi_WhenForwarderPathExists_CallsForwarderWithExpectedTelemetry` segfaults on 3.0 without this change.

…#5944 => V2) (#5957) This is a backport of #5944 to v2. ## Summary of changes Prevent the native loader from being unloaded while sending telemetry. ## Reason for change We send telemetry when we decide not to instrument a process (for instance because of an EOL runtime). To send the telemetry, we spawn the telemetry forwarder. This is done in a background thread to avoid blocking the startup of the process. However, .NET unloads the profiler when the `CorProfilerInfo::Initialize` method returns, even if the background thread is still running, causing a segfault. ## Implementation details We increment the reference count of the module to prevent it from being unloaded by the .NET runtime. Two different implementations: - On Windows, we use `GetModuleHandleEx` to increment the reference count. Then, when we're done sending the telemetry, we use `FreeLibraryAndExitThread` to safely unload the module. - On Linux, we use `dlopen` to increment the reference count. Unfortunately there is no safe way to unload the module from within itself, so we keep it in memory. If for some reason we failed to increment the reference count, we give up on sending telemetry. ## Test coverage `OnEolFrameworkInSsi_WhenForwarderPathExists_CallsForwarderWithExpectedTelemetry` segfaults on 3.0 without this change.

Kevin Gosse added 2 commits August 26, 2024 14:53

Linux

e624b15

Windows

859ab72

kevingosse requested a review from a team as a code owner August 26, 2024 13:12

github-actions Bot added the area:shared-components label Aug 26, 2024

tonyredondo approved these changes Aug 26, 2024

View reviewed changes

Fix compilation error

8db81ca

andrewlock approved these changes Aug 27, 2024

View reviewed changes

andrewlock mentioned this pull request Aug 27, 2024

Stop unloading the native loader on error #5942

Closed

kevingosse merged commit 778166d into master Aug 28, 2024

kevingosse deleted the kevin/safe_unload branch August 28, 2024 11:03

github-actions Bot added this to the vNext-v3 milestone Aug 28, 2024

kevingosse mentioned this pull request Aug 28, 2024

Prevent the native loader from being unloaded while sending telemetry (#5944 => V2) #5957

Merged

Uh oh!

Conversation

kevingosse commented Aug 26, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary of changes

Reason for change

Implementation details

Test coverage

Uh oh!

tonyredondo Aug 26, 2024

Choose a reason for hiding this comment

Uh oh!

kevingosse Aug 27, 2024

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Aug 26, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Execution-Time Benchmarks Report ⏱️

Uh oh!

datadog-ddstaging Bot commented Aug 26, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Datadog Report

⌛ Performance Regressions vs Default Branch (1)

Uh oh!

andrewlock commented Aug 26, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

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

Faster 🎉 in #5944

Raw results

Raw results

Uh oh!

andrewlock left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

kevingosse commented Aug 26, 2024 •

edited

Loading

andrewlock commented Aug 26, 2024 •

edited

Loading

datadog-ddstaging Bot commented Aug 26, 2024 •

edited

Loading

andrewlock commented Aug 26, 2024 •

edited

Loading