View Issue Details

IDProjectCategoryView StatusLast Update
0018124CentOS-7kernelpublic2021-03-25 11:18
ReporterPopiBrossard Assigned To 
PrioritynormalSeverityminorReproducibilityunable to reproduce
Status newResolutionopen 
OSCentOSOS Version7.9.2009 
Product Version7.9.2009 
Summary0018124: Systematic 5 second latency on every read (excepted first) of specific files in NFSv4.1
DescriptionDear maintainer,

I'm experiencing a really strange behavior with NFSv4.1 on some Centos 7 clients.
When reading some documents inside a NFS mount (not all of them seems to have the issue), the first read is normal (It takes 0.004 seconds in my infrastructure), but all the next read will take 5.004 seconds. (Like there is a timeout somewhere in the code adding a 5 second delay).

This behaviour disappear in NFSv4.0.

First, I thought it was a cache issue, so I tried to disable all possible cache in the NFS mount, but the behaviour doesn't changed (I've added 'nocto,noac,actimeo=0,nosharecache,lookupcache=none').

Then I tried to change the cache behaviour by installing FS-cache, and mouting using the "fsc"' option. Nothing changed.

In "nfs.conf" the only 5 second timeout I found was the option "rpc-timeout" in the section [gssd]. I tried changing this option to 2 seconds, and then reboot. The delay remain 5 seconds.

There is no firewall configured on the NFS client, the NFS server, and between them.

If I try reading directly the impacted file on the server ("ssh NFS_SERVER 'cat file; cat file'") there is no delay.

I've attached the logs 'rpcdebug -m nfs -s all && rpcdebug -m rpc -s all'. We can clearly see the 5 second delay. I've also attached a network capture of nfs trafic.

We can clearly see the timeout occures after the call of "nfs_update_inode". It's probably stopped by the call of "wake_up_first" RPC function.

I'm not totally sur if it's a RPC or NFS issue. Because the NFS function called is inside the kernel code I've tagged this issue "kernel". (and I don't really know which package contain the "wake_up_first" RPC function)

I've tagged priority "normal" because I can mount using NFSv4.0, so users aren't impacted.
Steps To ReproduceI wasn't able to reproduce this issue on a newly installed server, but mutliple servers are impacted.

$ mount -t nfs4 -o rw,soft,nolock,nodev,exec,nosuid,noatime,nodiratime,noacl,sec=krb5,vers=4.1 SERVER_IP:/EXPORT /tmp/test

$ time cat .Xauthority >/dev/null
cat .Xauthority > /dev/null 0,00s user 0,00s system 39% cpu 0,003 total
$ time cat .Xauthority >/dev/null
cat .Xauthority > /dev/null 0,00s user 0,00s system 0% cpu 5,005 total

If I umount and mount again, first read will take around 0.004 seconds, and second 5.004 seconds.
Additional InformationOn my Debian clients (Debian 10 / kernel 4.19) I don't see this behaviour.

I'm using "sec=krb5" for this mount. To manage Kerberos I use "sssd" with "FILE" tickets.

All needed services are UP and running (rpcbind, rpcgssd, nfsidmap, nfs-client.target)

IP are anonymised, I you see incoherent IP it's maybe due to my anonymisation process.

Currenlty, mounting using "sec=sys" is blocked, but I could try enabling it for tests if needed.
Tags3.10.0-1160.21.1.el7.x86_64, kerberos, kernel, nfsv4.1
abrt_hash
URL

Activities

PopiBrossard

PopiBrossard

2021-03-25 10:59

reporter  

capture_nfs_5sec.pcap (9,048 bytes)
nfs_5sec_latency.log (20,856 bytes)   
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up Generic cred
Mar 23 13:19:54 MY_SERVER kernel: NFS: permission(0:90/185818), mask=0x1, res=0
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_lookup_revalidate(torque/4.2.6.1) is valid
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up Generic cred
Mar 23 13:19:54 MY_SERVER kernel: NFS: permission(0:90/185819), mask=0x1, res=0
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_lookup_revalidate(4.2.6.1/bin) is valid
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up Generic cred
Mar 23 13:19:54 MY_SERVER kernel: NFS: permission(0:90/185820), mask=0x1, res=0
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_lookup_revalidate(bin/tail) is valid
Mar 23 13:19:54 MY_SERVER kernel: NFS: dentry_delete(bin/tail, 8088c)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up Generic cred
Mar 23 13:19:54 MY_SERVER kernel: NFS: permission(0:95/158335148), mask=0x81, res=0
Mar 23 13:19:54 MY_SERVER kernel: NFS: revalidating (0:95/158376155)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       new task initialized, procpid 30552
Mar 23 13:19:54 MY_SERVER kernel: RPC:       allocated task ffff98c3d9fb7e00
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 __rpc_execute flags=0x4280
Mar 23 13:19:54 MY_SERVER kernel: --> nfs41_call_sync_prepare data->seq_server ffff98c46dedc800
Mar 23 13:19:54 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
Mar 23 13:19:54 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_start nfs4 proc GETATTR (sync)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_reserve (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 reserved req ffff98c66c92c000 xid 656efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_reserveresult (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_refresh (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 looking up RPCSEC_GSS cred
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up RPCSEC_GSS cred
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 refreshing RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_refreshresult (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_allocate (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 allocated buffer of size 5280 at ffff98cc9750c000
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_bind (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_connect xprt ffff98c3f1389800 is connected
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_transmit (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 xprt_prepare_transmit
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 rpc_xdr_encode (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 marshaling RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_marshal
Mar 23 13:19:54 MY_SERVER kernel: RPC:       gss_get_mic_v2
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 using AUTH_GSS cred ffff98c3c57b43c0 to wrap rpc data
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_wrap_req
Mar 23 13:19:54 MY_SERVER kernel: encode_sequence: sessionid=1615451992:4220869208:11072:0 seqid=100 slotid=0 max_slotid=0 cache_this=0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_wrap_req returning 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 xprt_transmit(192)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_send_request(192) = 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 xmit complete
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_data_ready...
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_data_recv started
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading TCP record fragment of length 300
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading XID (4 bytes)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading reply for XID 656efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading CALL/REPLY flag (4 bytes)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       read reply XID 656efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC:       XID 656efbfa read 292 bytes
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xprt = ffff98c3f1389800, tcp_copied = 300, tcp_offset = 300, tcp_reclen = 300
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 xid 656efbfa complete (300 bytes received)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_data_recv done
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_status (status 300)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_decode (status 300)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 validating RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_validate
Mar 23 13:19:54 MY_SERVER kernel: RPC:       gss_verify_mic_v2
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_validate: gss_verify_mic succeeded.
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 using AUTH_GSS cred ffff98c3c57b43c0 to unwrap rpc data
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_type: type=0100000
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_change: change attribute=6942506972757280347
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_size: file size=100
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fsid: fsid=(0x1/0x0)
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fileid: fileid=158376155
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fs_locations: fs_locations done, error = 0
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_mode: file mode=0600
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_nlink: nlink=1
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_owner: uid=1412034074
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_group: gid=1332
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_rdev: rdev=(0x0:0x0)
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_space_used: space used=4096
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_access: atime=1616428378
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_metadata: ctime=1616428367
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_modify: mtime=1616428367
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_mounted_on_fileid: fileid=158376155
Mar 23 13:19:54 MY_SERVER kernel: decode_getfattr_attrs: xdr returned 0
Mar 23 13:19:54 MY_SERVER kernel: decode_getfattr_generic: xdr returned 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 gss_unwrap_resp returning 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 call_decode result 0
Mar 23 13:19:54 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
Mar 23 13:19:54 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:54 MY_SERVER kernel: nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 23 13:19:54 MY_SERVER kernel: nfs41_sequence_process: Error 0 free the slot
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:54 MY_SERVER kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 return 0, status 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 release task
Mar 23 13:19:54 MY_SERVER kernel: RPC:       freeing buffer of size 5280 at ffff98cc9750c000
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 release request ffff98c66c92c000
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389b20 "xprt_backlog")
Mar 23 13:19:54 MY_SERVER kernel: RPC:       rpc_release_client(ffff98c2b66ce400)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39772 freeing task
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_update_inode(0:95/158376155 fh_crc=0x7088327b ct=1 info=0x427e7f)
Mar 23 13:19:54 MY_SERVER kernel: NFS: (0:95/158376155) revalidation complete
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_lookup_revalidate(user/.Xauthority) is valid
Mar 23 13:19:54 MY_SERVER kernel: NFS: open file(user/.Xauthority)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       looking up Generic cred
Mar 23 13:19:54 MY_SERVER kernel: --> nfs_put_client({2})
Mar 23 13:19:54 MY_SERVER kernel: RPC:       new task initialized, procpid 30552
Mar 23 13:19:54 MY_SERVER kernel: RPC:       allocated task ffff98c3d9fb7c00
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 __rpc_execute flags=0x4281
Mar 23 13:19:54 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
Mar 23 13:19:54 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_start nfs4 proc OPEN_NOATTR (async)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_reserve (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 reserved req ffff98c66c92c000 xid 666efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_reserveresult (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_refresh (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 refreshing RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_refreshresult (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_allocate (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 allocated buffer of size 8272 at ffff98c3d63e8000
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_bind (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_connect xprt ffff98c3f1389800 is connected
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_transmit (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 xprt_prepare_transmit
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 rpc_xdr_encode (status 0)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 marshaling RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_marshal
Mar 23 13:19:54 MY_SERVER kernel: RPC:       gss_get_mic_v2
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 using AUTH_GSS cred ffff98c3c57b43c0 to wrap rpc data
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_wrap_req
Mar 23 13:19:54 MY_SERVER kernel: encode_sequence: sessionid=1615451992:4220869208:11072:0 seqid=101 slotid=0 max_slotid=0 cache_this=1
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_wrap_req returning 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 xprt_transmit(260)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_send_request(260) = 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 xmit complete
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_data_ready...
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_data_recv started
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading TCP record fragment of length 376
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading XID (4 bytes)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading reply for XID 666efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC:       reading CALL/REPLY flag (4 bytes)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       read reply XID 666efbfa
Mar 23 13:19:54 MY_SERVER kernel: RPC:       XID 666efbfa read 368 bytes
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xprt = ffff98c3f1389800, tcp_copied = 376, tcp_offset = 376, tcp_reclen = 376
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 xid 666efbfa complete (376 bytes received)
Mar 23 13:19:54 MY_SERVER kernel: RPC:       xs_tcp_data_recv done
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_status (status 376)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_decode (status 376)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 validating RPCSEC_GSS cred ffff98c3c57b43c0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_validate
Mar 23 13:19:54 MY_SERVER kernel: RPC:       gss_verify_mic_v2
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_validate: gss_verify_mic succeeded.
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 using AUTH_GSS cred ffff98c3c57b43c0 to unwrap rpc data
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_type: type=0100000
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_change: change attribute=6942506972757280347
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_size: file size=100
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fsid: fsid=(0x1/0x0)
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fileid: fileid=158376155
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_fs_locations: fs_locations done, error = 0
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_mode: file mode=0600
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_nlink: nlink=1
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_owner: uid=-2
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_group: gid=-2
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_rdev: rdev=(0x0:0x0)
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_space_used: space used=4096
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_access: atime=1616428378
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_metadata: ctime=1616428367
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_time_modify: mtime=1616428367
Mar 23 13:19:54 MY_SERVER kernel: decode_attr_mounted_on_fileid: fileid=158376155
Mar 23 13:19:54 MY_SERVER kernel: decode_getfattr_attrs: xdr returned 0
Mar 23 13:19:54 MY_SERVER kernel: decode_getfattr_generic: xdr returned 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 gss_unwrap_resp returning 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 call_decode result 0
Mar 23 13:19:54 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
Mar 23 13:19:54 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:54 MY_SERVER kernel: nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 23 13:19:54 MY_SERVER kernel: nfs41_sequence_process: Error 0 free the slot
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 return 0, status 0
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 release task
Mar 23 13:19:54 MY_SERVER kernel: RPC:       freeing buffer of size 8272 at ffff98c3d63e8000
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 release request ffff98c66c92c000
Mar 23 13:19:54 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389b20 "xprt_backlog")
Mar 23 13:19:54 MY_SERVER kernel: RPC:       rpc_release_client(ffff98c2b66ce400)
Mar 23 13:19:54 MY_SERVER kernel: RPC: 39773 freeing task
Mar 23 13:19:54 MY_SERVER kernel: NFS: nfs_update_inode(0:95/158376155 fh_crc=0x7088327b ct=3 info=0x427e7f)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:59 MY_SERVER kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mar 23 13:19:59 MY_SERVER kernel: NFS: read(user/.Xauthority, 1048576@0)
Mar 23 13:19:59 MY_SERVER kernel: NFS: read(user/.Xauthority, 1048576@100)
Mar 23 13:19:59 MY_SERVER kernel: NFS: flush(user/.Xauthority)
Mar 23 13:19:59 MY_SERVER kernel: NFS: release(user/.Xauthority)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       new task initialized, procpid 30552
Mar 23 13:19:59 MY_SERVER kernel: RPC:       allocated task ffff98c3c9390e00
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 __rpc_execute flags=0x4281
Mar 23 13:19:59 MY_SERVER kernel: nfs4_close_prepare: begin!
Mar 23 13:19:59 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=30
Mar 23 13:19:59 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 23 13:19:59 MY_SERVER kernel: nfs4_close_prepare: done!
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_start nfs4 proc CLOSE (async)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_reserve (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 reserved req ffff98c66c92c000 xid 676efbfa
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_reserveresult (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_refresh (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 refreshing RPCSEC_GSS cred ffff98c3d6be4cc0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_refreshresult (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_allocate (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 allocated buffer of size 6412 at ffff98c3eab90000
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_bind (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_connect xprt ffff98c3f1389800 is connected
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_transmit (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 xprt_prepare_transmit
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 rpc_xdr_encode (status 0)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 marshaling RPCSEC_GSS cred ffff98c3d6be4cc0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_marshal
Mar 23 13:19:59 MY_SERVER kernel: RPC:       gss_get_mic_v2
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 using AUTH_GSS cred ffff98c3d6be4cc0 to wrap rpc data
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_wrap_req
Mar 23 13:19:59 MY_SERVER kernel: encode_sequence: sessionid=1615451992:4220869208:11072:0 seqid=102 slotid=0 max_slotid=0 cache_this=1
Mar 23 13:19:59 MY_SERVER kernel: RPC:       gss_get_mic_v2
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_wrap_req returning 0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 xprt_transmit(256)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       xs_tcp_send_request(256) = 0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 xmit complete
Mar 23 13:19:59 MY_SERVER kernel: RPC:       xs_data_ready...
Mar 23 13:19:59 MY_SERVER kernel: RPC:       xs_tcp_data_recv started
Mar 23 13:19:59 MY_SERVER kernel: RPC:       reading TCP record fragment of length 156
Mar 23 13:19:59 MY_SERVER kernel: RPC:       reading XID (4 bytes)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       reading reply for XID 676efbfa
Mar 23 13:19:59 MY_SERVER kernel: RPC:       reading CALL/REPLY flag (4 bytes)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       read reply XID 676efbfa
Mar 23 13:19:59 MY_SERVER kernel: RPC:       XID 676efbfa read 148 bytes
Mar 23 13:19:59 MY_SERVER kernel: RPC:       xprt = ffff98c3f1389800, tcp_copied = 156, tcp_offset = 156, tcp_reclen = 156
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 xid 676efbfa complete (156 bytes received)
Mar 23 13:19:59 MY_SERVER kernel: RPC:       xs_tcp_data_recv done
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389990 "xprt_sending")
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_status (status 156)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_decode (status 156)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 validating RPCSEC_GSS cred ffff98c3d6be4cc0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_validate
Mar 23 13:19:59 MY_SERVER kernel: RPC:       gss_verify_mic_v2
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_validate: gss_verify_mic succeeded.
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 using AUTH_GSS cred ffff98c3d6be4cc0 to unwrap rpc data
Mar 23 13:19:59 MY_SERVER kernel: RPC:       gss_verify_mic_v2
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 gss_unwrap_resp returning -116
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 call_decode result -116
Mar 23 13:19:59 MY_SERVER kernel: nfs4_close_done: begin!
Mar 23 13:19:59 MY_SERVER kernel: --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=30
Mar 23 13:19:59 MY_SERVER kernel: <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:59 MY_SERVER kernel: nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 23 13:19:59 MY_SERVER kernel: nfs41_sequence_process: Error 0 free the slot
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98ca9cb304d8 "ForeChannel Slot table")
Mar 23 13:19:59 MY_SERVER kernel: nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mar 23 13:19:59 MY_SERVER kernel: nfs4_close_done: done, ret = 0!
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 return 0, status 0
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 release task
Mar 23 13:19:59 MY_SERVER kernel: RPC:       freeing buffer of size 6412 at ffff98c3eab90000
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 release request ffff98c66c92c000
Mar 23 13:19:59 MY_SERVER kernel: RPC:       wake_up_first(ffff98c3f1389b20 "xprt_backlog")
Mar 23 13:19:59 MY_SERVER kernel: RPC:       rpc_release_client(ffff98c66c92d600)
Mar 23 13:19:59 MY_SERVER kernel: RPC: 39774 freeing task
Mar 23 13:19:59 MY_SERVER kernel: NFS: dentry_delete(user/.Xauthority, 40808cc)
Mar 23 13:19:59 MY_SERVER kernel: nfs4_renew_state: start
Mar 23 13:19:59 MY_SERVER kernel: nfs4_schedule_state_renewal: requeueing work. Lease period = 60
Mar 23 13:19:59 MY_SERVER kernel: nfs4_renew_state: done
nfs_5sec_latency.log (20,856 bytes)   
PopiBrossard

PopiBrossard

2021-03-25 11:18

reporter   ~0038330

I forgot, here is my client NFS configuration:

$ grep -v '#' /etc/nfs.conf
[gssd]
 rpc-timeout=2

$ grep -v '#' /etc/sysconfig/nfs
GSS_USE_PROXY="yes"
SECURE_NFS=yes

#BLKMAPDARGS=""
SECURE_NFS=yes

Issue History

Date Modified Username Field Change
2021-03-25 10:59 PopiBrossard New Issue
2021-03-25 10:59 PopiBrossard Tag Attached: 3.10.0-1160.21.1.el7.x86_64
2021-03-25 10:59 PopiBrossard Tag Attached: kerberos
2021-03-25 10:59 PopiBrossard Tag Attached: kernel
2021-03-25 10:59 PopiBrossard Tag Attached: nfsv4.1
2021-03-25 10:59 PopiBrossard File Added: capture_nfs_5sec.pcap
2021-03-25 10:59 PopiBrossard File Added: nfs_5sec_latency.log
2021-03-25 11:18 PopiBrossard Note Added: 0038330