ivoanjo
commented
1 year ago Thanks @shanet for the detailed breakdown, and sorry that you're running into this issue!
Indeed it looks like the library_free from the ffi gem seems to be running and getting stuck somewhere in the glibc code.
Looking at __thread_gscope_wait it seems to grab the dl_stack_cache_lock before getting itself stuck on line 51 which is the same lock that __nptl_deallocate_stack needs so that seems to point at why the other threads are stuck as well.
To be honest, I'm not entirely sure that glibc is doing at this point, but before going deeper on glibc, there's a few things I'd suggest we look into at the Ruby level.
-
You mentioned bisecting the issue to 26ac04c06f87918eae773692dd428491bf8a11a4. That's... surprising since that change affected the new "CPU Profiling 2.0" that in 1.3.0 could not be turned on at all. (Enabling it happened in #2209, which was shipped in 1.4.0, and it was very experimental and not recommended).
But I suggest trying to remove the profiler from the equation -- can you set
DD_PROFILING_NO_EXTENSION=truewhile installing ddtrace? This stops the native extension from being built at all (thus disabling the profiler), and so we can check if the issue happens without it.You should see this in your logs after installing the gem with that option:
W, [2023-07-31T20:51:19.507276 #570693] WARN -- ddtrace: [ddtrace] Profiling was requested but is not supported, profiling disabled: Your ddtrace installation is missing support for the Continuous Profiler because the
DD_PROFILING_NO_EXTENSIONenvironment variable is/was set totrueduring installation. If you needed to use this, please tell us why on https://github.com/DataDog/dd-trace-rb/issues/new so we can fix it :)Note that this setting is applied at gem installation time, so if the gem is already installed, it won't do anything.
-
Currently,
ffiis an indirect dependency of ddtrace (via libddwaf). But libddwaf only gets enalbed if you enable the appsec functionality, which I don't see in your configuration. This left me really curious -- what library is getting garbage collected by ffi?Since you're able to attach to the process, can you try to call
dlinfoon the handle passed tolibrary_free(reference) so we can figure out which library is being garbage collected?I hope this will point us at either libddwaf, or at another gem that seems to, together with ddtrace, cause this incompatibility.
If needed, as an alternative, I can prepare a branch of
ffito log this information without needing gdb.
I hope that either one of these may provide clues to the next steps. Thanks again for the patience on this issue.
shanet
ngan
CedricCouton
casperisfine
beauraF
byroot
A few weeks ago we updated ddtrace in our application from version 0.53 to 1,11.1. Shortly after deploying this to production we noticed that some of our Resque workers would hang after they processed a job resulting in the worker to stop processing further jobs and causing a backups in the Resque queues. We identified the ddtrace upgrade as the source of this problem and reverted back to version 0.53 to resolve it for the time being.
Since then I've been working to identify what the root cause of this is. Here's what I know so far:
26ac04c06f87918eae773692dd428491bf8a11a4. This appears to add tracking of CPU-time for profiling.Threads as displayed by GDB:
GDB backtrace of all threads:
Using GDB I also got a Ruby backtrace of the main thread. The other threads were marked as killed already by Ruby and did not have a control frame pointer anymore to read a backtrace from:
The one Datadog thread's full name is
Datadog::Tracing::Workers::AsyncTransportper:I initially though the problem was with the
AsyncTransportclass, but after looking at the concurrency logic there I was unable to find any problems with it. Futhermore, returning to the backtraces above, the problem seems to lie elsewhere. Ruby has all threads other than the main thread marked as killed already so it would appear they joined the main thread cleanly.The main thread on the other hand is attempting to unload a library when it becomes stuck per the backtrace. Namely, it is stopping the fork (
rb_f_forkandruby_stop) then cleaning up withruby_cleanupandlibrary_freebefore finally becoming deadlocked atfutex_wait.This backtrace combined with the git bisecting of the ddtrace gem leads me to believe there is an issue with something in the native extension preventing Ruby from continuing with its cleanup of the fork resulting in a hung Resque worker process. This only appears to happen at high load with sufficient number of Resque workers. It's also worth noting that with 10 Resque workers, I never saw them all become stuck. At most 5-6 of them would become stuck over the timespan of ~12 hours. I assume this had to do with why multiple workers were needed to replicate the problem in the first place.
There's one other notable situation that happened too. I've inspected many of these deadlocked processes via GDB while debugging this and they all had the same backtrace. However, in a single case, which I never saw a second time, the backtrace was different with it being stuck on a
getaddrinfocall. I don't know if this is relevant since it ultimately still ends stuck on afutex_waitcall, but it stood out to me enough to save a copy of the backtrace when I saw it:Our environment is as follows:
Our ddtrace initialization config:
It's also worth noting that I was only able to replicate this behavior on AWS ECS. I tried reproducing it on a local Linux desktop (Arch rather than Ubuntu) and even when running 10 Resque workers could not replicate the issue. I don't know if that makes it environment specific or, since it only happens in high-load, that the considerably higher hardware capabilities of my desktop compared to the limited AWS containers prevented it from occurring.
I've also reviewed https://github.com/DataDog/dd-trace-rb/issues/466 which seems like a similar issue, but appears to be unrelated.
Overall, I've spent nearly two weeks getting to this point hoping to identify/solve the issue, but at least to obtain enough information to intelligently open a bug report. At this point I'm not sure what else to debug and am hoping for advice on what might be causing these deadlocks and how to further diagnose the problem. Thank you for reviewing.