Thanks, Chunk.
Suggested trace-cmd report from the client follows. Last 3 lines appear
salient, but I've included the full report just in case.
cpus=4
ls-969 [003] ..... 270.318649: nfs_getattr_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.318651: nfs_getattr_exit: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.318654: nfs_revalidate_inode_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.318658: rpc_task_begin:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4
status=0 action=0x0
ls-969 [003] ..... 270.318658: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.318660: nfs4_setup_sequence:
session=0x5988ad3c slot_nr=0 seq_nr=24 highest_used_slotid=0
ls-969 [003] ..... 270.318661: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.318661: rpc_request:
task:00000006@00000005 nfsv4 GETATTR (sync)
ls-969 [003] ..... 270.318662: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.318663: xprt_reserve:
task:00000006@00000005 xid=0x79569c7a
ls-969 [003] ..... 270.318663: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.318663: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refresh
rpc.gssd-613 [001] ..... 270.318690: rpcgss_upcall_msg:
msg='mech=krb5 uid=591200003 enctypes=20,19,18,17'
rpc.gssd-970 [002] ..... 270.326582: rpcgss_context:
win_size=128 expiry=4316009978 now=4294959728 timeout=84201
[email protected]
ls-969 [003] ...1. 270.326598: rpcgss_ctx_init:
cred=0xffff8895c5989900 service=integrity principal='(null)'
ls-969 [003] ..... 270.326600: rpcgss_upcall_result: for uid
591200003, result=0
ls-969 [003] ..... 270.326601: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326601: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326603: rpc_buf_alloc:
task:00000006@00000005 callsize=1844 recvsize=2704 status=0
ls-969 [003] ..... 270.326603: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326604: rpcgss_seqno:
task:00000006@00000005 xid=0x79569c7a seqno=1
ls-969 [003] ..... 270.326611: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326611: xprt_reserve_xprt:
task:00000006@00000005 snd_task:00000006
ls-969 [003] ..... 270.326612: rpcgss_need_reencode:
task:00000006@00000005 xid=0x79569c7a rq_seqno=1 seq_xmit=0 reencode unneeded
ls-969 [003] ..... 270.326612: rpc_xdr_sendto:
task:00000006@00000005 head=[0xffff8895c29fe008,260] page=0(0) tail=[(nil),0]
len=260
ls-969 [003] ..... 270.326627: xprt_transmit:
task:00000006@00000005 xid=0x79569c7a seqno=1 status=0
ls-969 [003] ...1. 270.326628: xprt_release_xprt:
task:00000006@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326629: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326629: rpc_task_sleep:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326630: rpc_task_sync_sleep:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.326754: xs_data_ready:
peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.326762: xprt_lookup_rqst:
peer=[10.108.2.102]:2049 xid=0x79569c7a status=0
kworker/u16:0-12 [001] ...2. 270.326764: rpc_task_wakeup:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.326768: xs_stream_read_request:
peer=[10.108.2.102]:2049 xid=0x79569c7a copied=384 reclen=384 offset=384
kworker/u16:0-12 [001] ..... 270.326769: xs_stream_read_data:
peer=[10.108.2.102]:2049 err=-11 total=388
ls-969 [003] ..... 270.326775: rpc_task_sync_wake:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326775: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.326775: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326775: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.326776: rpc_xdr_recvfrom:
task:00000006@00000005 head=[0xffff8895c29fe73c,2704] page=0(0) tail=[(nil),0]
len=384
ls-969 [003] ..... 270.326785: nfs4_map_name_to_uid: error=0
(OK) id=591200000 [email protected]
ls-969 [003] ..... 270.326786: nfs4_map_group_to_gid: error=0
(OK) id=591200004 [email protected]
ls-969 [003] ..... 270.326787: rpc_task_run_action:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326787: rpc_task_end:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326788: rpc_stats_latency:
task:00000006@00000005 xid=0x79569c7a nfsv4 GETATTR backlog=7956 rtt=149
execute=8131 xprt_id=1
ls-969 [003] ..... 270.326789: rpc_task_call_done:
task:00000006@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=nfs41_call_sync_done
ls-969 [003] ..... 270.326789: nfs4_sequence_done: error=0
(OK) session=0x5988ad3c slot_nr=0 seq_nr=24 highest_slotid=63
target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.326791: xprt_release_xprt:
task:00000006@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326793: nfs4_getattr: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c
valid=TYPE|MODE|NLINK|OWNER|GROUP|RDEV|SIZE|FSID|FILEID|ATIME|MTIME|CTIME|CHANGE|BTIME|0x400200
ls-969 [003] ...1. 270.326795: nfs_refresh_inode_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ...1. 270.326797: nfs_set_cache_invalid: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ...1. 270.326797: nfs_refresh_inode_exit:
error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31
size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326798: nfs_revalidate_inode_exit:
error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31
size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326799: nfs_access_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.326801: rpc_task_begin:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4
status=0 action=0x0
ls-969 [003] ..... 270.326801: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.326801: nfs4_setup_sequence:
session=0x5988ad3c slot_nr=0 seq_nr=25 highest_used_slotid=0
ls-969 [003] ..... 270.326802: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.326802: rpc_request:
task:00000007@00000005 nfsv4 ACCESS (sync)
ls-969 [003] ..... 270.326802: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.326803: xprt_reserve:
task:00000007@00000005 xid=0x7a569c7a
ls-969 [003] ..... 270.326803: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.326803: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refresh
ls-969 [003] ..... 270.326804: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326804: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326804: rpc_buf_alloc:
task:00000007@00000005 callsize=1836 recvsize=2712 status=0
ls-969 [003] ..... 270.326804: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326805: rpcgss_seqno:
task:00000007@00000005 xid=0x7a569c7a seqno=2
ls-969 [003] ..... 270.326807: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326807: xprt_reserve_xprt:
task:00000007@00000005 snd_task:00000007
ls-969 [003] ..... 270.326808: rpcgss_need_reencode:
task:00000007@00000005 xid=0x7a569c7a rq_seqno=2 seq_xmit=1 reencode unneeded
ls-969 [003] ..... 270.326808: rpc_xdr_sendto:
task:00000007@00000005 head=[0xffff8895c29fe008,268] page=0(0) tail=[(nil),0]
len=268
ls-969 [003] ..... 270.326816: xprt_transmit:
task:00000007@00000005 xid=0x7a569c7a seqno=2 status=0
ls-969 [003] ...1. 270.326817: xprt_release_xprt:
task:00000007@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326817: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326817: rpc_task_sleep:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326817: rpc_task_sync_sleep:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.326882: xs_data_ready:
peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.326885: xprt_lookup_rqst:
peer=[10.108.2.102]:2049 xid=0x7a569c7a status=0
kworker/u16:0-12 [001] ...2. 270.326885: rpc_task_wakeup:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.326888: xs_stream_read_request:
peer=[10.108.2.102]:2049 xid=0x7a569c7a copied=260 reclen=260 offset=260
kworker/u16:0-12 [001] ..... 270.326888: xs_stream_read_data:
peer=[10.108.2.102]:2049 err=-11 total=264
ls-969 [003] ..... 270.326895: rpc_task_sync_wake:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326895: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.326895: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.326895: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.326895: rpc_xdr_recvfrom:
task:00000007@00000005 head=[0xffff8895c29fe734,2712] page=0(0) tail=[(nil),0]
len=260
ls-969 [003] ..... 270.326898: rpc_task_run_action:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326898: rpc_task_end:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_exit_task
ls-969 [003] ..... 270.326899: rpc_stats_latency:
task:00000007@00000005 xid=0x7a569c7a nfsv4 ACCESS backlog=7 rtt=76 execute=98
xprt_id=1
ls-969 [003] ..... 270.326899: rpc_task_call_done:
task:00000007@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=nfs41_call_sync_done
ls-969 [003] ..... 270.326899: nfs4_sequence_done: error=0
(OK) session=0x5988ad3c slot_nr=0 seq_nr=25 highest_slotid=63
target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.326900: xprt_release_xprt:
task:00000007@00000005 snd_task:ffffffff
ls-969 [003] ...1. 270.326901: nfs_refresh_inode_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ...1. 270.326901: nfs_set_cache_invalid: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ...1. 270.326901: nfs_refresh_inode_exit:
error=0 (OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31
size=4096 cache_validity=0x0 () nfs_flags=0x0 ()
ls-969 [003] ..... 270.326902: nfs4_access: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c
ls-969 [003] ..... 270.326903: nfs_access_exit: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x0 () nfs_flags=0x4 (ACL_LRU_SET) mask=0x24 permitted=0x7
ls-969 [003] ..... 270.326907: nfs_getattr_enter:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cache_validity=0x0 ()
ls-969 [003] ..... 270.326908: nfs_getattr_exit: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x0 () nfs_flags=0x4 (ACL_LRU_SET)
ls-969 [003] ..... 270.326928: nfs_readdir_cache_fill:
fileid=00:2d:262146 fhandle=0xad8c294c version=31 cookie=0000000000000000:0x0
cache_index=0 dtsize=4096
ls-969 [003] ..... 270.326931: rpc_task_begin:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF runstate=0x4
status=0 action=0x0
ls-969 [003] ..... 270.326931: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=rpc_prepare_task
ls-969 [003] ..... 270.326931: nfs4_setup_sequence:
session=0x5988ad3c slot_nr=0 seq_nr=26 highest_used_slotid=0
ls-969 [003] ..... 270.326931: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_start
ls-969 [003] ..... 270.326932: rpc_request:
task:00000008@00000005 nfsv4 READDIR (sync)
ls-969 [003] ..... 270.326932: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserve
ls-969 [003] ..... 270.326932: xprt_reserve:
task:00000008@00000005 xid=0x7b569c7a
ls-969 [003] ..... 270.326932: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_reserveresult
ls-969 [003] ..... 270.326932: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refresh
ls-969 [003] ..... 270.326933: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_refreshresult
ls-969 [003] ..... 270.326933: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_allocate
ls-969 [003] ..... 270.326933: rpc_buf_alloc:
task:00000008@00000005 callsize=3932 recvsize=176 status=0
ls-969 [003] ..... 270.326933: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_encode
ls-969 [003] ..... 270.326934: rpcgss_seqno:
task:00000008@00000005 xid=0x7b569c7a seqno=3
ls-969 [003] ..... 270.326936: rpc_xdr_reply_pages:
task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88)
tail=[0xffff8895c29feff0,36] len=0
ls-969 [003] ..... 270.326937: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|NORTO|CRED_NOREF
runstate=RUNNING|0x1c status=0 action=call_transmit
ls-969 [003] ...1. 270.326937: xprt_reserve_xprt:
task:00000008@00000005 snd_task:00000008
ls-969 [003] ..... 270.326937: rpcgss_need_reencode:
task:00000008@00000005 xid=0x7b569c7a rq_seqno=3 seq_xmit=2 reencode unneeded
ls-969 [003] ..... 270.326938: rpc_xdr_sendto:
task:00000008@00000005 head=[0xffff8895c29fe008,284] page=0(0) tail=[(nil),0]
len=284
ls-969 [003] ..... 270.326946: xprt_transmit:
task:00000008@00000005 xid=0x7b569c7a seqno=3 status=0
ls-969 [003] ...1. 270.326947: xprt_release_xprt:
task:00000008@00000005 snd_task:ffffffff
ls-969 [003] ..... 270.326947: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 action=call_transmit_status
ls-969 [003] ...2. 270.326947: rpc_task_sleep:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x14 status=0 timeout=0 queue=xprt_pending
ls-969 [003] ..... 270.326947: rpc_task_sync_sleep:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x16 status=0 action=call_status
<idle>-0 [001] ..s2. 270.327040: xs_data_ready:
peer=[10.108.2.102]:2049
kworker/u16:0-12 [001] ...1. 270.327048: xprt_lookup_rqst:
peer=[10.108.2.102]:2049 xid=0x7b569c7a status=0
kworker/u16:0-12 [001] ...2. 270.327050: rpc_task_wakeup:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=0x6 status=0 timeout=15000 queue=xprt_pending
kworker/u16:0-12 [001] ..... 270.327054: xs_stream_read_request:
peer=[10.108.2.102]:2049 xid=0x7b569c7a copied=988 reclen=988 offset=988
kworker/u16:0-12 [001] ..... 270.327055: xs_stream_read_data:
peer=[10.108.2.102]:2049 err=-11 total=992
ls-969 [003] ..... 270.327062: rpc_task_sync_wake:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.327062: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=xprt_timer
ls-969 [003] ..... 270.327063: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_status
ls-969 [003] ..... 270.327063: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=0 action=call_decode
ls-969 [003] ..... 270.327063: rpc_xdr_recvfrom:
task:00000008@00000005 head=[0xffff8895c29fef64,140] page=4008(88)
tail=[0xffff8895c29feff0,36] len=988
ls-969 [003] ..... 270.327067: rpc_xdr_overflow:
task:00000008@00000005 nfsv4 READDIR requested=8 p=0xffff8895c29fefec
end=0xffff8895c29feff0
xdr=[0xffff8895c29fef64,140]/4008/[0xffff8895c29feff0,36]/988
ls-969 [003] ..... 270.327068: rpc_task_run_action:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=-5 action=rpc_exit_task
ls-969 [003] ..... 270.327068: rpc_task_end:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=-5 action=rpc_exit_task
ls-969 [003] ..... 270.327068: rpc_stats_latency:
task:00000008@00000005 xid=0x7b569c7a nfsv4 READDIR backlog=7 rtt=110
execute=137 xprt_id=1
ls-969 [003] ..... 270.327068: rpc_task_call_done:
task:00000008@00000005 flags=MOVEABLE|DYNAMIC|SENT|NORTO|CRED_NOREF
runstate=RUNNING|0x4 status=-5 action=nfs41_call_sync_done
ls-969 [003] ..... 270.327068: nfs4_sequence_done: error=0
(OK) session=0x5988ad3c slot_nr=0 seq_nr=26 highest_slotid=63
target_highest_slotid=63 status_flags=0x0 ()
ls-969 [003] ...1. 270.327069: xprt_release_xprt:
task:00000008@00000005 snd_task:ffffffff
ls-969 [003] ...1. 270.327070: nfs_set_cache_invalid: error=0
(OK) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31 size=4096
cache_validity=0x4 (INVALID_ATIME) nfs_flags=0x4 (ACL_LRU_SET)
ls-969 [003] ..... 270.327070: nfs4_readdir: error=-5
(EIO) fileid=00:2d:262146 fhandle=0xad8c294c
ls-969 [003] ..... 270.327071: nfs_readdir_cache_fill_done:
error=-5 (IO) fileid=00:2d:262146 fhandle=0xad8c294c type=4 (DIR) version=31
size=4096 cache_validity=0x4 (INVALID_ATIME) nfs_flags=0x4 (ACL_LRU_SET)
TWR
