progress stuck due to deadlock

[Besroy]

Environment

  Cluster: 908
  Namespace: nuobject2sh-dev
  Pod: sm-long-running4-1010-6db4d944f-rzrbj
  HomeObject Version: homeobject/3.0.6@oss/main
  HomeStore Version: homestore/7.0.0@oss/master

Description

One SM stuck and cannot process more requests during SH test, and the reason seems to be a deadlock issue between _pg_lock (HomeObject PG lock) and m_meta_mtx (MetaBlkService mutex).

More details in SH isssue records Issue75

Threads

Thread 73 (LWP 99) - GC Worker Thread

Thread 73 (Thread 0x7c6bddffb680 (LWP 99)):
 #0  0x00007c6d18c1ef70 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
 #1  0x00007c6d18c26101 in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libc.so.6
 #2  0x00005ced90b217a9 in __gthread_mutex_lock (__mutex=0x5ceda0018ce0)
 #3  std::mutex::lock (this=0x5ceda0018ce0)
 #4  std::lock_guard<std::mutex>::lock_guard (__m=..., this=<synthetic pointer>)
 #5  homestore::MetaBlkService::update_sub_sb (this=0x5ceda0018cd0, context_data=0x5ceda05776f0 "", sz=1751, cookie=0x5ceda032ac00) 
     at /home/ubuntu/.conan2/p/b/homes10e04144d6517/b/src/lib/meta/meta_blk_service.cpp:806
 #6  0x00005ced9096cffe in homeobject::HSHomeObject::update_pg_meta_after_gc (this=0x5ced9ffd0690, pg_id=<optimized out>, move_from_chunk=<optimized out>, move_to_chunk=<optimized out>, task_id=<optimized out>) 
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/hs_pg_manager.cpp:1010
 #7  0x00005ced90a6dcef in homeobject::GCManager::pdev_gc_actor::replace_blob_index (this=this@entry=0x5ceda0693100, move_from_chunk=<optimized out>, move_from_chunk@entry=224, move_to_chunk=<optimized out>, move_to_chunk@entry=187, 
 valid_blob_indexes=std::vector of length 154, capacity 256 = {...}, task_id=<optimized out>, task_id@entry=496)
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/gc_manager.cpp:582
 #8  0x00005ced90a6e609 in homeobject::GCManager::pdev_gc_actor::process_after_gc_metablk_persisted (this=this@entry=0x5ceda0693100, gc_task_sb=..., valid_blob_indexes=std::vector of length 154, capacity 256 = {...}, 
 task_id=task_id@entry=496)
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/gc_manager.cpp:1184
 #9  0x00005ced90a788b8 in homeobject::GCManager::pdev_gc_actor::process_gc_task (this=0x5ceda0693100, move_from_chunk=<optimized out>, priority=<optimized out>, task=..., task_id=<optimized out>) 
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/gc_manager.cpp:1148
 #10 0x00005ced90a7981f in operator() (__closure=0x7c6bddfecf40) 
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/gc_manager.cpp:346

Thread 25 (LWP 23) - GC Scanner Thread

holds this mutex:

  (gdb) p *(pthread_mutex_t*)0x5ceda0018ce0
  $1 = {__data = {__lock = 2, __count = 0, __owner = 23, __nusers = 1, ...}

trace:

 Thread 25 (Thread 0x7c6d15825680 (LWP 23)):
#0  0x00007c6d18c1ec37 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
 #1  0x00007c6d18c2933b in pthread_rwlock_wrlock () from /lib/x86_64-linux-gnu/libc.so.6
 #2  0x00005ced90962217 in std::__glibcxx_rwlock_wrlock (__rwlock=0x5ced9ffd0710)
 #3  std::__shared_mutex_pthread::lock (this=0x5ced9ffd0710)
 #4  std::shared_mutex::lock (this=0x5ced9ffd0710)
 #5  std::scoped_lock<std::shared_mutex>::scoped_lock (__m=..., this=<synthetic pointer>)
 #6  homeobject::HSHomeObject::can_chunks_in_pg_be_gc (this=0x5ced9ffd0690, pg_id=<optimized out>, pg_id@entry=0) 
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/hs_pg_manager.cpp:517
 #7  0x00005ced90a6acf1 in homeobject::GCManager::pdev_gc_actor::add_gc_task (this=0x5ceda0693100, priority=priority@entry=1 '\001', move_from_chunk=227) 
     at /home/ubuntu/HomeObject/src/lib/homestore_backend/gc_manager.cpp:325
 #8  0x00005ced90a7a31c in homeobject::GCManager::scan_chunks_for_gc (this=0x5ceda0582840)
 #9  0x00005ced90dbfd17 in std::function<void (void*)>::operator()(void*) const
 #10 iomgr::timer_epoll::on_timer_armed (this=0x5ced9ffe0740, iodev=<optimized out>)
 #11 0x00005ced90dbff57 in iomgr::timer_epoll::on_timer_fd_notification (iodev=iodev@entry=0x5ced9ff30af0)
 #12 0x00005ced90dfc728 in iomgr::IOReactorEPoll::listen (this=0x7c6cf8000980)

[JacksonYao287]

this is not a gc related issue, it is an iomgr issue, I will put the RCA here soon

[JacksonYao287]

T1: in sync_io_fiber of thread1 (worker reactor) try to update meta_blk , it holds the m_meta_lock and do sync_write , and finally yield to main_fiber without releasing m_meta_lock .
T2: gc thread hold the pg_lock and try to update pg metablk, then it waits for m_meta_lock , which is now hold by thread1(worker reactor).
T3: main_fiber of thread1 (worker reactor) starts to run(yield by sync_io_fiber), it calls the timer callback, which will try to acquire the pg_lock . since pg_lock is now hold by the gc thread, the whole reactor/thread will be blocked and dead lock happens, and will not yield to sync_io_fiber again.

[Besroy]

Found another stuck SM

While writing 100,000 blobs to 1 PG (blob_size=4M, replica_count=3), the SM sm-long-running2-1011-94cd44bb7-cftqc got stuck at end_of_append_batch while waiting for batch data to be written. When we dug into the stack traces, we found that many threads were in folly::nativeFutexWaitImpl status, and all IOReactor threads were in epoll_wait status. This might be the same issue, or it could be related to other components (like uring/reactor...). Currently, we don't have more clues or ideas about this stuck SM, so I will just comment here and wait for HO#364 to be merged to see if it can be reproduced. In the meantime, I will enable logmod iomgr:debug in env 1011 and try to reproduce it to gather more details.

Logs:
take one lsn as example, it didn't write data for more than 2 days

I have no name!@sm-long-running2-1011-94cd44bb7-cftqc:/logs/logs/latest$ grep 12737220540466466253 storage_mgr_log
[11/22/25 11:30:45.193] [storage_mgr] [debug] [66] [raft_repl_dev.cpp:934:on_push_data_received] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338] Data Channel: PushData received: time diff=2120 ms.
[11/22/25 11:30:45.193] [storage_mgr] [debug] [66] [hs_blob_manager.cpp:431:blob_put_get_blk_alloc_hints] [traceID=12737220540466466253,shardID=0x18,pg=0,shard=0x18,blob=4974] Picked p_chunk_id=269, reserved_blks=16384
[11/22/25 11:30:45.193] [storage_mgr] [debug] [66] [raft_repl_dev.cpp:1054:applier_create_req] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338]
[11/22/25 11:30:47.223] [storage_mgr] [trace] [31] [raft_state_machine.cpp:62:localize_journal_entry_prepare] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338] Raft Channel: Localizing Raft log_entry: server_id=389276869, term=1, journal_entry=[version=1.1, code=HS_DATA_LINKED, server_id=389276869, dsn=9644, header_size=48, key_size=8, value_size=8]
[11/22/25 11:30:47.223] [storage_mgr] [trace] [31] [raft_repl_dev.cpp:1028:applier_create_req] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338] Repl_key=[server=389276869, term=1, dsn=9644, hash=389267816, trace_id=12737220540466466253] already received
[11/22/25 11:30:47.224] [storage_mgr] [trace] [31] [common.cpp:176:set_lsn] [traceID=12737220540466466253] Setting lsn=9648 for request=repl_key=[server=389276869, term=1, dsn=9644, hash=389267816, trace_id=12737220540466466253], lsn=9648 state=[BLK_ALLOCATED | DATA_RECEIVED | ] m_headersize=48 m_keysize=8 is_proposer=false local_blkid=[[{blk#=212176 count=1025 chunk=269},] ] remote_blkid=[{blk#=212176 count=1025 chunk=269},]
[11/22/25 11:30:47.224] [storage_mgr] [trace] [31] [repl_log_store.cpp:23:append] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338] Raft Channel: Received append log entry rreq=[dsn=9644 term=1 lsn=9648 op=HS_DATA_LINKED local_blkid=[[{blk#=212176 count=1025 chunk=269},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | LOG_RECEIVED | ]]
[11/22/25 11:30:47.224] [storage_mgr] [trace] [31] [raft_state_machine.cpp:198:pre_commit_ext] [traceID=12737220540466466253] [rdev0:4f2a1bb5-ec69-417b-aed3-0d67c56be338] Precommit rreq=[dsn=9644 term=1 lsn=9648 op=HS_DATA_LINKED local_blkid=[[{blk#=212176 count=1025 chunk=269},] ] state=[BLK_ALLOCATED | DATA_RECEIVED | LOG_RECEIVED | ]]

StackTrace
Kill SM by SIGABRT, then check stack trace, it is still waiting for write complete

Thread 13 (Thread 0x766da58f5680 (LWP 31)):
#0  0x0000766dada8728d in syscall () from /lib/x86_64-linux-gnu/libc.so.6
#1  0x000062ca5e104c4f in folly::detail::(anonymous namespace)::nativeFutexWaitImpl (waitMask=4294967295, absSteadyTime=0x0, absSystemTime=0x0, expected=4294967293, addr=0x766da58e66f8) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/detail/Futex.cpp:126
#2  folly::detail::futexWaitImpl (futex=futex@entry=0x766da58e66f8, expected=expected@entry=4294967293, absSystemTime=absSystemTime@entry=0x0, absSteadyTime=absSteadyTime@entry=0x0, waitMask=waitMask@entry=4294967295) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/detail/Futex.cpp:254
#3  0x000062ca5e127dae in folly::detail::futexWait<std::atomic<unsigned int> > (waitMask=4294967295, expected=4294967293, futex=0x766da58e66f8) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/detail/Futex-inl.h:94
#4  folly::detail::MemoryIdler::futexWait<std::atomic<unsigned int>, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (idleTimeout=..., stackToRetain=1024, timeoutVariationFrac=0.5, waitMask=4294967295, expected=4294967293, fut=std::atomic<unsigned int> = { 4294967293 }) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/detail/MemoryIdler.h:128
#5  folly::detail::MemoryIdler::futexWait<std::atomic<unsigned int>, std::chrono::duration<long, std::ratio<1l, 1000000000l> > > (timeoutVariationFrac=0.5, stackToRetain=1024, idleTimeout=..., waitMask=4294967295, expected=4294967293, fut=...) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/detail/MemoryIdler.h:106
#6  folly::fibers::Baton::waitThread (this=0x766da58e66f8) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/fibers/Baton.cpp:70
#7  0x000062ca5e12808e in folly::fibers::Baton::wait<folly::fibers::Baton::wait()::<lambda()> > (mainContextFunc=..., this=<optimized out>) at /home/jenkins/.conan2/p/b/folly8428752782aa2/b/src/folly/fibers/Baton-inl.h:54
#8  0x000062ca5de8791c in folly::futures::detail::waitImpl<folly::Future<folly::Unit>, folly::Unit> (f=...) at /home/jenkins/.conan2/p/follyfb4eadbee73db/p/include/folly/futures/Future-inl.h:2211
#9  0x000062ca5de99173 in folly::Future<folly::Unit>::wait() && (this=0x766da58e6800) at /home/jenkins/.conan2/p/follyfb4eadbee73db/p/include/folly/futures/Future-inl.h:2400
#10 homestore::ReplLogStore::end_of_append_batch (this=0x62ca9524ec70, start_lsn=9647, count=8) at /home/jenkins/.conan2/p/b/homes5238d0851bcd9/b/src/lib/replication/log_store/repl_log_store.cpp:73
#11 0x000062ca5dfe7be4 in nuraft::raft_server::handle_append_entries (this=this@entry=0x62ca9538c010, req=...) at /home/jenkins/.conan2/p/b/nuraf2fcd9e3e2ebc5/b/src/src/handle_append_entries.cxx:1026
#12 0x000062ca5e037982 in nuraft::raft_server::process_req (this=0x62ca9538c010, req=..., ext_params=...) at /home/jenkins/.conan2/p/b/nuraf2fcd9e3e2ebc5/b/src/src/raft_server.cxx:799
#13 0x000062ca5df777dc in nuraft::raft_server_handler::process_req (ext_params=..., req=..., srv=0x62ca9538c010) at /home/jenkins/.conan2/p/nurafd77d127f7dce8/p/include/libnuraft/raft_server_handler.hxx:42
#14 nuraft_mesg::proto_service::step (this=this@entry=0x62ca8c46de10, server=..., request=..., reply=..., metrics=std::shared_ptr<nuraft_mesg::group_metrics> (use count 6, weak count 0) = {...}) at /home/jenkins/.conan2/p/b/nuraf8996814cbc77a/b/src/proto/proto_service.cpp:92
#15 0x000062ca5df784b9 in operator() (__closure=__closure@entry=0x766da58e7370) at /home/jenkins/.conan2/p/b/nuraf8996814cbc77a/b/src/proto/proto_service.cpp:155
#16 0x000062ca5df78ab8 in boost::asio::detail::binder0<nuraft_mesg::proto_service::raftStep(sisl::AsyncRpcDataPtr<nuraft_mesg::Messaging, nuraft_mesg::RaftGroupMsg, nuraft_mesg::RaftGroupMsg>&)::<lambda()> >::operator() (this=0x766da58e7370) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/bind_handler.hpp:56
#17 boost::asio::detail::executor_op<boost::asio::detail::binder0<nuraft_mesg::proto_service::raftStep(sisl::AsyncRpcDataPtr<nuraft_mesg::Messaging, nuraft_mesg::RaftGroupMsg, nuraft_mesg::RaftGroupMsg>&)::<lambda()> >, std::allocator<void>, boost::asio::detail::scheduler_operation>::do_complete(void *, boost::asio::detail::scheduler_operation *, const boost::system::error_code &, std::size_t) (owner=0x62ca951a2b00, base=<optimized out>) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/executor_op.hpp:70
#18 0x000062ca5df7d615 in boost::asio::detail::scheduler_operation::complete (bytes_transferred=<optimized out>, ec=..., owner=0x62ca951a2b00, this=0x62ca99db4dc0) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/scheduler_operation.hpp:40
#19 boost::asio::detail::scheduler::do_run_one (this=this@entry=0x62ca951a2b00, lock=..., this_thread=..., ec=...) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/impl/scheduler.ipp:493
#20 0x000062ca5df74fa1 in boost::asio::detail::scheduler::run (this=0x62ca951a2b00, ec=...) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/impl/scheduler.ipp:210
#21 0x000062ca5df7dedd in boost::asio::thread_pool::thread_function::operator() (this=<optimized out>) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/impl/thread_pool.ipp:39
#22 boost::asio::detail::posix_thread::func<boost::asio::thread_pool::thread_function>::run (this=<optimized out>) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/posix_thread.hpp:86
#23 0x000062ca5df79dc3 in boost::asio::detail::boost_asio_detail_posix_thread_function (arg=0x62ca8c44d8a0) at /home/jenkins/.conan2/p/boost8aba03ee70ea0/p/include/boost/asio/detail/impl/posix_thread.ipp:74
#24 0x0000766dad9fcaa4 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#25 0x0000766dada89c6c in ?? () from /lib/x86_64-linux-gnu/libc.so.6