NFS服务运行一段时间后导致客户端被卡死的问题分析及解决

最新推荐文章于 2024-07-18 06:00:00 发布

weixin_34205826

最新推荐文章于 2024-07-18 06:00:00 发布

阅读量5.5k

点赞数 4

CC 4.0 BY-SA版权

文章标签：移动开发运维开发工具

原文链接：https://my.oschina.net/LastRitter/blog/1542610

本文详细记录了一起NFS服务在运行一段时间后导致客户端被卡死的问题。通过分析NFS的基本架构和原理，发现问题是由于在服务端对NFS导出目录进行强制umount操作后，未执行`exportfs -av`或重启NFS服务，导致NFS客户端在文件系统变动时出现NFS3ERR_DELAY错误。解决方案包括正确处理umount和mount操作，调整NFS超时和重试设置，以及改进存储设备有效性检测方法。

摘要生成于 C知道，由 DeepSeek-R1 满血版支持，前往体验 >

2019独角兽企业重金招聘Python工程师标准>>>

问题描述

在现场环境中，多个节点上运行CentOS7 X64发行版，其中一个节点上运行NFS服务，其他节点作为NFS客户端，共享访问NFS服务节点上的文件。系统上还运行有其他很多软件，但是由于系统庞大，参与开发的人员较多，我们无法通过询问得知具体情况（通过多次询问，才得知他们NFS的服务端根目录使用过多次bind操作）。但是系统中出现NFS服务有时候运行30分钟左右会导致NFS客户端被卡死，且无法通过Kill -9终止的现象，期间也没有错误日志，也无法在现场环境进行。

初步分析

在此之前，我们对NFS的了解也仅限于简单的使用，所以此时我们应快速了解其基本架构、原理，以便进一步分析。
经初步资料查阅发下：NFS是一个网络文件系统，其关键部分运行在内核中，用户态只有一个简单的守护进程。多节点之间使用基于TCP协议的Sun RPC进行通讯，使用portmap服务进行服务发现。
使用kill -9都无法终止程序，说明程序是在内核态产生死锁。对于上层而言，NFS和普通文件系统并无差别，关键应该是在执行底层的RPC调用时被阻塞。根据经验，我们可以初步推测，这个死锁应该是发生在RPC远程调用的等待时。
进一步查阅资料发现：NFS的mount有soft和hard模式之分，其错误时等待方式不同，问题是否出在这里？下面我们将从这里入手，并配合一定的测试，来初步了解其特性和调试手段，然后再进行有针对性的测试来暴露问题，最终找到问题及其解决方法。

获取源码包

准备环境

$ yum install rpmdevtools yum-utils
$ rpmdev-setuptree

查看软件包信息

$ which nfsstat 
/usr/sbin/nfsstat

$ rpm -qf /usr/sbin/nfsstat
nfs-utils-1.3.0-0.21.el7_2.1.x86_64

$ yum info nfs-utils
...
已安装的软件包
名称    ：nfs-utils
架构    ：x86_64
时期       ：1
版本    ：1.3.0
发布    ：0.21.el7_2.1
大小    ：1.0 M
源    ：installed
来自源：updates
简介    ： NFS utilities and supporting clients and daemons for the kernel NFS server
网址    ：http://sourceforge.net/projects/nfs
协议    ： MIT and GPLv2 and GPLv2+ and BSD
描述    ： The nfs-utils package provides a daemon for the kernel NFS server and
         : related tools, which provides a much higher level of performance than the
         : traditional Linux NFS server used by most users.
         : 
         : This package also contains the showmount program.  Showmount queries the
         : mount daemon on a remote host for information about the NFS (Network File
         : System) server on the remote host.  For example, showmount can display the
         : clients which are mounted on that host.
         : 
         : This package also contains the mount.nfs and umount.nfs program.
...

下载源码包

$ cd ~/rpmbuild/
$ yumdownloader --source nfs-utils

$ rpm -ivh nfs-utils-1.3.0-0.21.el7_2.1.src.rpm

编译源码包

提取源码

$ yum install libevent-devel libnfsidmap-devel libtirpc-devel fedfs-utils-devel
$ rpmbuild -bp SPECS/nfs-utils.spec

$ mkdir -pv /opt/nfs
$ cp -rv BUILD/nfs-utils-1.3.0/ /opt/nfs/

配置

$ cd /opt/nfs/nfs-utils-1.3.0/
$ ./autogen.sh
$ ./configure \
	--build=x86_64-redhat-linux-gnu \
	--host=x86_64-redhat-linux-gnu \
	--disable-dependency-tracking \
	--enable-mountconfig \
	--enable-ipv6 \
	--enable-libmount-mount \
	--prefix=/opt/nfs/target \
'CFLAGS=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic -fpie -Wl,-z,relro,-z,now -D_FILE_OFFSET_BITS=64' \
CPPFLAGS= \
LDFLAGS=-pie

编译安装

$ make all
$ make install

查看目标文件

$ cd ../target/
$ tree
.
├── sbin
│   ├── blkmapd			pNFS的块映射服务。
│   ├── exportfs			NFS文件系统导出。
│   ├── mountstats		查看mount的文件系统的统计信息。
│   ├── nfsdcltrack		NFS状态持久化工具。
│   ├── nfsidmap			NFS的ID映射服务。
│   ├── nfsiostat		查看IO状态。
│   ├── nfsstat			查看NFS状态。
│   ├── rpcdebug			调试功能能设置工具。
│   ├── rpc.gssd			GSS认证服务。
│   ├── rpc.idmapd
│   ├── rpc.mountd
│   ├── rpc.nfsd
│   ├── rpc.statd
│   ├── rpc.svcgssd
│   ├── showmount		显示NFS服务器mount信息。
│   ├── sm-notify		向NFS端点发送重启信息。
│   └── start-statd
└── share
    └── man
        ├── man5
        │   ├── exports.5
        │   ├── nfs.5
        │   └── nfsmount.conf.5
        ├── man7
        │   └── nfsd.7
        └── man8
            ├── blkmapd.8
            ├── exportfs.8
            ├── gssd.8
            ├── idmapd.8
            ├── mountd.8
            ├── mount.nfs.8
            ├── mountstats.8
            ├── nfsd.8
            ├── nfsdcltrack.8
            ├── nfsidmap.8
            ├── nfsiostat.8
            ├── nfsstat.8
            ├── rpcdebug.8
            ├── rpc.gssd.8 -> gssd.8
            ├── rpc.idmapd.8 -> idmapd.8
            ├── rpc.mountd.8 -> mountd.8
            ├── rpc.nfsd.8 -> nfsd.8
            ├── rpc.sm-notify.8 -> sm-notify.8
            ├── rpc.statd.8 -> statd.8
            ├── rpc.svcgssd.8 -> svcgssd.8
            ├── showmount.8
            ├── sm-notify.8
            ├── statd.8
            ├── svcgssd.8
            └── umount.nfs.8

6 directories, 46 files

hard与soft模式异常测试

NFS服务器为192.168.195.136，配置如下：

$ vi /etc/exports
/opt *(rw,sync,no_root_squash,no_subtree_check)
/opt/android *(rw,sync,no_root_squash,no_subtree_check)

服务端开启NFS调试信息：

$ rpcdebug -m nfsd -s all

客户端开启NFS调试信息：

$ rpcdebug -m nfs -s all

使用hard模式mount

$ mount -t nfs 192.168.195.136:/opt /opt -osoft,timeo=5,retrans=2

网络正常时，查看ls命令的日志

$ ls /opt
$ dmesg -c
[1109522.499944] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109522.499947] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109522.500454] decode_attr_files_avail: files avail=5126859
[1109522.500456] decode_attr_files_free: files free=5126859
[1109522.500457] decode_attr_files_total: files total=5242880
[1109522.500458] decode_attr_space_avail: space avail=48261320704
[1109522.500458] decode_attr_space_free: space free=52573065216
[1109522.500459] decode_attr_space_total: space total=84417077248
[1109522.500460] decode_statfs: xdr returned 0!
[1109522.500462] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.467099] NFS: revalidating (0:44/2)
[1109523.467108] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.467109] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.467617] decode_attr_type: type=040000
[1109523.467619] decode_attr_change: change attribute=6364596956768490675
[1109523.467620] decode_attr_size: file size=4096
[1109523.467621] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.467621] decode_attr_fileid: fileid=2
[1109523.467622] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.467623] decode_attr_mode: file mode=0755
[1109523.467624] decode_attr_nlink: nlink=21
[1109523.467626] decode_attr_owner: uid=0
[1109523.467626] decode_attr_group: gid=0
[1109523.467627] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.467627] decode_attr_space_used: space used=4096
[1109523.467628] decode_attr_time_access: atime=1481873345
[1109523.467629] decode_attr_time_metadata: ctime=1481873206
[1109523.467629] decode_attr_time_modify: mtime=1481873206
[1109523.467630] decode_attr_mounted_on_fileid: fileid=524289
[1109523.467630] decode_getfattr_attrs: xdr returned 0
[1109523.467631] decode_getfattr_generic: xdr returned 0
[1109523.467633] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.467639] NFS: nfs_update_inode(0:44/2 fh_crc=0x41dc8638 ct=2 info=0x427e7f)
[1109523.467641] NFS: (0:44/2) revalidation complete
[1109523.467658] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.467659] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.468301] decode_attr_type: type=00
[1109523.468302] decode_attr_change: change attribute=6364596956768490675
[1109523.468303] decode_attr_size: file size=4096
[1109523.468304] decode_attr_fsid: fsid=(0x0/0x0)
[1109523.468305] decode_attr_fileid: fileid=0
[1109523.468305] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.468306] decode_attr_mode: file mode=00
[1109523.468306] decode_attr_nlink: nlink=1
[1109523.468307] decode_attr_owner: uid=-2
[1109523.468308] decode_attr_group: gid=-2
[1109523.468308] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.468309] decode_attr_space_used: space used=0
[1109523.468309] decode_attr_time_access: atime=0
[1109523.468333] decode_attr_time_metadata: ctime=1481873206
[1109523.468335] decode_attr_time_modify: mtime=1481873206
[1109523.468335] decode_attr_mounted_on_fileid: fileid=0
[1109523.468336] decode_getfattr_attrs: xdr returned 0
[1109523.468337] decode_getfattr_generic: xdr returned 0
[1109523.468338] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.468343] NFS: nfs_update_inode(0:44/2 fh_crc=0x41dc8638 ct=2 info=0x26040)
[1109523.468346] NFS: permission(0:44/2), mask=0x24, res=0
[1109523.468348] NFS: open dir(/)
[1109523.468349] NFS: revalidating (0:44/2)
[1109523.468351] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.468352] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.468563] decode_attr_type: type=040000
[1109523.468564] decode_attr_change: change attribute=6364596956768490675
[1109523.468565] decode_attr_size: file size=4096
[1109523.468566] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.468566] decode_attr_fileid: fileid=2
[1109523.468567] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.468567] decode_attr_mode: file mode=0755
[1109523.468568] decode_attr_nlink: nlink=21
[1109523.468569] decode_attr_owner: uid=0
[1109523.468569] decode_attr_group: gid=0
[1109523.468570] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.468571] decode_attr_space_used: space used=4096
[1109523.468571] decode_attr_time_access: atime=1481873345
[1109523.468572] decode_attr_time_metadata: ctime=1481873206
[1109523.468572] decode_attr_time_modify: mtime=1481873206
[1109523.468573] decode_attr_mounted_on_fileid: fileid=524289
[1109523.468573] decode_getfattr_attrs: xdr returned 0
[1109523.468574] decode_getfattr_generic: xdr returned 0
[1109523.468575] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.468578] NFS: nfs_update_inode(0:44/2 fh_crc=0x41dc8638 ct=2 info=0x427e7f)
[1109523.468579] NFS: (0:44/2) revalidation complete
[1109523.468590] NFS: readdir(/) starting at cookie 0
[1109523.468593] NFS: nfs_do_filldir() filling ended @ cookie 9223372036854775807; returning = 0
[1109523.468594] NFS: readdir(/) returns 0
[1109523.468600] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.468602] NFS: nfs_lookup_revalidate(/android) is valid
[1109523.468604] NFS: dentry_delete(/android, 10800cc)
[1109523.468605] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.468606] NFS: nfs_lookup_revalidate(/zfs) is valid
[1109523.468607] NFS: dentry_delete(/zfs, 10800cc)
[1109523.468608] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.468609] NFS: nfs_lookup_revalidate(/test.txt) is valid
[1109523.468611] NFS: revalidating (0:44/13)
[1109523.468612] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.468613] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.469745] decode_attr_type: type=0100000
[1109523.469746] decode_attr_change: change attribute=6364598550564246077
[1109523.469747] decode_attr_size: file size=2050
[1109523.469748] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.469748] decode_attr_fileid: fileid=13
[1109523.469749] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.469749] decode_attr_mode: file mode=0644
[1109523.469750] decode_attr_nlink: nlink=1
[1109523.469751] decode_attr_owner: uid=0
[1109523.469752] decode_attr_group: gid=0
[1109523.469752] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.469753] decode_attr_space_used: space used=4096
[1109523.469753] decode_attr_time_access: atime=1481873587
[1109523.469754] decode_attr_time_metadata: ctime=1481873577
[1109523.469754] decode_attr_time_modify: mtime=1481873577
[1109523.469755] decode_attr_mounted_on_fileid: fileid=13
[1109523.469755] decode_getfattr_attrs: xdr returned 0
[1109523.469756] decode_getfattr_generic: xdr returned 0
[1109523.469757] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.469760] NFS: nfs_update_inode(0:44/13 fh_crc=0x37ac62f7 ct=1 info=0x427e7f)
[1109523.469761] NFS: (0:44/13) revalidation complete
[1109523.469762] NFS: dentry_delete(/test.txt, 40800cc)
[1109523.469778] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.469780] NFS: nfs_lookup_revalidate(/test.txt) is valid
[1109523.469783] NFS: dentry_delete(/test.txt, 40800cc)
[1109523.469788] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.469789] NFS: nfs_lookup_revalidate(/CentOS-7-x86_64-Everything-1511.iso) is valid
[1109523.469790] NFS: revalidating (0:44/11)
[1109523.469791] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.469792] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.470356] decode_attr_type: type=0100000
[1109523.470357] decode_attr_change: change attribute=6364524539288547030
[1109523.470358] decode_attr_size: file size=420741120
[1109523.470359] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.470359] decode_attr_fileid: fileid=11
[1109523.470360] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.470360] decode_attr_mode: file mode=0755
[1109523.470361] decode_attr_nlink: nlink=1
[1109523.470362] decode_attr_owner: uid=0
[1109523.470362] decode_attr_group: gid=0
[1109523.470363] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.470363] decode_attr_space_used: space used=411308032
[1109523.470364] decode_attr_time_access: atime=1481855120
[1109523.470364] decode_attr_time_metadata: ctime=1481856345
[1109523.470365] decode_attr_time_modify: mtime=1481856345
[1109523.470365] decode_attr_mounted_on_fileid: fileid=11
[1109523.470366] decode_getfattr_attrs: xdr returned 0
[1109523.470366] decode_getfattr_generic: xdr returned 0
[1109523.470367] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.470370] NFS: nfs_update_inode(0:44/11 fh_crc=0x8e8a0486 ct=1 info=0x427e7f)
[1109523.470371] NFS: (0:44/11) revalidation complete
[1109523.470372] NFS: dentry_delete(/CentOS-7-x86_64-Everything-1511.iso, 40800cc)
[1109523.470377] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470378] NFS: nfs_lookup_revalidate(/lvm2) is valid
[1109523.470379] NFS: dentry_delete(/lvm2, 10800cc)
[1109523.470380] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470381] NFS: nfs_lookup_revalidate(/cluster) is valid
[1109523.470382] NFS: dentry_delete(/cluster, 10800cc)
[1109523.470386] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470387] NFS: nfs_lookup_revalidate(/syscall.sh) is valid
[1109523.470388] NFS: revalidating (0:44/14)
[1109523.470389] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.470390] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.470621] decode_attr_type: type=0100000
[1109523.470622] decode_attr_change: change attribute=6353487525572665064
[1109523.470623] decode_attr_size: file size=553
[1109523.470623] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.470624] decode_attr_fileid: fileid=14
[1109523.470624] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.470625] decode_attr_mode: file mode=0755
[1109523.470625] decode_attr_nlink: nlink=1
[1109523.470626] decode_attr_owner: uid=0
[1109523.470627] decode_attr_group: gid=0
[1109523.470627] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.470628] decode_attr_space_used: space used=4096
[1109523.470628] decode_attr_time_access: atime=1475207632
[1109523.470629] decode_attr_time_metadata: ctime=1479286590
[1109523.470629] decode_attr_time_modify: mtime=1475207569
[1109523.470630] decode_attr_mounted_on_fileid: fileid=14
[1109523.470630] decode_getfattr_attrs: xdr returned 0
[1109523.470631] decode_getfattr_generic: xdr returned 0
[1109523.470632] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.470635] NFS: nfs_update_inode(0:44/14 fh_crc=0xdd939116 ct=1 info=0x427e7f)
[1109523.470635] NFS: (0:44/14) revalidation complete
[1109523.470637] NFS: dentry_delete(/syscall.sh, 40800cc)
[1109523.470642] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470643] NFS: nfs_lookup_revalidate(/openstack) is valid
[1109523.470644] NFS: dentry_delete(/openstack, 10800cc)
[1109523.470646] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470646] NFS: nfs_lookup_revalidate(/dm-dynamic) is valid
[1109523.470649] NFS: dentry_delete(/dm-dynamic, 10800cc)
[1109523.470650] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470651] NFS: nfs_lookup_revalidate(/hello) is valid
[1109523.470652] NFS: dentry_delete(/hello, 10800cc)
[1109523.470653] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470654] NFS: nfs_lookup_revalidate(/stack) is valid
[1109523.470654] NFS: dentry_delete(/stack, 10800cc)
[1109523.470655] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470656] NFS: nfs_lookup_revalidate(/vm) is valid
[1109523.470657] NFS: dentry_delete(/vm, 10800cc)
[1109523.470658] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470659] NFS: nfs_lookup_revalidate(/multipath) is valid
[1109523.470659] NFS: dentry_delete(/multipath, 10800cc)
[1109523.470660] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470661] NFS: nfs_lookup_revalidate(/Software) is valid
[1109523.470662] NFS: dentry_delete(/Software, 10800cc)
[1109523.470663] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470664] NFS: nfs_lookup_revalidate(/systemd) is valid
[1109523.470664] NFS: dentry_delete(/systemd, 10800cc)
[1109523.470665] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470666] NFS: nfs_lookup_revalidate(/python) is valid
[1109523.470667] NFS: dentry_delete(/python, 10800cc)
[1109523.470668] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470668] NFS: nfs_lookup_revalidate(/progress) is valid
[1109523.470669] NFS: dentry_delete(/progress, 10800cc)
[1109523.470670] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470671] NFS: nfs_lookup_revalidate(/ref) is valid
[1109523.470671] NFS: dentry_delete(/ref, 10800cc)
[1109523.470672] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470673] NFS: nfs_lookup_revalidate(/nfs) is valid
[1109523.470674] NFS: dentry_delete(/nfs, 10800cc)
[1109523.470675] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470676] NFS: nfs_lookup_revalidate(/eclipse) is valid
[1109523.470676] NFS: dentry_delete(/eclipse, 10800cc)
[1109523.470677] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470678] NFS: nfs_lookup_revalidate(/scsi) is valid
[1109523.470679] NFS: dentry_delete(/scsi, 10800cc)
[1109523.470680] NFS: permission(0:44/2), mask=0x81, res=0
[1109523.470680] NFS: nfs_lookup_revalidate(/yum) is valid
[1109523.470681] NFS: dentry_delete(/yum, 10800cc)
[1109523.470682] NFS: readdir(/) starting at cookie 24
[1109523.470687] NFS: (0:44/2) data cache invalidated
[1109523.470696] _nfs4_proc_readdir: dentry = /, cookie = 0
[1109523.470698] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=1024
[1109523.470698] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
[1109523.470701] encode_readdir: cookie = 0, verifier = 00000000:00000000, bitmap = 0018091a:00b0a23a:00000000
[1109523.470702] nfs4_xdr_enc_readdir: inlined page args = (60, ffff88000087fce8, 80, 32688)
[1109523.473190] decode_readdir: verifier = 00000000:00000000
[1109523.473193] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
[1109523.473196] _nfs4_proc_readdir: returns 4584
[1109523.473198] decode_attr_type: type=00
[1109523.473199] decode_attr_change: change attribute=0
[1109523.473199] decode_attr_size: file size=0
[1109523.473200] decode_attr_fsid: fsid=(0x0/0x0)
[1109523.473201] decode_attr_fileid: fileid=2
[1109523.473201] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473202] decode_attr_mode: file mode=00
[1109523.473202] decode_attr_nlink: nlink=1
[1109523.473203] decode_attr_owner: uid=-2
[1109523.473203] decode_attr_group: gid=-2
[1109523.473204] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.473204] decode_attr_space_used: space used=0
[1109523.473205] decode_attr_time_access: atime=0
[1109523.473205] decode_attr_time_metadata: ctime=0
[1109523.473206] decode_attr_time_modify: mtime=0
[1109523.473206] decode_attr_mounted_on_fileid: fileid=0
[1109523.473207] decode_getfattr_attrs: xdr returned 0
[1109523.473208] decode_attr_type: type=00
[1109523.473208] decode_attr_change: change attribute=0
[1109523.473209] decode_attr_size: file size=0
[1109523.473209] decode_attr_fsid: fsid=(0x0/0x0)
[1109523.473226] decode_attr_fileid: fileid=2
[1109523.473228] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473228] decode_attr_mode: file mode=00
[1109523.473229] decode_attr_nlink: nlink=1
[1109523.473229] decode_attr_owner: uid=-2
[1109523.473230] decode_attr_group: gid=-2
[1109523.473230] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.473230] decode_attr_space_used: space used=0
[1109523.473231] decode_attr_time_access: atime=0
[1109523.473231] decode_attr_time_metadata: ctime=0
[1109523.473232] decode_attr_time_modify: mtime=0
[1109523.473232] decode_attr_mounted_on_fileid: fileid=0
[1109523.473233] decode_getfattr_attrs: xdr returned 0
[1109523.473234] decode_attr_type: type=040000
[1109523.473235] decode_attr_change: change attribute=6346343096919327641
[1109523.473235] decode_attr_size: file size=4096
[1109523.473236] decode_attr_fsid: fsid=(0xa983386a266c40c2/0x886bf94fb379d906)
[1109523.473236] decode_attr_fileid: fileid=2
[1109523.473237] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473237] decode_attr_mode: file mode=0755
[1109523.473238] decode_attr_nlink: nlink=11
[1109523.473238] decode_attr_owner: uid=0
[1109523.473239] decode_attr_group: gid=0
[1109523.473240] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.473240] decode_attr_space_used: space used=4096
[1109523.473241] decode_attr_time_access: atime=1481953801
[1109523.473241] decode_attr_time_metadata: ctime=1477623148
[1109523.473242] decode_attr_time_modify: mtime=1477623148
[1109523.473242] decode_attr_mounted_on_fileid: fileid=4718593
[1109523.473242] decode_getfattr_attrs: xdr returned 0
[1109523.473244] NFS: dentry_delete(/android, 10800cc)
[1109523.473244] decode_attr_type: type=040000
[1109523.473245] decode_attr_change: change attribute=6353487525598664995
[1109523.473245] decode_attr_size: file size=4096
[1109523.473246] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.473247] decode_attr_fileid: fileid=1181159
[1109523.473247] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473248] decode_attr_mode: file mode=0755
[1109523.473258] decode_attr_nlink: nlink=15
[1109523.473259] decode_attr_owner: uid=0
[1109523.473259] decode_attr_group: gid=0
[1109523.473260] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.473260] decode_attr_space_used: space used=4096
[1109523.473261] decode_attr_time_access: atime=1479286629
[1109523.473261] decode_attr_time_metadata: ctime=1479286590
[1109523.473262] decode_attr_time_modify: mtime=1467185801
[1109523.473262] decode_attr_mounted_on_fileid: fileid=1181159
[1109523.473263] decode_getfattr_attrs: xdr returned 0
[1109523.473265] NFS: nfs_update_inode(0:44/1181159 fh_crc=0x6176c546 ct=1 info=0x427e7f)
[1109523.473265] NFS: dentry_delete(/zfs, 10800cc)
[1109523.473266] decode_attr_type: type=0100000
[1109523.473267] decode_attr_change: change attribute=6364598550564246077
[1109523.473267] decode_attr_size: file size=2050
[1109523.473268] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.473268] decode_attr_fileid: fileid=13
[1109523.473269] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473269] decode_attr_mode: file mode=0644
[1109523.473269] decode_attr_nlink: nlink=1
[1109523.473270] decode_attr_owner: uid=0
[1109523.473270] decode_attr_group: gid=0
[1109523.473271] decode_attr_rdev: rdev=(0x0:0x0)
[1109523.473271] decode_attr_space_used: space used=4096
[1109523.473272] decode_attr_time_access: atime=1481873587
[1109523.473272] decode_attr_time_metadata: ctime=1481873577
[1109523.473273] decode_attr_time_modify: mtime=1481873577
[1109523.473273] decode_attr_mounted_on_fileid: fileid=13
[1109523.473274] decode_getfattr_attrs: xdr returned 0
[1109523.473275] NFS: nfs_update_inode(0:44/13 fh_crc=0x37ac62f7 ct=1 info=0x427e7f)
[1109523.473276] NFS: dentry_delete(/test.txt, 40800cc)
[1109523.473276] decode_attr_type: type=0100000
[1109523.473277] decode_attr_change: change attribute=6364524539288547030
[1109523.473277] decode_attr_size: file size=420741120
[1109523.473278] decode_attr_fsid: fsid=(0x25fc7e9117764101/0x94fa84be75ffc4ec)
[1109523.473278] decode_attr_fileid: fileid=11
[1109523.473300] decode_attr_fs_locations: fs_locations done, error = 0
[1109523.473301] decode_attr_mode: file mod