Adding OpenTelemetry instrumentation results in 15% RPS degradation

@noahfalk

Description

In the ASP.NET benchmarks, one of the scenarios we run is a "TODOs API" service which is basically a CRUD web api over top of a postgres database. We added it as part of our "cloud native" push in .NET 8. The intention was to track the perf difference between normal .NET, native AOT, trimming, etc.

It was always our intention to include OpenTelemetry in this scenario. It wasn't originally added because OpenTelemetry wasn't native AOT compatible at the time. But now it is, and I decided to enable the same configuration that .NET Aspire defaults to - Add OpenTelemetry to TodosApi (aspnet/Benchmarks#2014).

It adds tracing and metrics instrumentation, and the OTLP exporter configured on an environment variable. The environment variable isn't set in our system, so the telemetry doesn't go anywhere.

I would have thought there wouldn't be much runtime overhead in this scenario, but we are seeing a decent sized regression in RPS now that this is enabled.

Configuration

.NET 9 recent daily builds. Windows and Linux x64.

Regression?

This isn't a regression in .NET. But adding OpenTelemetry instrumentation to an application (even when there are no exporters) is a performance regression.

Data

https://aka.ms/aspnet/nativeaot/benchmarks/

On the "Native AOT" page - 18 of 21 - (which tracks the same benchmark apps against regular coreclr and native AOT. Note that this issue repros on both, so it isn't a native AOT issue).
Select "Stage2" on the right. You can pick Intel Linux or Intel Windows at the top, or both.
Notice the drop in RPS and the increase in average latency on Aug 20, 2024

The RPS went from 270k => 230k on linux. This date is the first time the benchmark was run after aspnet/Benchmarks#2014 was merged.

The following .zip contains before and after .nettrace files of the benchmark.
OpenTelemetryTraces.zip

Analysis

Doing a diff between the 2, I see a bunch more "DotNETRuntime/Contention/Start" events in the "after" for System.Diagnostics.DiagnosticSource

Before:

After:

This appears to be the same issue as illustrated in this simplified repro: https://github.com/cijothomas/lock-contention-activity-repro/blob/main/lock-contention-activity-repro/Program.cs.

cc @noahfalk @tarekgh @cijothomas

@tommcdon

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

Sounds like the same problem as dotnet/aspnetcore#50412

Tagging subscribers to this area: @dotnet/area-system-diagnostics-activity
See info in area-owners.md if you want to be subscribed.

tldr: RPS counters should be ThreadStatic or CpuCore based rather than Interlocked

The RPS being measured in the above benchmark is client side RPS using Wrk.

Sounds like the same problem as dotnet/aspnetcore#50412

Not fully. Based on the traces shown in screenshot, contention is at the Activity level. There is some contention shown for Metric path too. I am yet to check the traces fully to see if it is at the MeterListener level, or occurring at OpenTelemetry level. (I doubt if it is at OTel level, as there is no "lock" statement used by OTel Metrics in hot path.)

Activity and Meter have the same mechanism in calling back the registered listener which requires the lock to avoid mutating the listeners list during the operation. We need to change that for both cases to avoid locking during the notification.

Interesting seeing this issue here, as we recently had to rollback our OpenTelemetry instrumentation in one of our tool applications.

We have a console app that executes tasks for our background task queue mechanism. In our beta environment, we have nearly 1000 instances of this same .exe process running, across just 2 servers. Those 2 servers usually run at 25 to 30% CPU usage. When a very basic otel setup was introduced, usage capped the server at 100% CPU and would never drop from there: the environment stalled and we had to remove the instrumentation.

Because of this extreme performance effect, we currently have a custom feature toggle on our side that we check during initialization to conditionally call AddOpenTelemetry (and the rest of the OTEL setup) on a particular instance. So now we have OTEL enabled on just 3 or 4 out of the 1000 work types that we have (basically, one work type is mapped to one .exe instance).

Since our application is still using .NET 472, we've not pursued this much further for now as the intent was to reevaluate performance when we could perform the migration to .NET8, which is coming soon.

In our case, the degradation was vastly more significant than 15%, and it seemed to impact the project even if we removed every single instrumentation from the pipeline, which was extremely surprising to me. It is as if just the presence of the built-in hosted services already adds the biggest chunk of the overhead, for whatever reason.

Another thing worth mentioning is that this tool does not have ASPNETCore involved at all. It is just a simple console application that runs on an infinite while loop, dequeueing and processing work based on an input parameter that indicates "which type of work it should dequeue/process".

@AlgorithmsAreCool

@AlgorithmsAreCool I used this repro to test this : https://github.com/cijothomas/lock-contention-activity-repro/blob/main/lock-contention-activity-repro/Program.cs

(It exposes the metric about contentions via prometheus, leveraing OpenTelemetry internally!)

I used this repro to test this : ...

I'll use this repro also to see it's impact. My current test was targeted at contention on the collection of DiagnosticListeners

My main issue right now is convincing my test app to properly consume the new version of System.Diagnostics.DiagnosticSource that i have built. 😥

But based on my testing this should eliminate ~80% of the contention from starting and stopping activities

@tarekgh

@tarekgh Is there a doc somewhere on how to consume local versions of the runtime?

My microbenchmark benchmark results (so far...)

10 threads
50,000 start/dispose activities per thread
10 ActivityListeners
10 runs of benchmark

Before

119, 968 Microsoft-Windows-DotNETRuntime/Contention/Start events

Lock Contentions 17,024
Lock Contentions per thread 1,702.400
Lock Contentions per iteration 0.034

Lock Contentions 16,522
Lock Contentions per thread 1,652.200
Lock Contentions per iteration 0.033

Lock Contentions 16,201
Lock Contentions per thread 1,620.100
Lock Contentions per iteration 0.032

Lock Contentions 15,917
Lock Contentions per thread 1,591.700
Lock Contentions per iteration 0.032

Lock Contentions 16,767
Lock Contentions per thread 1,676.700
Lock Contentions per iteration 0.034

Lock Contentions 15,336
Lock Contentions per thread 1,533.600
Lock Contentions per iteration 0.031

Lock Contentions 15,068
Lock Contentions per thread 1,506.800
Lock Contentions per iteration 0.030

Lock Contentions 15,952
Lock Contentions per thread 1,595.200
Lock Contentions per iteration 0.032

Lock Contentions 16,173
Lock Contentions per thread 1,617.300
Lock Contentions per iteration 0.032

Lock Contentions 17,289
Lock Contentions per thread 1,728.900
Lock Contentions per iteration 0.035

Elapsed time: 00:00:15.1899827

After

0 Microsoft-Windows-DotNETRuntime/Contention/Start events

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Lock Contentions 0
Lock Contentions per thread 0.000
Lock Contentions per iteration 0.000

Elapsed time: 00:00:01.5148120

Unless i've done something quite wrong, this should be correct. My methodology was to switch to an immutable copy-on-write approach for modifying the listener collection that uses a CAS to mutate the collection.

It should be noted that this approach will be slightly slower to add/remove listeners because the list of listeners must be copied each time it is mutated. That that performance will degrade with O(N) complexity as the number of listeners grows.

However, that event should be rare compared to creation of Activities which is made much much faster under contention and likely in the uncontented scenario also because the previous approach would acquire/release a lock for each item in the listener collection individually.

Note the above microbenchmark shows a 10x improvement in runtime using the lock-free approach under contention.

Also, there is a slight behavioral change.

Previously, if a listener was added or removed from the list exactly during the signaling of a single Activity, that change would be observed because the list was being locked/unlocked for each item in the list
With the proposed change, the Activity thread obtains a local immutable version of the list before it begins signaling listeners.

I doubt anyone will notice this at all and since this is a mutithreaded scenario, there would be no way to reliably reproduce the previous behavior anyway.

I agree usually creating/adding listeners is done a few times in main scenarios so we can accept some perf degradation there.
I didn't see your changes but want to mention, we want to avoid depending on Immutable collections library in System..Diagnostics.DiagnosticSource.dll. because the diagnostic library is low in stack, and we are trying to reduce the dependencies for the sake of AOT scenarios and avoid cyclic dependencies. Considering that, we need to mimic the immutable collection behavior in the fix here.

Previously, if a listener was added or removed from the list exactly during the signaling of a single Activity, that change would be observed because the list was being locked/unlocked for each item in the list

Previously we had a problem too as it can report the event twice to the same listener. We should be ok/better with the change here.

I didn't see your changes but want to mention, we want to avoid depending on Immutable collections library in System..Diagnostics.DiagnosticSource.dll. because the diagnostic library is low in stack, and we are trying to reduce the dependencies for the sake of AOT scenarios and avoid cyclic dependencies. Considering that, we need to mimic the immutable collection behavior in the fix here.

I can make this change, it is fairly simple. I'll retest after removing the dependency

Btw, this change would affect my team also from a perf perspective. Given the date, is this looking like a .NET 9 fix or a .NET 10 fix?

We are targeting .NET 10 here. We are trying to avoid any risk for current release.

@cijothomas

Updated figures after the following changes

Removed Immutable collections
Added Prometheus and instrumentation per @cijothomas
Better table ✨

Thread Count	Methodology	Max Contentions	Min Contentions	Average Contentions	Average Execution Time (s)
1	Baseline	0	0	0	0.04198
2	Baseline	1	0	0.125	0.05053
4	Baseline	9	18	3.406	0.081563
8	Baseline	2168	1472	1743.125	0.300675
16	Baseline	4436	3622	4005.375	0.6288
1	New	0	0	0	0.039686
2	New	0	0	0	0.041909
4	New	0	0	0	0.047901
8	New	0	0	0	0.063951
16	New	0	0	0	0.073664

Opened a draft PR with the changes

Navigation Menu

Repository navigation

Adding OpenTelemetry instrumentation results in 15% RPS degradation #107158

Description

Configuration

Regression?

Data

Analysis

Before:

After:

7 remaining items

Before

After

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Adding OpenTelemetry instrumentation results in 15% RPS degradation #107158

Description

Description

Configuration

Regression?

Data

Analysis

Before:

After:

Activity

dotnet-policy-service commented on Aug 29, 2024

EgorBo commented on Aug 29, 2024

dotnet-policy-service commented on Aug 29, 2024

eerhardt commented on Aug 29, 2024

cijothomas commented on Aug 29, 2024

tarekgh commented on Aug 29, 2024

julealgon commented on Aug 30, 2024

7 remaining items

cijothomas commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

Before

After

AlgorithmsAreCool commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

tarekgh commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 3, 2024

tarekgh commented on Sep 3, 2024

AlgorithmsAreCool commented on Sep 4, 2024

AlgorithmsAreCool commented on Sep 4, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions