Re: steam-associated reproducible hard NFSv4.2 client hang (5.9, 5.10)

["bfields@fieldses.org" <bfields@fieldses.org>]

On Tue, Feb 23, 2021 at 11:58:51PM +0000, Trond Myklebust wrote:
> On Tue, 2021-02-23 at 17:57 -0500, J. Bruce Fields wrote:
> > On Sun, Jan 03, 2021 at 02:27:51PM +0000, Nick Alcock wrote:
> > > Relevant exports, from /proc/fs/nfs/exports:
> > > 
> > > /       192.168.16.0/24,silk.wkstn.nix(ro,insecure,no_root_squash,s
> > > ync,no_wdelay,no_subtree_check,v4root,fsid=0,uuid=0a4a4563:00764033
> > > :8c827c0e:989cf534,sec=390003:390004:390005:1)
> > > /home/.loom.srvr.nix    *.srvr.nix,fold.srvr.nix(rw,root_squash,syn
> > > c,wdelay,no_subtree_check,uuid=0a4a4563:00764033:8c827c0e:989cf534,
> > > sec=1)
> 
> Isn't that trying to export the same filesystem as '/' on the line
> above using conflicting export options?

Yes, and exporting something on the root filesystem is generally a bad
idea for the usual reasons.

I don't see any explanation for the write hang there, though.

Unless maybe if it leaves mountd unable to answer an upcall for some
reason, hm.

I think that would show up in /proc/net/rpc/nfsd.fh/content.  Try
cat'ing that file after 'rpcdebug -m rpc -s cache' and that should show
if there's an upcall that's not getting answered.

--b.

> 
> 
> > > /pkg/non-
> > > free/steam     192.168.16.0/24,silk.wkstn.nix(rw,root_squash,sync,w
> > > delay,uuid=11b94016:cb6e4b64:beb6c134:9ea3d6b3,sec=1)
> > > 
> > > Blocked tasks after the hang suggest that the client is hung
> > > waiting
> > > indefinitely for the server to reply, and I'd guess the server
> > > doesn't
> > > think it needs to. (I can do some server-side debugging dumps too
> > > if you
> > > think the problem might be there.)
> > 
> > I seem to remember there have been some subtle changes to how dropped
> > replies are handled.  If I remember right: a v4 server is never
> > supposed
> > to drop a reply without also closing the tcp connection, but it may
> > have
> > done so in the past.  (I *think* all those cases are fixed?)
> > 
> > And the client may have been changed to be more unforgiving about
> > that
> > requirement in recent years.
> > 
> > But I don't know if that's where the issue is.
> > 
> > I'm not sure how best to go about debugging.  I suppose you could try
> > to
> > capture a network trace and work out if there's an RPC that isn't
> > getting a reply.
> > 
> > Maybe turning on server debugging and looking for "svc: svc_process
> > dropit" messages timed with the start of the hang.  I think what you
> > want is "rpdebug -m rpc -s svcdsp".
> > 
> > Does rpc.mountd look healthy?
> > 
> > --b.
> > 
> > 
> > > 
> > > [  322.843962] sysrq: Show Blocked State
> > > [  322.844058] task:tee             state:D stack:    0 pid: 1176
> > > ppid:  1173 flags:0x00000000
> > > [  322.844064] Call Trace:
> > > [  322.844074]  __schedule+0x3db/0x7ee
> > > [  322.844079]  ? io_schedule+0x70/0x6d
> > > [  322.844082]  schedule+0x68/0xdc
> > > [  322.844085]  io_schedule+0x46/0x6d
> > > [  322.844089]  bit_wait_io+0x11/0x52
> > > [  322.844092]  __wait_on_bit+0x31/0x90
> > > [  322.844096]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844100]  ? var_wake_function+0x30/0x27
> > > [  322.844104]  nfs_wait_on_request.part.0+0x31/0x33
> > > [  322.844107]  nfs_page_group_lock_head+0x31/0x78
> > > [  322.844110]  nfs_lock_and_join_requests+0x9d/0x26e
> > > [  322.844114]  nfs_updatepage+0x1be/0x985
> > > [  322.844118]  nfs_write_end+0x128/0x52a
> > > [  322.844122]  ? iov_iter_copy_from_user_atomic+0xe8/0x3ce
> > > [  322.844127]  generic_perform_write+0xed/0x17c
> > > [  322.844131]  nfs_file_write+0x14a/0x29f
> > > [  322.844135]  new_sync_write+0xfb/0x16b
> > > [  322.844139]  vfs_write+0x1ee/0x29a
> > > [  322.844142]  ? vfs_read+0x17b/0x198
> > > [  322.844145]  ksys_write+0x61/0xd0
> > > [  322.844148]  __x64_sys_write+0x1a/0x1c
> > > [  322.844151]  do_syscall_64+0x32/0x45
> > > [  322.844154]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  322.844158] RIP: 0033:0x7f4781f323a3
> > > [  322.844160] RSP: 002b:00007ffcf8220408 EFLAGS: 00000246
> > > ORIG_RAX: 0000000000000001
> > > [  322.844164] RAX: ffffffffffffffda RBX: 0000000000000092 RCX:
> > > 00007f4781f323a3
> > > [  322.844166] RDX: 0000000000000092 RSI: 00007ffcf8220530 RDI:
> > > 0000000000000003
> > > [  322.844168] RBP: 00007ffcf8220530 R08: 0000000000000000 R09:
> > > 0000000000000001
> > > [  322.844170] R10: 0000000000400ad2 R11: 0000000000000246 R12:
> > > 0000000000000092
> > > [  322.844172] R13: 0000000002361580 R14: 0000000000000092 R15:
> > > 00007f4782201720
> > > [  322.844202] task:CIPCServer::Thr state:D stack:    0 pid: 1801
> > > ppid:  1540 flags:0x20020000
> > > [  322.844207] Call Trace:
> > > [  322.844212]  __schedule+0x3db/0x7ee
> > > [  322.844219]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844222]  schedule+0x68/0xdc
> > > [  322.844227]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844230]  __wait_on_bit+0x31/0x90
> > > [  322.844235]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844238]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844242]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844246]  ? var_wake_function+0x30/0x27
> > > [  322.844250]  __rpc_execute+0xe5/0x485
> > > [  322.844254]  ? sugov_get_util+0xf0/0xeb
> > > [  322.844258]  rpc_execute+0xa5/0xaa
> > > [  322.844263]  rpc_run_task+0x148/0x187
> > > [  322.844267]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844272]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844278]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844283]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844287]  nfs_access_get_cached+0x14d/0x1df
> > > [  322.844291]  nfs_do_access+0x48/0x28e
> > > [  322.844296]  ? step_into+0x2bc/0x6a1
> > > [  322.844301]  nfs_permission+0xa2/0x1b8
> > > [  322.844305]  inode_permission+0x96/0xca
> > > [  322.844308]  ? unlazy_walk+0x4c/0x80
> > > [  322.844312]  link_path_walk.part.0+0x2a5/0x320
> > > [  322.844315]  ? path_init+0x2c2/0x3e5
> > > [  322.844318]  path_lookupat+0x3f/0x1b1
> > > [  322.844322]  filename_lookup+0x97/0x17f
> > > [  322.844326]  ? kmem_cache_alloc+0x32/0x200
> > > [  322.844331]  user_path_at_empty+0x59/0x8a
> > > [  322.844333]  do_faccessat+0x70/0x227
> > > [  322.844337]  __ia32_sys_access+0x1c/0x1e
> > > [  322.844340]  __do_fast_syscall_32+0x5f/0x8e
> > > [  322.844342]  do_fast_syscall_32+0x3d/0x80
> > > [  322.844346]  entry_SYSCALL_compat_after_hwframe+0x45/0x0
> > > [  322.844348] RIP: 0023:0xf7ee6549
> > > [  322.844350] RSP: 002b:00000000eb763b28 EFLAGS: 00200292
> > > ORIG_RAX: 0000000000000021
> > > [  322.844353] RAX: ffffffffffffffda RBX: 000000005754d9e0 RCX:
> > > 0000000000000004
> > > [  322.844355] RDX: 00000000f7ab3e1c RSI: 000000005754d9e0 RDI:
> > > 00000000eb763bc8
> > > [  322.844357] RBP: 00000000f78a91c0 R08: 0000000000000000 R09:
> > > 0000000000000000
> > > [  322.844359] R10: 0000000000000000 R11: 0000000000000000 R12:
> > > 0000000000000000
> > > [  322.844360] R13: 0000000000000000 R14: 0000000000000000 R15:
> > > 0000000000000000
> > > [  322.844364] task:CFileWriterThre state:D stack:    0 pid: 1810
> > > ppid:  1540 flags:0x20024000
> > > [  322.844367] Call Trace:
> > > [  322.844371]  __schedule+0x3db/0x7ee
> > > [  322.844375]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844379]  schedule+0x68/0xdc
> > > [  322.844382]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844385]  __wait_on_bit+0x31/0x90
> > > [  322.844389]  ? call_reserveresult+0xa0/0x9f
> > > [  322.844391]  ? call_transmit_status+0x160/0x159
> > > [  322.844395]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844398]  ? var_wake_function+0x30/0x27
> > > [  322.844401]  __rpc_execute+0xe5/0x485
> > > [  322.844404]  ? nfs_check_verifier+0x5b/0xa4
> > > [  322.844407]  rpc_execute+0xa5/0xaa
> > > [  322.844410]  rpc_run_task+0x148/0x187
> > > [  322.844414]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844417]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844422]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844426]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844430]  nfs_getattr+0x159/0x374
> > > [  322.844433]  vfs_getattr_nosec+0x96/0xa4
> > > [  322.844435]  vfs_statx+0x7a/0xe5
> > > [  322.844438]  vfs_fstatat+0x1f/0x21
> > > [  322.844443]  __do_compat_sys_ia32_lstat64+0x2b/0x4e
> > > [  322.844448]  __ia32_compat_sys_ia32_lstat64+0x14/0x16
> > > [  322.844450]  __do_fast_syscall_32+0x5f/0x8e
> > > [  322.844453]  do_fast_syscall_32+0x3d/0x80
> > > [  322.844457]  entry_SYSCALL_compat_after_hwframe+0x45/0x0
> > > [  322.844459] RIP: 0023:0xf7ee6549
> > > [  322.844460] RSP: 002b:00000000eb561be8 EFLAGS: 00000292
> > > ORIG_RAX: 00000000000000c4
> > > [  322.844463] RAX: ffffffffffffffda RBX: 00000000c521bf60 RCX:
> > > 00000000eb561e70
> > > [  322.844465] RDX: 00000000f7ab3e1c RSI: 00000000eb561e70 RDI:
> > > 00000000c521bf60
> > > [  322.844467] RBP: 0000000000000000 R08: 0000000000000000 R09:
> > > 0000000000000000
> > > [  322.844468] R10: 0000000000000000 R11: 0000000000000000 R12:
> > > 0000000000000000
> > > [  322.844470] R13: 0000000000000000 R14: 0000000000000000 R15:
> > > 0000000000000000
> > > [  322.844477] task:Steam - DirWatc state:D stack:    0 pid: 1924
> > > ppid:  1540 flags:0x20024000
> > > [  322.844480] Call Trace:
> > > [  322.844484]  __schedule+0x3db/0x7ee
> > > [  322.844488]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844492]  schedule+0x68/0xdc
> > > [  322.844495]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844498]  __wait_on_bit+0x31/0x90
> > > [  322.844501]  ? rpc_sleep_on_timeout+0x64/0x9c
> > > [  322.844504]  ? rpc_check_timeout+0x1e0/0x1e0
> > > [  322.844507]  ? call_connect_status+0x180/0x17a
> > > [  322.844511]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844513]  ? var_wake_function+0x30/0x27
> > > [  322.844516]  __rpc_execute+0xe5/0x485
> > > [  322.844520]  rpc_execute+0xa5/0xaa
> > > [  322.844523]  rpc_run_task+0x148/0x187
> > > [  322.844526]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844530]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844534]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844538]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844542]  nfs_lookup_verify_inode+0x67/0x82
> > > [  322.844545]  nfs_do_lookup_revalidate+0x19b/0x29c
> > > [  322.844548]  nfs4_do_lookup_revalidate+0x5d/0xc5
> > > [  322.844552]  nfs4_lookup_revalidate+0x6a/0x8d
> > > [  322.844555]  lookup_fast+0xb8/0x122
> > > [  322.844559]  path_openat+0xfd/0xfd8
> > > [  322.844562]  ? unlazy_walk+0x4c/0x80
> > > [  322.844565]  ? terminate_walk+0x62/0xed
> > > [  322.844569]  ? putname+0x4b/0x53
> > > [  322.844572]  do_filp_open+0x86/0x110
> > > [  322.844576]  ? kmem_cache_alloc+0x32/0x200
> > > [  322.844579]  ? __alloc_fd+0xb2/0x143
> > > [  322.844583]  do_sys_openat2+0x8d/0x13a
> > > [  322.844585]  ? do_faccessat+0x108/0x227
> > > [  322.844588]  __ia32_compat_sys_openat+0x48/0x63
> > > [  322.844591]  __do_fast_syscall_32+0x5f/0x8e
> > > [  322.844594]  do_fast_syscall_32+0x3d/0x80
> > > [  322.844597]  entry_SYSCALL_compat_after_hwframe+0x45/0x0
> > > [  322.844600] RIP: 0023:0xf7ee6549
> > > [  322.844601] RSP: 002b:000000008c8fbcb0 EFLAGS: 00200287
> > > ORIG_RAX: 0000000000000127
> > > [  322.844604] RAX: ffffffffffffffda RBX: 00000000ffffff9c RCX:
> > > 000000008c8fbffc
> > > [  322.844606] RDX: 0000000000098800 RSI: 0000000000000000 RDI:
> > > 00000000f7ab3e1c
> > > [  322.844608] RBP: 0000000000000000 R08: 0000000000000000 R09:
> > > 0000000000000000
> > > [  322.844609] R10: 0000000000000000 R11: 0000000000000000 R12:
> > > 0000000000000000
> > > [  322.844611] R13: 0000000000000000 R14: 0000000000000000 R15:
> > > 0000000000000000
> > > [  322.844614] task:CGenericAsyncFi state:D stack:    0 pid: 1927
> > > ppid:  1540 flags:0x20020000
> > > [  322.844617] Call Trace:
> > > [  322.844621]  __schedule+0x3db/0x7ee
> > > [  322.844625]  schedule+0x68/0xdc
> > > [  322.844628]  io_schedule+0x46/0x6d
> > > [  322.844631]  wait_on_page_bit_common+0xf8/0x325
> > > [  322.844634]  ?
> > > trace_raw_output_file_check_and_advance_wb_err+0x80/0x7d
> > > [  322.844638]  wait_on_page_bit+0x3f/0x41
> > > [  322.844642]  wait_on_page_writeback.part.0+0x35/0x80
> > > [  322.844645]  wait_on_page_writeback+0x27/0x29
> > > [  322.844647]  __filemap_fdatawait_range+0x88/0xd9
> > > [  322.844651]  filemap_write_and_wait_range+0x45/0x80
> > > [  322.844655]  nfs_wb_all+0x30/0x13d
> > > [  322.844658]  nfs4_file_flush+0x85/0xc0
> > > [  322.844661]  filp_close+0x3e/0x78
> > > [  322.844664]  __close_fd+0x23/0x30
> > > [  322.844667]  __ia32_sys_close+0x22/0x50
> > > [  322.844670]  __do_fast_syscall_32+0x5f/0x8e
> > > [  322.844673]  do_fast_syscall_32+0x3d/0x80
> > > [  322.844676]  entry_SYSCALL_compat_after_hwframe+0x45/0x0
> > > [  322.844678] RIP: 0023:0xf7ee6549
> > > [  322.844680] RSP: 002b:000000008c5fddb0 EFLAGS: 00200286
> > > ORIG_RAX: 0000000000000006
> > > [  322.844682] RAX: ffffffffffffffda RBX: 000000000000004d RCX:
> > > 0000000000000002
> > > [  322.844684] RDX: 0000000000000000 RSI: 00000000f7d02e70 RDI:
> > > 000000000000004d
> > > [  322.844686] RBP: 000000008c5fe110 R08: 0000000000000000 R09:
> > > 0000000000000000
> > > [  322.844688] R10: 0000000000000000 R11: 0000000000000000 R12:
> > > 0000000000000000
> > > [  322.844689] R13: 0000000000000000 R14: 0000000000000000 R15:
> > > 0000000000000000
> > > [  322.844699] task:ThreadPoolForeg state:D stack:    0 pid: 1768
> > > ppid:  1735 flags:0x00004000
> > > [  322.844702] Call Trace:
> > > [  322.844705]  __schedule+0x3db/0x7ee
> > > [  322.844709]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844712]  schedule+0x68/0xdc
> > > [  322.844716]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844719]  __wait_on_bit+0x31/0x90
> > > [  322.844722]  ? rpc_sleep_on_timeout+0x64/0x9c
> > > [  322.844725]  ? rpc_check_timeout+0x1e0/0x1e0
> > > [  322.844728]  ? call_connect_status+0x180/0x17a
> > > [  322.844731]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844734]  ? var_wake_function+0x30/0x27
> > > [  322.844737]  __rpc_execute+0xe5/0x485
> > > [  322.844740]  ? nfs_check_verifier+0x5b/0xa4
> > > [  322.844743]  rpc_execute+0xa5/0xaa
> > > [  322.844746]  rpc_run_task+0x148/0x187
> > > [  322.844750]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844753]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844758]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844762]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844766]  nfs_getattr+0x159/0x374
> > > [  322.844769]  vfs_getattr_nosec+0x96/0xa4
> > > [  322.844771]  vfs_statx+0x7a/0xe5
> > > [  322.844774]  __do_sys_newstat+0x31/0x4c
> > > [  322.844778]  __x64_sys_newstat+0x16/0x18
> > > [  322.844781]  do_syscall_64+0x32/0x45
> > > [  322.844783]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  322.844786] RIP: 0033:0x7fe70ebf19e6
> > > [  322.844787] RSP: 002b:00007fe6c15b2068 EFLAGS: 00000246
> > > ORIG_RAX: 0000000000000004
> > > [  322.844790] RAX: ffffffffffffffda RBX: 00000bd4193e1910 RCX:
> > > 00007fe70ebf19e6
> > > [  322.844792] RDX: 00007fe6c15b2078 RSI: 00007fe6c15b2078 RDI:
> > > 00000bd4193e1910
> > > [  322.844794] RBP: 00007fe6c15b2160 R08: 0000000000000001 R09:
> > > 00007ffd971ed090
> > > [  322.844796] R10: 0000000000056764 R11: 0000000000000246 R12:
> > > 00007fe6c15b2078
> > > [  322.844797] R13: 00000bd4192f6f60 R14: 00007fe6c15b2108 R15:
> > > 00007fe6c15b2120
> > > [  322.844801] task:ThreadPoolForeg state:D stack:    0 pid: 1769
> > > ppid:  1735 flags:0x00000000
> > > [  322.844804] Call Trace:
> > > [  322.844807]  __schedule+0x3db/0x7ee
> > > [  322.844811]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844814]  schedule+0x68/0xdc
> > > [  322.844817]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844820]  __wait_on_bit+0x31/0x90
> > > [  322.844823]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844826]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844829]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844831]  ? var_wake_function+0x30/0x27
> > > [  322.844834]  __rpc_execute+0xe5/0x485
> > > [  322.844837]  ? update_cfs_group+0x9a/0x9e
> > > [  322.844840]  rpc_execute+0xa5/0xaa
> > > [  322.844842]  rpc_run_task+0x148/0x187
> > > [  322.844845]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844849]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844853]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844856]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844859]  nfs_file_write+0xfc/0x29f
> > > [  322.844862]  new_sync_write+0xfb/0x16b
> > > [  322.844866]  vfs_write+0x1ee/0x29a
> > > [  322.844868]  ? __fget_light+0x31/0x72
> > > [  322.844871]  ksys_write+0x61/0xd0
> > > [  322.844874]  __x64_sys_write+0x1a/0x1c
> > > [  322.844877]  do_syscall_64+0x32/0x45
> > > [  322.844880]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  322.844881] RIP: 0033:0x7fe71859ab7f
> > > [  322.844883] RSP: 002b:00007fe6bd5b0d30 EFLAGS: 00000293
> > > ORIG_RAX: 0000000000000001
> > > [  322.844885] RAX: ffffffffffffffda RBX: 00007fe6bd5b0d68 RCX:
> > > 00007fe71859ab7f
> > > [  322.844887] RDX: 0000000000000007 RSI: 00007fe6bd5b1090 RDI:
> > > 000000000000005b
> > > [  322.844888] RBP: 00007fe6bd5b0de0 R08: 0000000000000000 R09:
> > > 00007ffd971ed090
> > > [  322.844890] R10: 0000000000065fd2 R11: 0000000000000293 R12:
> > > 00000bd418d95020
> > > [  322.844891] R13: 00007fe6bd5b1090 R14: 0000000000000007 R15:
> > > 0000000000000000
> > > [  322.844900] task:ThreadPoolForeg state:D stack:    0 pid: 1807
> > > ppid:  1773 flags:0x00000000
> > > [  322.844902] Call Trace:
> > > [  322.844904]  __schedule+0x3db/0x7ee
> > > [  322.844907]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844908]  schedule+0x68/0xdc
> > > [  322.844911]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.844913]  __wait_on_bit+0x31/0x90
> > > [  322.844915]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844916]  ? __rpc_atrun+0x20/0x1a
> > > [  322.844918]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.844920]  ? var_wake_function+0x30/0x27
> > > [  322.844922]  __rpc_execute+0xe5/0x485
> > > [  322.844924]  rpc_execute+0xa5/0xaa
> > > [  322.844926]  rpc_run_task+0x148/0x187
> > > [  322.844928]  nfs4_do_call_sync+0x61/0x81
> > > [  322.844930]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.844933]  nfs4_proc_getattr+0x67/0xee
> > > [  322.844936]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.844938]  nfs_access_get_cached+0x14d/0x1df
> > > [  322.844940]  nfs_do_access+0x48/0x28e
> > > [  322.844942]  ? nfs4_lookup_revalidate+0x38/0x8d
> > > [  322.844944]  nfs_permission+0xa2/0x1b8
> > > [  322.844946]  inode_permission+0x96/0xca
> > > [  322.844948]  ? unlazy_walk+0x4c/0x80
> > > [  322.844950]  link_path_walk.part.0+0x2a5/0x320
> > > [  322.844952]  ? path_init+0x2c2/0x3e5
> > > [  322.844954]  path_lookupat+0x3f/0x1b1
> > > [  322.844956]  filename_lookup+0x97/0x17f
> > > [  322.844959]  ? do_unlk+0x9a/0xca
> > > [  322.844960]  ? kmem_cache_alloc+0x32/0x200
> > > [  322.844963]  user_path_at_empty+0x59/0x8a
> > > [  322.844965]  vfs_statx+0x64/0xe5
> > > [  322.844967]  __do_sys_newstat+0x31/0x4c
> > > [  322.844968]  ? do_fcntl+0x113/0x582
> > > [  322.844971]  ? fput+0x13/0x15
> > > [  322.844972]  ? __x64_sys_fcntl+0x81/0xa8
> > > [  322.844974]  __x64_sys_newstat+0x16/0x18
> > > [  322.844976]  do_syscall_64+0x32/0x45
> > > [  322.844977]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  322.844979] RIP: 0033:0x7f0d1fd0c9e6
> > > [  322.844980] RSP: 002b:00007f0d08e12e18 EFLAGS: 00000246
> > > ORIG_RAX: 0000000000000004
> > > [  322.844981] RAX: ffffffffffffffda RBX: 00007f0d08e12edc RCX:
> > > 00007f0d1fd0c9e6
> > > [  322.844983] RDX: 00007f0d08e12e28 RSI: 00007f0d08e12e28 RDI:
> > > 00001605c2ff1169
> > > [  322.844984] RBP: 00007f0d08e12ec0 R08: 0000000000000001 R09:
> > > 00007fffaddd9090
> > > [  322.844985] R10: 00001605c3133480 R11: 0000000000000246 R12:
> > > 0000000000000000
> > > [  322.844986] R13: 0000000000000000 R14: 00001605c2ff0f00 R15:
> > > 0000000000000000
> > > [  322.844988] task:ThreadPoolForeg state:D stack:    0 pid: 2031
> > > ppid:  1773 flags:0x00004000
> > > [  322.844990] Call Trace:
> > > [  322.844992]  __schedule+0x3db/0x7ee
> > > [  322.844995]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.844997]  schedule+0x68/0xdc
> > > [  322.844999]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.845001]  __wait_on_bit+0x31/0x90
> > > [  322.845003]  ? rpc_sleep_on_timeout+0x64/0x9c
> > > [  322.845005]  ? rpc_check_timeout+0x1e0/0x1e0
> > > [  322.845006]  ? call_connect_status+0x180/0x17a
> > > [  322.845009]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.845010]  ? var_wake_function+0x30/0x27
> > > [  322.845012]  __rpc_execute+0xe5/0x485
> > > [  322.845014]  rpc_execute+0xa5/0xaa
> > > [  322.845016]  rpc_run_task+0x148/0x187
> > > [  322.845018]  nfs4_do_call_sync+0x61/0x81
> > > [  322.845020]  _nfs4_proc_getattr+0x10a/0x120
> > > [  322.845023]  nfs4_proc_getattr+0x67/0xee
> > > [  322.845026]  __nfs_revalidate_inode+0xb7/0x2df
> > > [  322.845028]  nfs_access_get_cached+0x14d/0x1df
> > > [  322.845030]  nfs_do_access+0x48/0x28e
> > > [  322.845032]  ? nfs4_lookup_revalidate+0x38/0x8d
> > > [  322.845034]  nfs_permission+0xa2/0x1b8
> > > [  322.845036]  inode_permission+0x96/0xca
> > > [  322.845038]  ? unlazy_walk+0x4c/0x80
> > > [  322.845040]  link_path_walk.part.0+0x2a5/0x320
> > > [  322.845042]  ? path_init+0x2c2/0x3e5
> > > [  322.845044]  path_lookupat+0x3f/0x1b1
> > > [  322.845046]  filename_lookup+0x97/0x17f
> > > [  322.845049]  ? kmem_cache_alloc+0x32/0x200
> > > [  322.845051]  user_path_at_empty+0x59/0x8a
> > > [  322.845054]  ? mntput_no_expire+0x4f/0x264
> > > [  322.845055]  vfs_statx+0x64/0xe5
> > > [  322.845057]  ? putname+0x4b/0x53
> > > [  322.845059]  __do_sys_newstat+0x31/0x4c
> > > [  322.845062]  ? __x64_sys_futex+0x13a/0x159
> > > [  322.845064]  ? switch_fpu_return+0x58/0xf2
> > > [  322.845066]  __x64_sys_newstat+0x16/0x18
> > > [  322.845068]  do_syscall_64+0x32/0x45
> > > [  322.845069]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  322.845071] RIP: 0033:0x7f0d1fd0c9e6
> > > [  322.845072] RSP: 002b:00007f0d00331108 EFLAGS: 00000246
> > > ORIG_RAX: 0000000000000004
> > > [  322.845073] RAX: ffffffffffffffda RBX: 00001605c2fdc0a0 RCX:
> > > 00007f0d1fd0c9e6
> > > [  322.845074] RDX: 00007f0d00331118 RSI: 00007f0d00331118 RDI:
> > > 00001605c2fdc0a0
> > > [  322.845076] RBP: 00007f0d00331200 R08: 0000000000000001 R09:
> > > 00007fffaddd9090
> > > [  322.845077] R10: 000000000005771c R11: 0000000000000246 R12:
> > > 00007f0d00331118
> > > [  322.845078] R13: 00001605c3309c40 R14: 00007f0d003311a8 R15:
> > > 00007f0d003311c0
> > > [  322.845087] task:192.168.16.8-ma state:D stack:    0 pid: 2044
> > > ppid:     2 flags:0x00004000
> > > [  322.845089] Call Trace:
> > > [  322.845091]  __schedule+0x3db/0x7ee
> > > [  322.845094]  ?
> > > trace_event_raw_event_rpc_xdr_overflow+0x280/0x27e
> > > [  322.845095]  schedule+0x68/0xdc
> > > [  322.845098]  rpc_wait_bit_killable+0x11/0x52
> > > [  322.845100]  __wait_on_bit+0x31/0x90
> > > [  322.845102]  ? __rpc_atrun+0x20/0x1a
> > > [  322.845103]  ? __rpc_atrun+0x20/0x1a
> > > [  322.845105]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  322.845107]  ? var_wake_function+0x30/0x27
> > > [  322.845109]  __rpc_execute+0xe5/0x485
> > > [  322.845111]  rpc_execute+0xa5/0xaa
> > > [  322.845113]  rpc_run_task+0x148/0x187
> > > [  322.845115]  nfs4_do_call_sync+0x61/0x81
> > > [  322.845117]  _nfs4_proc_statfs+0xc1/0xcf
> > > [  322.845120]  nfs4_proc_statfs+0x55/0x74
> > > [  322.845122]  nfs_statfs+0x65/0x152
> > > [  322.845124]  ? _nfs4_proc_delegreturn+0x21e/0x2e5
> > > [  322.845127]  statfs_by_dentry+0x55/0x74
> > > [  322.845129]  vfs_statfs+0x24/0x43
> > > [  322.845132]  check_free_space+0x3c/0xe5
> > > [  322.845135]  do_acct_process+0x5d/0x5e1
> > > [  322.845136]  ? nfs_end_delegation_return+0x1cb/0x3aa
> > > [  322.845138]  ? complete+0x49/0x57
> > > [  322.845141]  acct_process+0xe5/0x105
> > > [  322.845143]  do_exit+0x781/0xa1b
> > > [  322.845145]  ? refcount_dec_and_lock+0x22/0x8c
> > > [  322.845148]  __module_put_and_exit+0x1b/0x1b
> > > [  322.845150]  nfs4_run_state_manager+0x293/0x933
> > > [  322.845152]  ? nfs4_do_reclaim+0x820/0x81c
> > > [  322.845155]  kthread+0x142/0x15f
> > > [  322.845157]  ? __kthread_create_worker+0x130/0x122
> > > [  322.845159]  ret_from_fork+0x1f/0x2a
> > > [  369.859385] INFO: task tee:1176 blocked for more than 122
> > > seconds.
> > > [  369.859391]       Not tainted 5.10.4-00021-gde017294a539-dirty
> > > #3
> > > [  369.859393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > disables this message.
> > > [  369.859395] task:tee             state:D stack:    0 pid: 1176
> > > ppid:  1173 flags:0x00000000
> > > [  369.859399] Call Trace:
> > > [  369.859407]  __schedule+0x3db/0x7ee
> > > [  369.859410]  ? io_schedule+0x70/0x6d
> > > [  369.859412]  schedule+0x68/0xdc
> > > [  369.859415]  io_schedule+0x46/0x6d
> > > [  369.859417]  bit_wait_io+0x11/0x52
> > > [  369.859420]  __wait_on_bit+0x31/0x90
> > > [  369.859422]  out_of_line_wait_on_bit+0x7e/0x80
> > > [  369.859426]  ? var_wake_function+0x30/0x27
> > > [  369.859429]  nfs_wait_on_request.part.0+0x31/0x33
> > > [  369.859431]  nfs_page_group_lock_head+0x31/0x78
> > > [  369.859433]  nfs_lock_and_join_requests+0x9d/0x26e
> > > [  369.859436]  nfs_updatepage+0x1be/0x985
> > > [  369.859439]  nfs_write_end+0x128/0x52a
> > > [  369.859443]  ? iov_iter_copy_from_user_atomic+0xe8/0x3ce
> > > [  369.859446]  generic_perform_write+0xed/0x17c
> > > [  369.859449]  nfs_file_write+0x14a/0x29f
> > > [  369.859452]  new_sync_write+0xfb/0x16b
> > > [  369.859455]  vfs_write+0x1ee/0x29a
> > > [  369.859457]  ? vfs_read+0x17b/0x198
> > > [  369.859459]  ksys_write+0x61/0xd0
> > > [  369.859462]  __x64_sys_write+0x1a/0x1c
> > > [  369.859464]  do_syscall_64+0x32/0x45
> > > [  369.859467]  entry_SYSCALL_64_after_hwframe+0x44/0x0
> > > [  369.859469] RIP: 0033:0x7f4781f323a3
> > > [  369.859471] RSP: 002b:00007ffcf8220408 EFLAGS: 00000246
> > > ORIG_RAX: 0000000000000001
> > > [  369.859474] RAX: ffffffffffffffda RBX: 0000000000000092 RCX:
> > > 00007f4781f323a3
> > > [  369.859475] RDX: 0000000000000092 RSI: 00007ffcf8220530 RDI:
> > > 0000000000000003
> > > [  369.859477] RBP: 00007ffcf8220530 R08: 0000000000000000 R09:
> > > 0000000000000001
> > > [  369.859478] R10: 0000000000400ad2 R11: 0000000000000246 R12:
> > > 0000000000000092
> > > [  369.859480] R13: 0000000002361580 R14: 0000000000000092 R15:
> > > 00007f4782201720
> > > [  369.859495] INFO: task CGenericAsyncFi:1927 blocked for more
> > > than 122 seconds.
> > > [  369.859497]       Not tainted 5.10.4-00021-gde017294a539-dirty
> > > #3
> > > [  369.859498] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > > disables this message.
> > > [  369.859499] task:CGenericAsyncFi state:D stack:    0 pid: 1927
> > > ppid:  1540 flags:0x20020000
> > > [  369.859501] Call Trace:
> > > [  369.859504]  __schedule+0x3db/0x7ee
> > > [  369.859506]  schedule+0x68/0xdc
> > > [  369.859508]  io_schedule+0x46/0x6d
> > > [  369.859510]  wait_on_page_bit_common+0xf8/0x325
> > > [  369.859512]  ?
> > > trace_raw_output_file_check_and_advance_wb_err+0x80/0x7d
> > > [  369.859515]  wait_on_page_bit+0x3f/0x41
> > > [  369.859517]  wait_on_page_writeback.part.0+0x35/0x80
> > > [  369.859519]  wait_on_page_writeback+0x27/0x29
> > > [  369.859521]  __filemap_fdatawait_range+0x88/0xd9
> > > [  369.859523]  filemap_write_and_wait_range+0x45/0x80
> > > [  369.859525]  nfs_wb_all+0x30/0x13d
> > > [  369.859528]  nfs4_file_flush+0x85/0xc0
> > > [  369.859530]  filp_close+0x3e/0x78
> > > [  369.859532]  __close_fd+0x23/0x30
> > > [  369.859534]  __ia32_sys_close+0x22/0x50
> > > [  369.859536]  __do_fast_syscall_32+0x5f/0x8e
> > > [  369.859538]  do_fast_syscall_32+0x3d/0x80
> > > [  369.859540]  entry_SYSCALL_compat_after_hwframe+0x45/0x0
> > > [  369.859541] RIP: 0023:0xf7ee6549
> > > [  369.859543] RSP: 002b:000000008c5fddb0 EFLAGS: 00200286
> > > ORIG_RAX: 0000000000000006
> > > [  369.859545] RAX: ffffffffffffffda RBX: 000000000000004d RCX:
> > > 0000000000000002
> > > [  369.859546] RDX: 0000000000000000 RSI: 00000000f7d02e70 RDI:
> > > 000000000000004d
> > > [  369.859547] RBP: 000000008c5fe110 R08: 0000000000000000 R09:
> > > 0000000000000000
> > > [  369.859548] R10: 0000000000000000 R11: 0000000000000000 R12:
> > > 0000000000000000
> > > [  369.859549] R13: 0000000000000000 R14: 0000000000000000 R15:
> > > 0000000000000000
> > > [  394.423093] nfs: server loom not responding, still trying
> > > 
> > > -- 
> > > NULL && (void)
> 
> -- 
> Trond Myklebust
> CTO, Hammerspace Inc
> 4984 El Camino Real, Suite 208
> Los Altos, CA 94022
> ​
> www.hammer.space
>