Flush fix for SimpleLogProcessor #1308

cijothomas · 2023-10-19T14:40:10Z

SimpleLogProcessor's force_flush was incorrectly implemented as it did not do anything assuming there was nothing to flush. But the SimpleLogProcessor uses a queue with pub-sub mechanism to operate, so flush is not a no-op. This is handled correctly for SimpleSpanProcessor.

Instead of borrowing the approach from SimpleSpanProcessor, I have refactored the SimpleLogProcessor to use no queue and instead use a simple Mutex protected exporter/shutdown. I feel this is sufficient (and want to port this to SimpleSpanProcessor as well), but would like to get feedback on the approach - was there some scenario which prompted the queue/pub-sub for SimpleProcessors? Or this approach is sufficient?

There should not be any perf concerns as SimpleProcessors are used for learning/dev scenarios, and not for production. (Except when you are exporting to operating system native tracing like etw, user_events, but for them we have written RentrantProcessor separately.)

~~Note: I temporarily added some extra dependencies to test this out. If the direction is okay, I'll do a cleanup and modify the tests to not rely on tracing and friends.~~

cijothomas · 2023-10-19T14:41:21Z

The approach used in #1305 was used here as well. Its proving very useful to catch issues quickly, so irrespective of the actual fix, expect a bunch of new tests based on InMemoryLogExporter !

cijothomas · 2023-10-19T14:48:04Z

If this approach is good enough, that can remove the "crossbeam-channel = { version = "0.5", optional = true }" dependency from sdk completely as well?

codecov · 2023-10-19T15:01:39Z

Codecov Report

Attention: 4 lines in your changes are missing coverage. Please review.

Files	Coverage Δ
opentelemetry-sdk/src/logs/mod.rs	`100.0% <100.0%> (ø)`
opentelemetry-sdk/src/logs/log_processor.rs	`10.3% <73.3%> (+10.3%)`	⬆️

... and 9 files with indirect coverage changes

📢 Thoughts on this report? Let us know!

lalitb · 2023-10-19T16:45:45Z

Thanks for picking this up, and the InMemoryExporter tests :) So there are two options here

Option 1: Keep the existing queue based approach, and fix the SimpleLogProcessor::force_flush to process the queue (as done for spans). Which mean tokio::log!() -> Logger::emit() -> LogProcessor::emit() will return immediately after writing to queue, and a separate background thread will process the queue. No locks, and lags in application thread. The queue is unbounded, which means it can continue to grow if the input throughput exceeds the processing capacity. But then, SimpleLogProcessor is not for production use.

Option 2: The approach in this PR to do a export from application thread, and so a mutex lock is required to ensure that Exporter::export() is not called concurrently from multiple application threads. Simple approach, and without external dependency on crossbeam-channel.

While most of the language implementation (probably all) go with Option 2, I don't have strong opinion against Option 1 if we address the flushing issue. Nothing wrong with the performance gain even for non-production usage :)

cijothomas · 2023-10-19T18:07:50Z

Thanks for picking this up, and the InMemoryExporter tests :) So there are two options here

Option 1: Keep the existing queue based approach, and fix the SimpleLogProcessor::force_flush to process the queue (as done for spans). Which mean tokio::log!() -> Logger::emit() -> LogProcessor::emit() will return immediately after writing to queue, and a separate background thread will process the queue. No locks, and lags in application thread. The queue is unbounded, which means it can continue to grow if the input throughput exceeds the processing capacity. But then, SimpleLogProcessor is not for production use.

Option 2: The approach in this PR to do a export from application thread, and so a mutex lock is required to ensure that Exporter::export() is not called concurrently from multiple application threads. Simple approach, and without external dependency on crossbeam-channel.

While most of the language implementation (probably all) go with Option 2, I don't have strong opinion against Option 1 if we address the flushing issue. Nothing wrong with the performance gain even for non-production usage :)

I want to use Option 2 only, unless there is a strong reason not to.

It keeps the code a lot simpler, and reduces dependencies.
Is aligned with the spirit of SimpleProcessors original spec intent.
If someone really wants the user thread to return quickly, but does not want to pay for the buffer either, then they can use BatchProcessor with capacity=1. (Not a valid scenario in my opinion!)

lalitb · 2023-10-19T19:01:32Z

If someone really wants the user thread to return quickly, but does not want to pay for the buffer either, then they can use BatchProcessor with capacity=1. (Not a valid scenario in my opinion!)

that's a good point. Good to get feedback on the reason behind original implementation :)

TommyCpp · 2023-10-23T05:37:02Z

Pub-sub based approach first introduced in #502 to address the performance issue of simple span processors. One thing worth noting is currently users who don't use async runtime in Rust cannot use BatchSpanProcessor so there were some argument to keep the SimpleSpanProcessor relatively performant.

shaun-cox · 2023-10-20T15:07:40Z

opentelemetry-sdk/src/logs/log_processor.rs

@@ -42,62 +42,32 @@ pub trait LogProcessor: Send + Sync + Debug {
 /// emitted. If you find this limiting, consider the batch processor instead.
 #[derive(Debug)]
 pub struct SimpleLogProcessor {
-    sender: crossbeam_channel::Sender<Option<LogData>>,
-    shutdown: crossbeam_channel::Receiver<()>,
+    exporter: Mutex<Box<dyn LogExporter>>,


Why does this need to be wrapped in a Mutex? It seems a processor owns its exporter and the methods to call on it are &mut self, so who is thing shared with that requires the Mutex?

Can I table this, and come back to this after this PR?

cijothomas · 2023-10-23T21:18:37Z

Pub-sub based approach first introduced in #502 to address the performance issue of simple span processors. One thing worth noting is currently users who don't use async runtime in Rust cannot use BatchSpanProcessor so there were some argument to keep the SimpleSpanProcessor relatively performant.

Thanks for sharing the background!
#502 does not seem to addressing any end user needs. What I understand is that, that PR addresses the "must not block" part from the spec, just for spec compliance purposes.
Also, the spec does not require SimpleSpanProcessor to not-block/high-perf. It only says the API/SDK should not block, and leaves out the SpanProcessors.

"Some downstream SpanProcessors and subsequent SpanExporters called from this operation may be used for testing, proof-of-concept ideas, or debugging and may not be designed for production use themselves. They are not in the scope of this requirement and recommendation."

@jtescher Can you comment on any actual use cases on having a performant simple span processor? Or we did that just for spec compliance? If that is the case, would you be okay to revert that change, as spec does not require that from us.

cijothomas · 2023-10-23T21:20:05Z

One thing worth noting is currently users who don't use async runtime in Rust cannot use BatchSpanProcessor so there were some argument to keep the SimpleSpanProcessor relatively performant.

This is something we need to address separately, anyways, do you agree? i.e We want to support users who do not use aync runtimes. (not just traces, but metrics too)

hdost · 2023-10-24T03:47:24Z

Thanks for sharing the background!
#502 does not seem to addressing any end user needs.

Not sure I would assume that.

cijothomas · 2023-10-24T04:26:46Z

Thanks for sharing the background!
#502 does not seem to addressing any end user needs.

Not sure I would assume that.

Can you share some user needs around SimpleProcessor? The linked PR talks mostly about spec compliance...

opentelemetry-sdk/src/logs/log_processor.rs

cijothomas · 2023-11-08T19:35:23Z

@jtescher Could you comment on #1308 (comment), when you get a chance ? I am mostly looking to ensure we agree (or disagree) on the direction, which is:

Keep SimpleLog/SpanProcessors "simple", and documented to end-users that this is not meant for Production scenarios.
a. As a bonus, crossbeam-channel dependency can be removed from sdk.
Users without an async runtime cannot use BatchProcessor (they cannot use Metrics Sdk either), but this is an issue we want to address irrespective of this PR!

In the absence of any real user needs for high-performing SimpleProcessor, we should strive to keep it simple! Happy to change my views, if there are actual use cases I am not aware of!

jtescher · 2023-11-08T20:59:01Z

Yeah I don't think it needs to be as performant 👍 . The simple case should be for scripts / jobs / other sync activities which shouldn't produce a volume of spans where it is impactful.

cijothomas · 2023-11-10T19:19:34Z

@TommyCpp @jtescher Please re-review. I have fixed handling the lock poisoning in latest commits.

The question from @shaun-cox about the very need of Mutex - Let me get back to it after this PR.

This PR now makes it easy to write semi-integration tests for Logging using in-memory-exporter, and I want to add more of that.

cijothomas · 2023-11-10T23:24:54Z

@hdost Can you re-review as well as you have previously reviewed?

TommyCpp · 2023-11-12T18:39:44Z

@hdost Can you re-review as well as you have previously reviewed?

cc @hdost for final review

cijothomas added 2 commits October 19, 2023 07:32

Fix Flush for Log Processor and more..

f9bcbef

fmt fix

23732f6

cijothomas requested a review from a team October 19, 2023 14:40

TommyCpp self-assigned this Oct 20, 2023

shaun-cox approved these changes Oct 23, 2023

View reviewed changes

TommyCpp removed their assignment Oct 24, 2023

TommyCpp reviewed Oct 24, 2023

View reviewed changes

opentelemetry-sdk/src/logs/log_processor.rs Outdated Show resolved Hide resolved

cijothomas added 4 commits November 10, 2023 08:58

Merge branch 'main' into cijothomas/log-simpleprocessorfix

018b538

fix unit test and handle lock poison

b7afe6b

fmt

21a3e1b

handle lock poison for shutdown

862adcf

jtescher approved these changes Nov 10, 2023

View reviewed changes

TommyCpp approved these changes Nov 12, 2023

View reviewed changes

TommyCpp assigned hdost Nov 12, 2023

hdost approved these changes Nov 12, 2023

View reviewed changes

hdost merged commit cb2d127 into open-telemetry:main Nov 12, 2023
14 checks passed

cijothomas deleted the cijothomas/log-simpleprocessorfix branch November 13, 2023 19:47

cijothomas mentioned this pull request Nov 28, 2023

[Feature]: SimpleSpanProcessor to be consistent with SimpleLogRecordProcessor #1409

Closed

cijothomas mentioned this pull request Dec 12, 2023

[Feature]: Support Metrics, BatchProcessor without async runtime #1437

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flush fix for SimpleLogProcessor #1308

Flush fix for SimpleLogProcessor #1308

cijothomas commented Oct 19, 2023 •

edited

Loading

cijothomas commented Oct 19, 2023

cijothomas commented Oct 19, 2023

codecov bot commented Oct 19, 2023 •

edited

Loading

lalitb commented Oct 19, 2023 •

edited

Loading

cijothomas commented Oct 19, 2023

lalitb commented Oct 19, 2023

TommyCpp commented Oct 23, 2023

shaun-cox Oct 20, 2023

cijothomas Nov 10, 2023

cijothomas commented Oct 23, 2023

cijothomas commented Oct 23, 2023

hdost commented Oct 24, 2023

cijothomas commented Oct 24, 2023

cijothomas commented Nov 8, 2023

jtescher commented Nov 8, 2023

cijothomas commented Nov 10, 2023

cijothomas commented Nov 10, 2023

TommyCpp commented Nov 12, 2023

Flush fix for SimpleLogProcessor #1308

Flush fix for SimpleLogProcessor #1308

Conversation

cijothomas commented Oct 19, 2023 • edited Loading

cijothomas commented Oct 19, 2023

cijothomas commented Oct 19, 2023

codecov bot commented Oct 19, 2023 • edited Loading

Codecov Report

lalitb commented Oct 19, 2023 • edited Loading

cijothomas commented Oct 19, 2023

lalitb commented Oct 19, 2023

TommyCpp commented Oct 23, 2023

shaun-cox Oct 20, 2023

Choose a reason for hiding this comment

cijothomas Nov 10, 2023

Choose a reason for hiding this comment

cijothomas commented Oct 23, 2023

cijothomas commented Oct 23, 2023

hdost commented Oct 24, 2023

cijothomas commented Oct 24, 2023

cijothomas commented Nov 8, 2023

jtescher commented Nov 8, 2023

cijothomas commented Nov 10, 2023

cijothomas commented Nov 10, 2023

TommyCpp commented Nov 12, 2023

cijothomas commented Oct 19, 2023 •

edited

Loading

codecov bot commented Oct 19, 2023 •

edited

Loading

lalitb commented Oct 19, 2023 •

edited

Loading