对 ESXi NFS 数据存储上的延迟峰值进行故障排除

Question

我在 ESXi 中的 NFS 数据存储上遇到了大约5 秒的fsync 延迟，这是由某些虚拟机触发的。我怀疑这可能是由使用 NCQ/TCQ 的 VM 引起的，因为这不会发生在虚拟 IDE 驱动器上。

这可以使用fsync-tester（由 Ted Ts'o）和ioping 重现。例如使用具有 8GB 磁盘的 Grml 实时系统：

Linux 2.6.33-grml64:
root@dynip211 /mnt/sda # ./fsync-tester
fsync time: 5.0391
fsync time: 5.0438
fsync time: 5.0300
fsync time: 0.0231
fsync time: 0.0243
fsync time: 5.0382
fsync time: 5.0400
[... goes on like this ...]

那是 5 秒，而不是毫秒。这甚至会在同一主机和数据存储上运行的不同 VM 上创建 IO 延迟：

root@grml /mnt/sda/ioping-0.5 # ./ioping -i 0.3 -p 20 .
4096 bytes from . (reiserfs /dev/sda): request=1 time=7.2 ms
4096 bytes from . (reiserfs /dev/sda): request=2 time=0.9 ms
4096 bytes from . (reiserfs /dev/sda): request=3 time=0.9 ms
4096 bytes from . (reiserfs /dev/sda): request=4 time=0.9 ms
4096 bytes from . (reiserfs /dev/sda): request=5 time=4809.0 ms
4096 bytes from . (reiserfs /dev/sda): request=6 time=1.0 ms
4096 bytes from . (reiserfs /dev/sda): request=7 time=1.2 ms
4096 bytes from . (reiserfs /dev/sda): request=8 time=1.1 ms
4096 bytes from . (reiserfs /dev/sda): request=9 time=1.3 ms
4096 bytes from . (reiserfs /dev/sda): request=10 time=1.2 ms
4096 bytes from . (reiserfs /dev/sda): request=11 time=1.0 ms
4096 bytes from . (reiserfs /dev/sda): request=12 time=4950.0 ms

当我将第一个 VM 移动到本地存储时，它看起来完全正常：

root@dynip211 /mnt/sda # ./fsync-tester
fsync time: 0.0191
fsync time: 0.0201
fsync time: 0.0203
fsync time: 0.0206
fsync time: 0.0192
fsync time: 0.0231
fsync time: 0.0201
[... tried that for one hour: no spike ...]

我尝试过的没有区别的事情：

• 测试了多个 ESXi 内部版本：381591、348481、260247
• 在不同的硬件、不同的 Intel 和 AMD 机器上测试
• 使用不同的 NFS 服务器进行测试，都显示相同的行为：
  • OpenIndiana b147（ZFS 同步始终或禁用：没有区别）
  • OpenIndiana b148（ZFS 同步始终或禁用：没有区别）
  • Linux 2.6.32（同步或异步：没有区别）
  • NFS 服务器是在同一台机器上（作为虚拟存储设备）还是在不同的主机上没有区别

来宾操作系统测试，显示问题：

• Windows 7 64 位（使用 CrystalDiskMark，延迟高峰主要发生在准备阶段）
• Linux 2.6.32（fsync-tester + ioping）
• Linux 2.6.38（fsync-tester + ioping）

我无法在 Linux 2.6.18 VM 上重现此问题。

另一种解决方法是使用虚拟 IDE 磁盘（与 SCSI/SAS 相比），但这会限制性能和每个 VM 的驱动器数量。

2011-06-30 更新：

如果应用程序在 fsync 之前写入多个小块，则延迟峰值似乎会更频繁地发生。例如 fsync-tester 这样做（strace 输出）：

pwrite(3, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 1048576, 0) = 1048576
fsync(3)                                = 0

ioping 在准备文件时执行此操作：

[lots of pwrites]
pwrite(3, "********************************"..., 4096, 1036288) = 4096
pwrite(3, "********************************"..., 4096, 1040384) = 4096
pwrite(3, "********************************"..., 4096, 1044480) = 4096
fsync(3)                                = 0

ioping 的设置阶段几乎总是挂起，而 fsync-tester 有时可以正常工作。有人能够更新 fsync-tester 来编写多个小块吗？我的 C 技能很烂；)

2011-07-02 更新：

iSCSI 不会出现此问题。我在 OpenIndiana COMSTAR iSCSI 服务器上尝试了这个。但是 iSCSI 不能让您轻松访问 VMDK 文件，因此您可以使用快照和 rsync 在主机之间移动它们。

2011-07-06 更新：

这是wireshark 捕获的一部分，由同一vSwitch 上的第三个VM 捕获。这一切都发生在同一台主机上，不涉及物理网络。

我在 20 点左右开始使用 ioping。直到 5 秒延迟结束后才发送数据包：

No.  Time        Source                Destination           Protocol Info
1082 16.164096   192.168.250.10        192.168.250.20        NFS      V3 WRITE Call (Reply In 1085), FH:0x3eb56466 Offset:0 Len:84 FILE_SYNC
1083 16.164112   192.168.250.10        192.168.250.20        NFS      V3 WRITE Call (Reply In 1086), FH:0x3eb56f66 Offset:0 Len:84 FILE_SYNC
1084 16.166060   192.168.250.20        192.168.250.10        TCP      nfs > iclcnet-locate [ACK] Seq=445 Ack=1057 Win=32806 Len=0 TSV=432016 TSER=769110
1085 16.167678   192.168.250.20        192.168.250.10        NFS      V3 WRITE Reply (Call In 1082) Len:84 FILE_SYNC
1086 16.168280   192.168.250.20        192.168.250.10        NFS      V3 WRITE Reply (Call In 1083) Len:84 FILE_SYNC
1087 16.168417   192.168.250.10        192.168.250.20        TCP      iclcnet-locate > nfs [ACK] Seq=1057 Ack=773 Win=4163 Len=0 TSV=769110 TSER=432016
1088 23.163028   192.168.250.10        192.168.250.20        NFS      V3 GETATTR Call (Reply In 1089), FH:0x0bb04963
1089 23.164541   192.168.250.20        192.168.250.10        NFS      V3 GETATTR Reply (Call In 1088)  Directory mode:0777 uid:0 gid:0
1090 23.274252   192.168.250.10        192.168.250.20        TCP      iclcnet-locate > nfs [ACK] Seq=1185 Ack=889 Win=4163 Len=0 TSV=769821 TSER=432716
1091 24.924188   192.168.250.10        192.168.250.20        RPC      Continuation
1092 24.924210   192.168.250.10        192.168.250.20        RPC      Continuation
1093 24.924216   192.168.250.10        192.168.250.20        RPC      Continuation
1094 24.924225   192.168.250.10        192.168.250.20        RPC      Continuation
1095 24.924555   192.168.250.20        192.168.250.10        TCP      nfs > iclcnet_svinfo [ACK] Seq=6893 Ack=1118613 Win=32625 Len=0 TSV=432892 TSER=769986
1096 24.924626   192.168.250.10        192.168.250.20        RPC      Continuation
1097 24.924635   192.168.250.10        192.168.250.20        RPC      Continuation
1098 24.924643   192.168.250.10        192.168.250.20        RPC      Continuation
1099 24.924649   192.168.250.10        192.168.250.20        RPC      Continuation
1100 24.924653   192.168.250.10        192.168.250.20        RPC      Continuation

第二次更新 2011-07-06：

TCP窗口大小似乎有一些影响。我无法使用 FreeNAS（基于 FreeBSD）作为 NFS 服务器来重现这个问题。Wireshark 捕获显示 TCP 窗口定期更新为 29127 字节。我没有在 OpenIndiana 中看到它们，默认情况下它使用更大的窗口大小。

如果我在 OpenIndiana 中设置以下选项并重新启动 NFS 服务器，则无法再重现此问题：

ndd -set /dev/tcp tcp_recv_hiwat 8192 # default is 128000
ndd -set /dev/tcp tcp_max_buf 1048575 # default is 1048576

但这会降低性能：使用 dd_rescue 从 /dev/zero 写入文件的速度从 170MB/s 到 80MB/s。

2011-07-07 更新：

我已经上传了这个tcpdump 捕获（可以用wireshark分析）。在这种情况下，192.168.250.2 是 NFS 服务器 (OpenIndiana b148)，192.168.250.10 是 ESXi 主机。

我在这次捕获期间测试过的东西：

开始“ioping -w 5 -i 0.2”。在时间 30，设置挂起 5 秒，在时间 40 完成。

开始“ioping -w 5 -i 0.2”。在时间 60，设置挂起 5 秒，在时间 70 完成。

在时间 90 启动“fsync-tester”，输出如下，在时间 120 停止：

fsync time: 0.0248
fsync time: 5.0197
fsync time: 5.0287
fsync time: 5.0242
fsync time: 5.0225
fsync time: 0.0209

第二次更新 2011-07-07：

测试了另一个 NFS 服务器虚拟机，这次是 NexentaStor 3.0.5 社区版：显示同样的问题。

2011-07-31 更新：

我还可以在新的 ESXi 版本 4.1.0.433742 上重现此问题。

Answer 1

这个问题似乎在 ESXi 5 中得到了修复。我已经成功测试了内部版本 469512。