Perf bottleneck when Loggers upgrade weak ref to LoggerProvider

[cijothomas]

Noticed while stress testing Logs, but should be applicable to Tracing as well, as they follow the same pattern, where Logger (Tracer), holds a Weak ref to LoggerProvider (TracerProvider), and in hoth path (logger.EmitLog, span.Record), the weak reference to provider is upgraded to Arc, to obtain things like processor list, resource etc. from the provider. This weak -> Arc upgrade seems to be the bottleneck.

Here's how I tested:

1. Ran the stress test for logs, in my box, and it shows ~7M/sec throughput.
2. Modified the NoOpLogProcessor in the above test to return false, which should make the throughput skyrocket as we don't have to do anything like creating LogRecord or invoke processors etc. This did increase the throughput to ~35M/sec, but I was expecting 200+M/sec, as I get similar throughout when using tracing+no-op-tracing-subscriber, without any OpenTelemetry component.
3. After some manual explorations, found that the upgrading of weak to Arc in the hot path of checking if event is enabled is the bottleneck.
4. I refactored the code so that Logger is holding an Arc instead of Weak (draft code ), so there is no longer the need for upgrading to Arc in hotpath. With this change, the throughput shot to ~250M/sec (in line with what was seen with using tracing+no-op subscriber alone).

The weak ref to provider was introduced for Tracing (and then followed for Logging), in this PR. Using Arc does mean that the Provider won't be dropped and shutdown won't be signaled until the last Logger is dropped, but that seems okay to me. In the case of Logging, Logger's are held only by the appenders (tokio-tracing subscribers etc), which, when dropped, will drop their Logger as well, allowing provider to be dropped....
I do not know if this has any further implications, especially for Tracer/Span case.

The (perf) issue is applicable to Span as well as this upgrade occurs (I think) twice - when span begins and when span ends...

Opening this issue to get feedback on this from experts and to check if this draft code is a reasonable direction to further explore.

[cijothomas]

@frigus02 Tagging you as you mentioned something along this line in the original, so want to see if they are still applicable..

[TommyCpp]

I think for Tracer it's a little bit easier to leak it into some blocking tasks and blocks the TracerProvider to drop if we switch to Arc

[djc]

@shaun-cox this seems like it might be of interest to you.

[cijothomas]

@shaun-cox this seems like it might be of interest to you.

Yes!! I did consult (offline) @shaun-cox and @lalitb a lot to narrow down the bottleneck to this point and also for the potential fix!

[cijothomas]

I think for Tracer it's a little bit easier to leak it into some blocking tasks and blocks the TracerProvider to drop if we switch to Arc

What is the implication of that? i.e What if TracerProvider is not dropped? Is the impact limited to losing those spans/metrics still in-memory? Or something more severe like apps never exiting etc.?

Also, is that something which users can resolve by ensuring they call shutdown themselves at the app-end?
Similar to how CPP : https://github.com/open-telemetry/opentelemetry-cpp/blob/main/examples/logs_simple/main.cc#L77-L78
and other languages are doing.

[lalitb]

Also, is that something which users can resolve by ensuring they call shutdown themselves at the app-end?

In current design, shutdown_tracer_provider method removes the reference of the currently active TracerProvider from the global singleton, which in-turn causes the destructor/drop to be called for this removed TracerProvider instance, which further shutdowns all the processors. With the change to Arc, we can add a new TracerProvider::Shutdown() method, and explicitly invoke it from within shutdown_tracer_provider . This new method will invoke shutdown on all processors, and so ensure that all the existing events/spans are flushed. And no new spans can be exported with processors in shutdown state.

I think for Tracer it's a little bit easier to leak it into some blocking tasks and blocks the TracerProvider to drop if we switch to Arc

In otel-cpp, TracerProvider maintains the list of all the created Tracers, so also controls it's lifetime. But I think this is pure design choice. In Rust, we can let TracerProvider instance remain active in shutdown state.

[bIgBV]

I can take a look at this.

[bIgBV]

After talking to @cijothomas and doing some of my own digging, it looks like LoggerProvider was modeled off of the TracerProvider.

#229 was the PR which introduced using Weak references from the Tracer to the TracerProvider so that the object could be dropped when the pipeline was shutting down. This pattern was then brought into the `LoggerProvider.

I don't see why we cannot use the Arc directly in both cases as we cans still use the existing shutdown mechanism without paying the cost of the upgrade call. I can update the branch with @cijothomas 's draft code and have a PR open.

[cijothomas]

Thanks! Could you open a PR with the proposed changes for logs first, and then we can extend it to Traces. The gains would be more relevant for Spans as this bottleneck is faced twice - start, end of span.

[hdost]

This weak -> Arc upgrade seems to be the bottleneck.

I am not sure we should be upgrading the Weak to an Arc in the hot path, but instead we might want to look at making the reference Weak in the hot path also.

[cijothomas]

Closing this issue for Logs. Will open a separate one for doing similar change for Traces.