Ceph » CephFS

On the nfs ganesha mount, when the cluster is made full with async IO, the mount hangs.

Please refer https://bugzilla.redhat.com/show_bug.cgi?id=2291163#c21

The nfs ganesha process is manually killed to collect the core and analysed.

The following thread is causing the deadlock. The issue has occurred while handling the osd full event. The 'handle_osd_map' takes the 'client_lock' and cancels all the ongoing
writes in case of osd full. The cancel would call the finisher of each write call which again takes the 'client_lock'. This is introduced recently as part of
https://github.com/ceph/ceph/pull/59987/commits/3ebe97484d26cf5d9cd78636ee4718c075a2897b and required in the normal code flow otherwise it causes corruption.

---------

#0  0x00007f4d77274960 in __lll_lock_wait () from /lib64/libc.so.6
#1  0x00007f4d7727aff2 in pthread_mutex_lock@@GLIBC_2.2.5 () from /lib64/libc.so.6
#2  0x00007f4d7491b0a1 in __gthread_mutex_lock (__mutex=0x7f4d200f99b0) at /usr/include/c++/11/x86_64-redhat-linux/bits/gthr-default.h:749
#3  std::mutex::lock (this=<optimized out>) at /usr/include/c++/11/bits/std_mutex.h:100
#4  std::scoped_lock<std::mutex>::scoped_lock (__m=..., this=<optimized out>, this=<optimized out>, __m=...) at /usr/include/c++/11/mutex:655
#5  Client::C_Lock_Client_Finisher::finish (this=0x7f4ca0103550, r=-28) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:11371
#6  0x00007f4d74888dfd in Context::complete (this=0x7f4ca0103550, r=<optimized out>) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/include/Context.h:99
#7  0x00007f4d7498850c in std::__do_visit<std::__detail::__variant::__deduce_visit_result<void>, Objecter::Op::complete(std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&, boost::system::error_code, int, boost::asio::io_context::basic_executor_type<std::allocator<void>, 0ul>)::{lambda(auto:1&&)#1}, std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*> >(Objecter::Op::complete(std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&, boost::system::error_code, int, boost::asio::io_context::basic_executor_type<std::allocator<void>, 0ul>)::{lambda(auto:1&&)#1}&&, std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&) (__visitor=...) at /usr/include/c++/11/variant:1727
#8  std::visit<Objecter::Op::complete(std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&, boost::system::error_code, int, boost::asio::io_context::basic_executor_type<std::allocator<void>, 0ul>)::{lambda(auto:1&&)#1}, std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*> >(Objecter::Op::complete(std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&, boost::system::error_code, int, boost::asio::io_context::basic_executor_type<std::allocator<void>, 0ul>)::{lambda(auto:1&&)#1}&&, std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&) (__visitor=...) at /usr/include/c++/11/variant:1761
#9  Objecter::Op::complete(std::variant<boost::asio::any_completion_handler<void (boost::system::error_code)>, fu2::abi_310::detail::function<fu2::abi_310::detail::config<true, false, 16ul>, fu2::abi_310::detail::property<true, false, void (boost::system::error_code)> >, Context*>&&, boost::system::error_code, int, boost::asio::io_context::basic_executor_type<std::allocator<void>, 0ul>) (e=..., e=..., r=-28, ec=..., f=...) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/osdc/Objecter.h:2074
#10 Objecter::Op::complete (e=..., r=-28, ec=..., this=0x7f4ca022c7f0) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/osdc/Objecter.h:2089
#11 Objecter::op_cancel (this=0x7f4d200fab20, s=<optimized out>, tid=<optimized out>, r=-28) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/osdc/Objecter.cc:2527
#12 0x00007f4d7498ea12 in Objecter::op_cancel_writes (this=0x7f4d200fab20, r=-28, pool=103) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/osdc/Objecter.cc:2626
#13 0x00007f4d748e1c8e in Client::_handle_full_flag (this=0x7f4d200f9830, pool=103) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:2829
#14 0x00007f4d748ed20c in Client::handle_osd_map (m=..., this=0x7f4d200f9830) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:2914
#15 Client::ms_dispatch2 (this=0x7f4d200f9830, m=...) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:2955
#16 0x00007f4d75b8add2 in Messenger::ms_deliver_dispatch (m=..., this=0x7f4d200ed3e0) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/msg/Messenger.h:731
#17 DispatchQueue::entry (this=0x7f4d200ed6f0) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/msg/DispatchQueue.cc:201
#18 0x00007f4d75c27fa1 in DispatchQueue::DispatchThread::entry (this=<optimized out>) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/msg/DispatchQueue.h:101
#19 0x00007f4d77277c02 in start_thread () from /lib64/libc.so.6
#20 0x00007f4d772fcc40 in clone3 () from /lib64/libc.so.6
--------

There are so many writes and reads which are also blocked because of above deadlock as below.

------------------

#0  0x00007f4d77274960 in __lll_lock_wait () from /lib64/libc.so.6
#1  0x00007f4d7727aff2 in pthread_mutex_lock@@GLIBC_2.2.5 () from /lib64/libc.so.6
#2  0x00007f4d748a98e8 in __gthread_mutex_lock (__mutex=0x7f4d200f99b0) at /usr/include/c++/11/x86_64-redhat-linux/bits/gthr-default.h:749
#3  std::mutex::lock (this=0x7f4d200f99b0) at /usr/include/c++/11/bits/std_mutex.h:100
#4  std::unique_lock<std::mutex>::lock (this=0x7f4d2e7f9bb0) at /usr/include/c++/11/bits/unique_lock.h:139
#5  std::unique_lock<std::mutex>::unique_lock (__m=..., this=<optimized out>, this=<optimized out>, __m=...) at /usr/include/c++/11/bits/unique_lock.h:69
#6  Client::ll_preadv_pwritev (syncdataonly=false, do_fsync=false, bl=0x7f4bbc557148, onfinish=0x7f4bbc557140, write=true, offset=3037016064, iovcnt=1, iov=<optimized out>, fh=0x7f4c6812d690, this=0x7f4d200f9830) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:16040
#7  ceph_ll_nonblocking_readv_writev (cmount=<optimized out>, io_info=io_info@entry=0x7f4bbc320c48) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/libcephfs.cc:2043
#8  0x00007f4d754446dd in ceph_fsal_write2 (obj_hdl=0x7f4c68203e60, bypass=<optimized out>, done_cb=0x7f4d77530840 <mdc_write_cb>, write_arg=0x7f4bbc364528, caller_arg=0x7f4bbc117fd0) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/FSAL/FSAL_CEPH/handle.c:2266
#9  0x00007f4d77530153 in mdcache_write2 (obj_hdl=0x7f4c681299d8, bypass=<optimized out>, done_cb=<optimized out>, write_arg=0x7f4bbc364528, caller_arg=<optimized out>) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_file.c:682
#10 0x00007f4d775080ca in nfs4_op_write (op=<optimized out>, data=0x7f4bbc313090, resp=0x7f4bbc327120) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_op_write.c:490
#11 0x00007f4d774e9315 in process_one_op (data=0x7f4bbc313090, status=0x7f4d2e7fa64c) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_Compound.c:905
#12 0x00007f4d774ea928 in nfs4_Compound (arg=<optimized out>, req=0x7f4bbc5610f0, res=0x7f4bbc00cbe0) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_Compound.c:1382
#13 0x00007f4d7746db05 in nfs_rpc_process_request (reqdata=<optimized out>, retry=<optimized out>) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/MainNFSD/nfs_worker_thread.c:1462
#14 0x00007f4d771c65f7 in svc_request (xprt=0x7f4d480115e0, xdrs=<optimized out>) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1229
#15 0x00007f4d771cae6a in svc_rqst_xprt_task_recv (wpe=<optimized out>) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1210
#16 0x00007f4d771cd91b in svc_rqst_epoll_loop (wpe=0x55e04fdd7d78) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1585
#17 0x00007f4d771d6cbc in work_pool_thread (arg=0x7f4ca40139b0) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/work_pool.c:187
#18 0x00007f4d77277c02 in start_thread () from /lib64/libc.so.6
#19 0x00007f4d772fcc40 in clone3 () from /lib64/libc.so.6

#0  0x00007f4d7727479a in __futex_abstimed_wait_common () from /lib64/libc.so.6
#1  0x00007f4d77276fa0 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libc.so.6
#2  0x00007f4d76e446b0 in std::condition_variable::wait(std::unique_lock<std::mutex>&) () from /lib64/libstdc++.so.6
#3  0x00007f4d7491d013 in std::condition_variable::wait<C_SaferCond::wait()::{lambda()#1}>(std::unique_lock<std::mutex>&, C_SaferCond::wait()::{lambda()#1}) (__p=..., __lock=..., this=0x7f4cc7ffc970) at /usr/include/c++/11/condition_variable:103
#4  C_SaferCond::wait (this=0x7f4cc7ffc940) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/common/Cond.h:101
#5  operator() (wanted=4, tbl=..., onfinish=..., __closure=<synthetic pointer>) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:11164
#6  Client::_read_sync (checkeof=<synthetic pointer>, bl=0x7f4cc7ffca30, len=4, off=<optimized out>, f=0x7f4c842ed590, this=0x7f4d200f9830) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:11213
#7  Client::_read (this=0x7f4d200f9830, f=0x7f4c842ed590, offset=<optimized out>, size=4, bl=0x7f4cc7ffca30, onfinish=0x0) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:10959
#8  0x00007f4d748a7e7e in Client::ll_read (bl=0x7f4cc7ffca30, len=<optimized out>, off=2985001052, fh=0x7f4c842ed590, this=0x7f4d200f9830) at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/client/Client.cc:15838
#9  ceph_ll_read (cmount=<optimized out>, filehandle=0x7f4c842ed590, off=off@entry=2985001052, len=<optimized out>, buf=0x7f4d10d9b000 ";Y\321\034L\177") at /usr/src/debug/ceph-19.2.0-17.el9cp.x86_64/src/libcephfs.cc:1934
#10 0x00007f4d75444232 in ceph_fsal_read2 (obj_hdl=0x7f4bd40defc0, bypass=<optimized out>, done_cb=0x7f4d77530950 <mdc_read_cb>, read_arg=0x7f4be81229c8, caller_arg=0x7f4be8430a50) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/FSAL/FSAL_CEPH/handle.c:2016
#11 0x00007f4d775300a3 in mdcache_read2 (obj_hdl=0x7f4bd40e0398, bypass=<optimized out>, done_cb=<optimized out>, read_arg=0x7f4be81229c8, caller_arg=<optimized out>) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_file.c:595
#12 0x00007f4d775595b6 in nfs4_read.constprop.0 (op=op@entry=0x7f4be8006a70, data=data@entry=0x7f4be8009810, resp=resp@entry=0x7f4be88ff930, info=info@entry=0x0, io=<optimized out>) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_op_read.c:794
#13 0x00007f4d774fc4a2 in nfs4_op_read (op=0x7f4be8006a70, data=0x7f4be8009810, resp=0x7f4be88ff930) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_op_read.c:859
#14 0x00007f4d774e9315 in process_one_op (data=0x7f4be8009810, status=0x7f4cc7ffd64c) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_Compound.c:905
#15 0x00007f4d774ea928 in nfs4_Compound (arg=<optimized out>, req=0x7f4be811fb20, res=0x7f4be8125350) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/Protocols/NFS/nfs4_Compound.c:1382
#16 0x00007f4d7746db05 in nfs_rpc_process_request (reqdata=<optimized out>, retry=<optimized out>) at /usr/src/debug/nfs-ganesha-6.0-6.el9cp.x86_64/src/MainNFSD/nfs_worker_thread.c:1462
#17 0x00007f4d771c65f7 in svc_request (xprt=0x7f4d48004450, xdrs=<optimized out>) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1229
#18 0x00007f4d771cae6a in svc_rqst_xprt_task_recv (wpe=<optimized out>) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1210
#19 0x00007f4d771cd91b in svc_rqst_epoll_loop (wpe=0x55e04fdd7d78) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/svc_rqst.c:1585
#20 0x00007f4d771d6cbc in work_pool_thread (arg=0x7f4ca01f4020) at /usr/src/debug/libntirpc-6.0-1.el9cp.x86_64/src/work_pool.c:187
#21 0x00007f4d77277c02 in start_thread () from /lib64/libc.so.6
#22 0x00007f4d772fcc40 in clone3 () from /lib64/libc.so.6

------------------