Issue with calling done_cb from a different thread for fsal_read2
Hi all, I'm working to create an async model in fsal layer for my filesystem. As part of this, called "done_cb" for a read_req from my own thread in fsal layer. This causes hang and nfs4 stopped responding. Here is pseudo code for the read callback. i could see a similar implementation in FSAL_MEM (mem_handle.c) layer void fsal_read2_cb(void *cbArg, int err) { struct test_wa *wa = (struct test_wa*)cbArg; fsal_errors_t fsal_error = posix2fsal_error(err); struct root_op_context root_op_context; init_root_op_context(&root_op_context, wa->ctx_export, wa->fsal_export, 0, 0, UNKNOWN_REQUEST); wa->done_cb(wa->obj_hdl, fsalstat(fsal_error, err), wa->read_arg, wa->caller_arg); release_root_op_context(); free(wa); return; } Shouldn't we call done_cb from a custom thread ? Can you please let me know if i'm missing something and right way to do this - Thanks for the help Regards, Chakra
Im using Ganesha Version - v3.3 - on Ubuntu machine
That pseudo-code looks okay. Can you attach to the hung ganesha in the debugger and look at what the thread is doing? It may be stuck on a lock or something. Daniel On 12/17/20 5:22 AM, Chakra Divi wrote:
Hi all,
I'm working to create an async model in fsal layer for my filesystem. As part of this, called "done_cb" for a read_req from my own thread in fsal layer. This causes hang and nfs4 stopped responding. Here is pseudo code for the read callback. i could see a similar implementation in FSAL_MEM (mem_handle.c) layer
void fsal_read2_cb(void *cbArg, int err) { struct test_wa *wa = (struct test_wa*)cbArg; fsal_errors_t fsal_error = posix2fsal_error(err); struct root_op_context root_op_context; init_root_op_context(&root_op_context, wa->ctx_export, wa->fsal_export, 0, 0, UNKNOWN_REQUEST); wa->done_cb(wa->obj_hdl, fsalstat(fsal_error, err), wa->read_arg, wa->caller_arg); release_root_op_context(); free(wa); return; }
Shouldn't we call done_cb from a custom thread ? Can you please let me know if i'm missing something and right way to do this - Thanks for the help
Regards, Chakra _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
Hi Daniel, Thanks for responding. I have attached the hung ganesha and captured the backtraces for all threads - all worker threads are waiting on the conditional variable. I could see no locks as such in any of the threads. Is there anything i need to take care while updating op_ctx ? backtrace of one of the worker thread ************************************************************************* (gdb) bt #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225 #1 0x00007f98a96a3d7b in work_pool_thread (arg=0x7f9899373020) at /root/chakra/nfs-ganesha_V3-stable/nfs-ganesha/src/libntirpc/src/work_pool.c:215 #2 0x00007f98a9e9b6ba in start_thread (arg=0x7f987b2fe700) at pthread_create.c:333 #3 0x00007f98a99c941d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109 ************************************************************************* fio command im using - see weird output...at the end ************************************************************************* root@testnode:~# fio --direct=1 --name=testfile --directory=/nfs4/testnode/test --thread --runtime=120 --time_based --refill_buffers --overwrite=0 --ioengine=libaio --rw=read --bs=128k --numjobs=4 --filesize=4g --fallocate=none --group_reporting --iodepth=512 testfile: (g=0): rw=read, bs=128K-128K/128K-128K/128K-128K, ioengine=libaio, iodepth=512 ... fio-2.2.10 Starting 4 threads testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) Jobs: 4 (f=4): [R(4)] [inf% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 1158050441d:06h:43m:07s] ************************************************************************* Regards, Chakra
That's normal for a worker thread. They wait on the condition variable, until work is available, then wake up and do the work. op_ctx is safe, it's stored in thread-local-storage, so it's completely thread safe. Usually, on a hung Ganesha, you'll find at least one thread with a long backtrace, waiting on something at the bottom, or hard looping, or something like that. Along that call path it's holding a lock, that other threads are waiting on. One possibility is that the async is messed up somehow, and sockets aren't being released back to epoll, so we stop listening on them. You can turn on ntirpc tracing (set TIRPC = FULL_DEBUG in Components, and RPC_Debug_Flags = 0xffffffff in NFS_CORE_PARAM). It should then log xprts being added and removed from epoll, and you can look at that. Daniel On 12/18/20 4:47 AM, Chakra Divi wrote:
Hi Daniel,
Thanks for responding. I have attached the hung ganesha and captured the backtraces for all threads - all worker threads are waiting on the conditional variable. I could see no locks as such in any of the threads. Is there anything i need to take care while updating op_ctx ?
backtrace of one of the worker thread ************************************************************************* (gdb) bt #0 pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225 #1 0x00007f98a96a3d7b in work_pool_thread (arg=0x7f9899373020) at /root/chakra/nfs-ganesha_V3-stable/nfs-ganesha/src/libntirpc/src/work_pool.c:215 #2 0x00007f98a9e9b6ba in start_thread (arg=0x7f987b2fe700) at pthread_create.c:333 #3 0x00007f98a99c941d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109 *************************************************************************
fio command im using - see weird output...at the end ************************************************************************* root@testnode:~# fio --direct=1 --name=testfile --directory=/nfs4/testnode/test --thread --runtime=120 --time_based --refill_buffers --overwrite=0 --ioengine=libaio --rw=read --bs=128k --numjobs=4 --filesize=4g --fallocate=none --group_reporting --iodepth=512 testfile: (g=0): rw=read, bs=128K-128K/128K-128K/128K-128K, ioengine=libaio, iodepth=512 ... fio-2.2.10 Starting 4 threads testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) testfile: Laying out IO file(s) (1 file(s) / 4096MB) Jobs: 4 (f=4): [R(4)] [inf% done] [0KB/0KB/0KB /s] [0/0/0 iops] [eta 1158050441d:06h:43m:07s] *************************************************************************
Regards, Chakra _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
Hi Daniel, Thanks for giving info to look into it. I have checked the logs and found that - svc_destroy_task is running in a loop for two tasks - whose xp_refcnts are negative. Following the are the logs where refcnt became negative. I'm suspecting this could be due to async call back. /**************************************************************/ 21/12/2020 T13:42:28.211691+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_flushv: 0x7f19fa871f00 fd 13 returning Success (0) 21/12/2020 T13:42:28.211705+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_write: 0x7f19fa871f00 fd 13 COMPLETED 21/12/2020 T13:42:28.211716+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_write: 0x7f19fa871f00 fd 13 About to release 21/12/2020 T13:42:28.211728+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt 1 af 10 port 874 @svc_ioq_write:399 21/12/2020 T13:42:28.211739+0000 9399[none] [svc_32] 0 :rpc :xdr_ioq_destroy() xioq 0x7f19f140e180 21/12/2020 T13:42:28.211755+0000 9399[none] [svc_32] 0 :rpc :Call uio_release 21/12/2020 T13:42:28.211869+0000 9399[none] [svc_32] 0 :rpc :xdr_bytes_free:653 already free 21/12/2020 T13:42:28.211901+0000 9399[none] [svc_32] 0 :rpc :xdr_ioq_destroy() xioq 0x7f19f3410300 21/12/2020 T13:42:28.211921+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt 0 af 10 port 874 @free_nfs_request:1402 21/12/2020 T13:42:28.211934+0000 9399[none] [svc_32] 0 :rpc :svc_vc_destroy_it() 0x7f19fa871f00 fd 13 xp_refcnt 0 @free_nfs_request:1402 21/12/2020 T13:42:28.211953+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt -1 af 10 port 874 @svc_resume_task:1247 21/12/2020 T13:42:28.211968+0000 9399[none] [svc_32] 0 :rpc :WARNING! already destroying!() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt -1 af 10 port 874 @svc_resume_task:1247 /**************************************************************/ I found that in the function svc_vc_destroy_task() - when ref count is non-zero - task is resubmitted to work_pool_thread and thus creating a loop when refcount is negative. if refcount is negative is this way its expected to execute ? Regards, Chakra
xp_refcnt should definitely never be negative. We can probably handle it better in svc_vc_destroy_task(), but it's a big bug if it happens, and we'd expect things to break. I took a quick look, and didn't see anything, but this is complicated code, and I'll have to look closer. I may not be able to get to it before the new year, since we are shutdown starting Thursday until the 4th. I'll try to get time to look at it, but it may have to wait until then. Daniel On 12/21/20 11:07 AM, Chakra Divi wrote:
Hi Daniel,
Thanks for giving info to look into it. I have checked the logs and found that - svc_destroy_task is running in a loop for two tasks - whose xp_refcnts are negative.
Following the are the logs where refcnt became negative. I'm suspecting this could be due to async call back. /**************************************************************/ 21/12/2020 T13:42:28.211691+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_flushv: 0x7f19fa871f00 fd 13 returning Success (0) 21/12/2020 T13:42:28.211705+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_write: 0x7f19fa871f00 fd 13 COMPLETED 21/12/2020 T13:42:28.211716+0000 9399[none] [svc_32] 0 :rpc :svc_ioq_write: 0x7f19fa871f00 fd 13 About to release 21/12/2020 T13:42:28.211728+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt 1 af 10 port 874 @svc_ioq_write:399 21/12/2020 T13:42:28.211739+0000 9399[none] [svc_32] 0 :rpc :xdr_ioq_destroy() xioq 0x7f19f140e180 21/12/2020 T13:42:28.211755+0000 9399[none] [svc_32] 0 :rpc :Call uio_release 21/12/2020 T13:42:28.211869+0000 9399[none] [svc_32] 0 :rpc :xdr_bytes_free:653 already free 21/12/2020 T13:42:28.211901+0000 9399[none] [svc_32] 0 :rpc :xdr_ioq_destroy() xioq 0x7f19f3410300 21/12/2020 T13:42:28.211921+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt 0 af 10 port 874 @free_nfs_request:1402 21/12/2020 T13:42:28.211934+0000 9399[none] [svc_32] 0 :rpc :svc_vc_destroy_it() 0x7f19fa871f00 fd 13 xp_refcnt 0 @free_nfs_request:1402 21/12/2020 T13:42:28.211953+0000 9399[none] [svc_32] 0 :rpc :svc_release_it() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt -1 af 10 port 874 @svc_resume_task:1247 21/12/2020 T13:42:28.211968+0000 9399[none] [svc_32] 0 :rpc :WARNING! already destroying!() 0x7f19fa871f00 fd 13 fd_send -1 xp_refcnt -1 af 10 port 874 @svc_resume_task:1247 /**************************************************************/
I found that in the function svc_vc_destroy_task() - when ref count is non-zero - task is resubmitted to work_pool_thread and thus creating a loop when refcount is negative. if refcount is negative is this way its expected to execute ?
Regards, Chakra _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
Daniel, Hope you are back. Did you get a chance to look into the code ? Do you need anything more that can help you to understand the sequence of events resulted in xp_refcnt negative ? Chakra
Not yet, sorry. I'll try to get to it in the next couple of days. On 1/7/21 12:44 AM, Chakra Divi wrote:
Daniel,
Hope you are back. Did you get a chance to look into the code ? Do you need anything more that can help you to understand the sequence of events resulted in xp_refcnt negative ?
Chakra _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
Okay, I've had a chance to look at this, and I now have working async I/O using FSAL_MEM. The necessary fixes are here: https://github.com/nfs-ganesha/ntirpc/pull/225 https://review.gerrithub.io/c/ffilz/nfs-ganesha/+/508819 Daniel On 1/7/21 12:44 AM, Chakra Divi wrote:
Daniel,
Hope you are back. Did you get a chance to look into the code ? Do you need anything more that can help you to understand the sequence of events resulted in xp_refcnt negative ?
Chakra _______________________________________________ Devel mailing list -- devel@lists.nfs-ganesha.org To unsubscribe send an email to devel-leave@lists.nfs-ganesha.org
participants (2)
-
Chakra Divi -
Daniel Gryniewicz