Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[SDK] BatchSpanProcessor::ForceFlush appears to be hanging forever #2574

Closed
lidavidm opened this issue Mar 4, 2024 · 4 comments · Fixed by #2584
Closed

[SDK] BatchSpanProcessor::ForceFlush appears to be hanging forever #2574

lidavidm opened this issue Mar 4, 2024 · 4 comments · Fixed by #2584
Assignees
Labels
bug Something isn't working triage/accepted Indicates an issue or PR is ready to be actively worked on.

Comments

@lidavidm
Copy link
Contributor

lidavidm commented Mar 4, 2024

Describe your environment
Platform: Linux/x86_64
Build system: CMake
Package manager: conda/conda-forge
OpenTelemetry version: 1.14.1

Steps to reproduce
Unfortunately, this is entwined into a large proprietary application and I've not been able to extricate it. We are using the OTLP exporter, BatchSpanProcessor, and we are calling Flush periodically with a timeout.

What is the expected behavior?
ForceFlush with a timeout should reliably complete within the timeout (roughly)

What is the actual behavior?
ForceFlush appears to get stuck inside the spinlock:

#0  0x00007f52a6c49f17 in __GI_sched_yield () at ../sysdeps/unix/syscall-template.S:120
#1  0x00007f52a84ce4ee in opentelemetry::v1::sdk::trace::BatchSpanProcessor::ForceFlush(std::chrono::duration<long, std::ratio<1l, 1000000l> >) () from /home/lidavidm/miniforge3/envs/dev/bin/../lib/libopentelemetry_trace.so

or

   0x00007f52a84ce49e <+334>:	jne    0x7f52a84ce4bd <_ZN13opentelemetry2v13sdk5trace18BatchSpanProcessor10ForceFlushENSt6chrono8durationIlSt5ratioILl1ELl1000000EEEE+365>
   0x00007f52a84ce4a0 <+336>:	pause
=> 0x00007f52a84ce4a2 <+338>:	mov    %ebx,%eax
   0x00007f52a84ce4a4 <+340>:	and    $0x7f,%eax
   0x00007f52a84ce4a7 <+343>:	cmp    $0x7f,%eax

These traces appear to me to correspond with the spinlock portion. It appears to me that the spinlock portion does not respect the timeout:

// If it will be already signaled, we must wait util notified.
// We use a spin lock here
if (false ==
synchronization_data_->is_force_flush_pending.exchange(false, std::memory_order_acq_rel))
{
for (int retry_waiting_times = 0;
false == synchronization_data_->is_force_flush_notified.load(std::memory_order_acquire);
++retry_waiting_times)
{
opentelemetry::common::SpinLockMutex::fast_yield();
if ((retry_waiting_times & 127) == 127)
{
std::this_thread::yield();
}
}
}
synchronization_data_->is_force_flush_notified.store(false, std::memory_order_release);

Additional context
We think this only occurred once we upgraded from 1.13.0 to 1.14.1. Note that we did not used to have a timeout, since we did not feel a need to. When we upgraded, we noticed it was getting stuck exporting, and added the timeout to try to avoid this (and as general good practice), but it seems there's some deeper issue as to why the export seems to never complete.

I did set a breakpoint on the actual Export method and it does appear to be called regularly, but the main thread that is blocking in ForceFlush isn't getting unblocked.

@lidavidm lidavidm added the bug Something isn't working label Mar 4, 2024
@github-actions github-actions bot added the needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. label Mar 4, 2024
@owent
Copy link
Member

owent commented Mar 5, 2024

Thanks, this may happen when more than one threads call ForceFlush.

@owent owent self-assigned this Mar 5, 2024
@lidavidm
Copy link
Contributor Author

lidavidm commented Mar 5, 2024

Thanks for the quick diagnosis. I can say our problem definitely persists in 1.13.0 (so it's just coincidence that we started noticing after the 1.14.1 upgrade) and a lock does appear to fix the problem.

@owent
Copy link
Member

owent commented Mar 6, 2024

Thanks. There should be only one thread calling this function internally, it's still a problem when users call it in another thread.
I was thinking about a lockless way to solve this problem. Or the critical section may be a little long to make more conflict.

@marcalff marcalff added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Mar 6, 2024
Copy link

github-actions bot commented May 8, 2024

This issue was marked as stale due to lack of activity.

@github-actions github-actions bot added the Stale label May 8, 2024
@marcalff marcalff changed the title BatchSpanProcessor::ForceFlush appears to be hanging forever [SDK] BatchSpanProcessor::ForceFlush appears to be hanging forever May 23, 2024
@github-actions github-actions bot removed the Stale label May 26, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants