HHVM watchman deadlock GDB debugging session

debugging.md

Summary

• The thread that holds s_sharedDataMutex is calling WatchmanConnection::close()
• WatchmanConnection::close() needs to run something in the EventBaseThread
• The EventBaseThread is in a callback that's trying to get s_sharedDataMutex
• This is a deadlock.

Event Base Thread

[Current thread is 210 (Thread 0x7fb97e16b700 (LWP 510964))]
#0  __lll_lock_wait (futex=futex@entry=0x110786a0 <HPHP::(anonymous namespace)::s_sharedDataMutex>, private=0) at lowlevellock.c:52
#1  0x00007fbe83055c22 in __GI___pthread_mutex_lock (mutex=0x110786a0 <HPHP::(anonymous namespace)::s_sharedDataMutex>) at ../nptl/pthread_mutex_lock.c:80
#2  0x000000000a36359d in __gthread_mutex_lock (__mutex=0x110786a0 <HPHP::(anonymous namespace)::s_sharedDataMutex>) at third-party-buck/platform009/build/libgcc/include/c++/trunk/x86_64-facebook-linux/bits/gthr-default.h:749
#3  std::mutex::lock (this=<optimized out>) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/std_mutex.h:100
#4  std::lock_guard<std::mutex>::lock_guard (this=<optimized out>, __m=...) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/std_mutex.h:159
#5  HPHP::(anonymous namespace)::WatchmanThreadEventBase::add(folly::Function<void ()>)::{lambda()#1}::operator()() (this=0x7fbc35356940) at hphp/runtime/ext/watchman/ext_watchman.cpp:131

Thread holding s_sharedDataMutex

(gdb) p s_sharedDataMutex
$5 = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 2, __count = 0, __owner = 431100, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}},
      __size = "\002\000\000\000\000\000\000\000\374\223\006\000\001", '\000' <repeats 26 times>, __align = 2}}, <No data fields>}
(gdb) t find 431100
Thread 190 has target id 'Thread 0x7fbc609e0700 (LWP 431100)'

[Current thread is 190 (Thread 0x7fbc609e0700 (LWP 431100))]
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000000000eb9bd0a in folly::detail::(anonymous namespace)::nativeFutexWaitImpl (addr=<optimized out>, expected=<optimized out>, absSystemTime=<optimized out>, absSteadyTime=<optimized out>, waitMask=<optimized out>) at folly/detail/Futex.cpp:124
#2  folly::detail::futexWaitImpl (futex=0x89, expected=2196904233, absSystemTime=<optimized out>, absSteadyTime=<optimized out>, waitMask=<optimized out>) at folly/detail/Futex.cpp:250
#3  0x0000000006d82423 in folly::detail::futexWaitUntil<std::atomic<unsigned int>, std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (futex=0x7fbc609d37b0, expected=2, deadline=..., waitMask=4294967295)
    at folly/detail/Futex-inl.h:119
#4  folly::detail::MemoryIdler::futexWaitUntil<std::atomic<unsigned int>, std::chrono::time_point<std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > >, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (
    fut=..., expected=2, deadline=..., waitMask=4294967295, idleTimeout=..., stackToRetain=1024, timeoutVariationFrac=0.5) at folly/detail/MemoryIdler.h:164
#5  folly::Baton<true, std::atomic>::tryWaitSlow<std::chrono::_V2::steady_clock, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (this=0x7fbc609d37b0, deadline=..., opt=...) at folly/synchronization/Baton.h:305
#6  0x000000000e9fe8d4 in folly::Baton<true, std::atomic>::wait (this=0x7fbc609d37b0, opt=...) at folly/synchronization/Baton.h:177
#7  folly::EventBase::runInEventBaseThreadAndWait(folly::Function<void ()>) (this=0x7fbce1d67990, fn=...) at folly/io/async/EventBase.cpp:662
#8  0x000000000e9fea0f in folly::EventBase::runImmediatelyOrRunInEventBaseThreadAndWait(folly::Function<void ()>) (this=0x7fbce1d67990, fn=...) at folly/io/async/EventBase.cpp:669
#9  0x000000000e5521f1 in watchman::WatchmanConnection::close (this=0x7fbc353d2f90) at watchman/cppclient/WatchmanConnection.cpp:134
#10 0x000000000e551f83 in watchman::WatchmanConnection::~WatchmanConnection (this=0x7fbc353d2f90) at watchman/cppclient/WatchmanConnection.cpp:56
#11 0x0000000006d7ea6f in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release_slow_last_use (this=0x7fbc353d2f80) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/shared_ptr_base.h:191
#12 0x000000000a37371a in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release (this=0x7fb9d3792dc0) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/shared_ptr_base.h:173
#13 std::__shared_count<(__gnu_cxx::_Lock_policy)2>::~__shared_count (this=<optimized out>) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/shared_ptr_base.h:788
#14 std::__shared_ptr<watchman::WatchmanClient, (__gnu_cxx::_Lock_policy)2>::~__shared_ptr (this=<optimized out>) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/shared_ptr_base.h:1227
#15 std::__shared_ptr<watchman::WatchmanClient, (__gnu_cxx::_Lock_policy)2>::reset (this=<optimized out>) at third-party-buck/platform009/build/libgcc/include/c++/trunk/bits/shared_ptr_base.h:1345
#16 HPHP::(anonymous namespace)::ActiveSubscription::checkConnection (this=<optimized out>) at hphp/runtime/ext/watchman/ext_watchman.cpp:402
#17 HPHP::(anonymous namespace)::ActiveSubscription::unsubscribe[abi:cxx11]() (this=0x7fbcd8232428) at hphp/runtime/ext/watchman/ext_watchman.cpp:262
#18 HPHP::(anonymous namespace)::watchman_unsubscribe_impl (name=...) at hphp/runtime/ext/watchman/ext_watchman.cpp:569
#19 0x000000000a3618a3 in HPHP::(anonymous namespace)::f_HH_watchman_unsubscribe (_name=...) at hphp/runtime/ext/watchman/ext_watchman.cpp:794