NFSv4.1（AWS EFS）服务器元数据请求泛滥问题排查求助

各位大佬好，最近一周我碰到个头疼的问题：我们多个Web服务器集群连接的NFSv4.1（AWS EFS）网络驱动器突然出现元数据请求暴增的情况，已经引发了性能下降甚至生产故障。我做了一系列排查，下面是详细过程和目前的发现，希望能得到大家的帮助！

初始排查 #

我先做了基础诊断，结果如下：

• 用nfsiostat观测到出现问题的服务器上请求量在60-450 ops/s之间
• 用nfstrace --mode=live --verbose=2追踪发现，同一个操作会反复针对2-3个文件句柄执行，具体请求序列如下：

CALL  [ operations: 4 tag: void minor version: 1

[ SEQUENCE(53) [ sessionid: 0xeab1201a93b669600000000000000001 sequenceid: 0xfc12c slotid: 2 cache this: 0 ]

[ PUTFH(22) [ object: 839c9918169aed49bd6f96adab5438bc47b1460162fe4a739cd8c98405868b2b5de303ed1f4ecfa82c26f5ca1db4cce8e63aad38fe72a397bdae51d8a7e93eb118ad8c736b30323165273b9c805db85936cf3be626b6ba4165ecf9755a54fdd174a535e217ffee4fa0166feea6e86becf9fa16280fd877b3545e07fe03aede08 ]

[ ACCESS(3) [ READ LOOKUP MODIFY EXTEND DELETE  ]

[ GETATTR(9) [ mask: 0x18300000 CHANGE SIZE TIME_METADATA TIME_MODIFY ]  ]

REPLY [  operations: 4 status: OK tag: void

[ SEQUENCE(53) [ status: OK session: 0xeab1201a93b669600000000000000001 sequenceid: 0xfc12c slotid: 2 highest slotid: 63 target highest slotid: 63 status flags: 0 ]

[ PUTFH(22) [ status: OK ]

[ ACCESS(3) [ status: OK supported: READ LOOKUP MODIFY EXTEND DELETE  access: READ LOOKUP MODIFY EXTEND DELETE  ]

[ GETATTR(9) [ status: OK mask: 0x18300000 CHANGE SIZE TIME_METADATA TIME_MODIFY ]  ]

• 用lsof -N没找到任何进程在使用NFS驱动器上的文件
• iotop也没发现明显异常
• 用tcpdump -s 0 -w /tmp/nfs.pcap port 2049抓包后导入Wireshark解析文件句柄，结果毫无意义（比如解析出的inode不存在）

目前我通过将AWS EFS的吞吐量模式改为弹性暂时缓解了问题，但根本原因还没找到，而且这个问题看起来和nginx服务器泛滥NFS元数据请求的情况非常相似。

UPDATE 1 #

后来我找到了定位问题文件的方法——通过tshark分析抓包获取文件修改时间：

tshark -r /tmp/nfs.pcap -V

解析出的GETATTR响应包含时间信息：

Opcode: GETATTR (9)
Status: NFS4_OK (0)
Attr mask[0]: 0x00000018 (Change, Size)
reqd_attr: Change (3)
changeid: 1626
reqd_attr: Size (4)
size: 38912
Attr mask[1]: 0x00300000 (Time_Metadata, Time_Modify)
reco_attr: Time_Metadata (52)
seconds: 1678928064
nseconds: 8000000
reco_attr: Time_Modify (53)
seconds: 1678928064
nseconds: 8000000

接着用find命令匹配对应时间的文件：

find /path/to/mount/point/ -newermt "15 Mar 2023" ! -newermt "17 Mar 2023" -ls | grep 13:54

结果发现请求都集中在网站首页加载的2-5个特定文件上，但还是没找到问题根源。

之后我测试了Linux内核4.0以上支持的lazytime挂载选项（该选项会将更多元数据缓存到内存，减少写入请求），做了一组对比实验：

实验结果 #

• Server 1：
  • 初始挂载选项：relatime，NFS请求量460.982 ops/s
  • 修改挂载选项为lazytime，卸载并重新挂载NFS驱动器后，请求量降至1.400 ops/s
  • 重启服务器后，请求量保持在1.316 ops/s
• Server 2：
  • 初始挂载选项：relatime，NFS请求量390.998 ops/s
  • 未修改挂载选项，仅卸载重新挂载后，请求量暂时降至1.750 ops/s
  • 重启服务器后，请求量反弹至531.932 ops/s

实验结论 #

1. 卸载重新挂载磁盘能暂时解决问题
2. lazytime选项能部分缓解问题
3. 问题似乎和服务器启动有关，这和之前的观测一致

UPDATE 2 #

我找到了更有效的调试方法——启用NFS内核调试：

# 启用所有NFS调试日志
rpcdebug -m nfs -s all

# 实时查看调试输出
tail -f /var/log/syslog

# 关闭调试
rpcdebug -m nfs -c all

调试日志给出了有用的信息，比如：

Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213426] NFS: nfs_update_inode(0:55/1440391441734181492 fh_crc=0xc29dd48a ct=2 info=0x26040)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213428] NFS: permission(0:55/1440391441734181492), mask=0x1, res=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213430] NFS: nfs_lookup_revalidate_done(/Components) is valid
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213432] --> nfs41_call_sync_prepare data->seq_server 000000008a198bb4
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213433] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213433] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213436] encode_sequence: sessionid=1354075206:678036945:0:16777216 seqid=238661 slotid=0 max_slotid=0 cache_this=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213842] decode_attr_type: type=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213843] decode_attr_change: change attribute=2153
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213844] decode_attr_size: file size=71680
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213845] decode_attr_fsid: fsid=(0x0/0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213845] decode_attr_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213846] decode_attr_fs_locations: fs_locations done, error = 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213846] decode_attr_mode: file mode=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213847] decode_attr_nlink: nlink=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213848] decode_attr_rdev: rdev=(0x0:0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213848] decode_attr_space_used: space used=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213849] decode_attr_time_access: atime=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213849] decode_attr_time_metadata: ctime=1677729393
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213850] decode_attr_time_modify: mtime=1677729393
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213851] decode_attr_mounted_on_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213851] decode_getfattr_attrs: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213852] decode_getfattr_generic: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213853] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213854] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213855] nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213855] nfs41_sequence_process: Error 0 free the slot
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213856] nfs4_free_slot: slotid 0 highest_used_slotid 4294967295
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213860] NFS: nfs_update_inode(0:55/10743289300410127521 fh_crc=0xb5c7d895 ct=1 info=0x26040)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213862] NFS: permission(0:55/10743289300410127521), mask=0x1, res=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213864] NFS: nfs_lookup_revalidate_done(Components/Image.png) is valid
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.213867] NFS: dentry_delete(Components/Image.png, 48084c)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214000] NFS: permission(0:55/1440391441734181492), mask=0x81, res=-10
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214003] --> nfs41_call_sync_prepare data->seq_server 000000008a198bb4
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214004] --> nfs4_alloc_slot used_slots=0000 highest_used=4294967295 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214005] <-- nfs4_alloc_slot used_slots=0001 highest_used=0 slotid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214009] encode_sequence: sessionid=1354075206:678036945:0:16777216 seqid=238662 slotid=0 max_slotid=0 cache_this=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214472] decode_attr_type: type=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214473] decode_attr_change: change attribute=1626
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214473] decode_attr_size: file size=3891