☰

大量 NFS 元数据流量淹没 NFSv4.1 服务器 (AWS EFS)

tag-icon • tag-icon linux amazon-web-services nfs encrypting-file-system
大量 NFS 元数据流量淹没 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 中的吞吐量模式更改为弹性来缓解该问题，但该问题会导致性能问题并导致生产中断。

注意：这个问题与这个问题非常相似：nginx 网络服务器向 NFS 发送大量元数据请求

更新 1

我发现通过查看回复数据包我能够确定哪些文件有问题，用 tshark ( tshark -r /tmp/nfs.pcap -V) 打开 tcp 转储足以获取文件修改的时间戳；

        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 个看似随机的文件的元数据。

经过进一步阅读，我发现lazytimeLinux Kernel 4.0 中有一个可用的选项。此选项在 RAM 中保存更多信息并减少元数据写入。我对此做了一些实验，我将这个挂载选项应用于/etc/fstab集群中一台服务器上的文件，然后对另一台服务器进行了“安慰剂”处理。观察结果如下；

  • 服务器 1：
    • 检查安装选项 - 使用 relatime
    • 检查 nfs 统计数据 - 460.982 ops/s
    • 更新了挂载选项
    • 卸载并安装 NFS 驱动器
    • 检查 nfs 统计数据 - 1.400 ops/s
    • 重新启动
    • 检查 nfs 统计数据 - 1.316 ops/s
  • 服务器2：
    • 检查安装选项 - 使用 relatime
    • 检查 nfs 统计数据 - 390.998 ops/s
    • 没有更新挂载选项
    • 卸载并安装 NFS 驱动器
    • 检查 nfs 统计数据 - 1.750 ops/s
    • 重新启动
    • 检查 nfs 统计数据 - 531.932 ops/s

由此得出的结论是；

  • 卸载并重新安装磁盘可暂时解决该问题
  • lazytime选项似乎部分缓解了这个问题
  • 问题似乎与启动有关，这与其他观察结果一致

更新2

我在这里找到了一种更有效的故障排除方法；

# enable debugging
rpcdebug -m nfs -s all

# watch debug output
tail -f /var/log/syslog

# disable debugging
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=38912
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214474] decode_attr_fsid: fsid=(0x0/0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214475] decode_attr_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214475] decode_attr_fs_locations: fs_locations done, error = 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214476] decode_attr_mode: file mode=00
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214476] decode_attr_nlink: nlink=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214477] decode_attr_rdev: rdev=(0x0:0x0)
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214477] decode_attr_space_used: space used=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214478] decode_attr_time_access: atime=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214479] decode_attr_time_metadata: ctime=1678928064
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214479] decode_attr_time_modify: mtime=1678928064
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214480] decode_attr_mounted_on_fileid: fileid=0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214480] decode_getfattr_attrs: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214481] decode_getfattr_generic: xdr returned 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214483] --> nfs4_alloc_slot used_slots=0001 highest_used=0 max_slots=64
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214483] <-- nfs4_alloc_slot used_slots=0003 highest_used=1 slotid=1
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214484] nfs4_free_slot: slotid 1 highest_used_slotid 0
Mar 17 10:20:41 ip-10-1-2-84 kernel: [ 3897.214485] nfs41_sequence_process: Error 0 free the slot

答案1

看起来这是由内核错误引起的，linux-aws-5.4.0-1097我回滚到linux-aws-5.4.0-1096并且问题消失然后linux-aws-5.4.0-1097再次前滚并且一旦 Web 服务器请求资产它就开始红线@> 200 ops/s。

根据此处的注释：https://www.ubuntuupdates.org/package/core/bionic/main/proposed/linux-aws-5.4看起来 NFS 客户端在 1097 年被修改了：https://bugs.launchpad.net/ubuntu/+source/linux/+bug/2003053

相关内容