前言
在测试分布式文件系统的工具中，常用的一种工具就是vdbench。
同时对于分布式文件系统的高可用以及高可靠来说，我们经常人为对存储系统注入故障。在故障注入期间，我们不仅要关注 IO 数据的正确性（高可靠），还应该关注IO的高可用（IO中断时间不能超过业务/系统所能容忍的时间）。
那么，我们如何通过vdbench的日志来判断后端是否发生了故障，以及故障导致的IO中断的具体时长呢？
两个重要的日志文件
在vdbench 每一次执行的目录下，都有 errorlog 和 flatfile 两个日志文件。
比如 执行一次 vdbench：
~/workspace/vdbench/vdbench -jn -o /tmp/tmp.ED3oNdKf0e/output -f /tmp/tmp.ED3oNdKf0e/basic_io_4fault_injection fsd1_mountpoint=/mnt/SQKhf/ duration=900
在上述vdbench 执行完成之后， 在 -o 参数所指定的目录下 /tmp/tmp.ED3oNdKf0e/output 存在着vdbench 的关键日志文件。
errorlog 日志文件分析
摘取一段 errorlog 日志如下：
15:46:46.933 localhost-0: Created new mmap file: /tmp/vdbench.pid22619.fsd1.mmap.0 mmap size: 49.098k
15:46:46.933 localhost-0: Allocating Data Validation map: 50,276 one-byte entries for each 4,096-byte block.
15:46:46.933 localhost-0: Created new DV map: fsd1 size: 205,926,400 bytes; key block size: 4096; entries: 50,275
15:46:46.937 localhost-0: Creating journal file /root/fsd1.jnl
15:46:46.939 localhost-0: Writing Data Validation map to /root/fsd1.jnl
15:46:47.042 localhost-0: Writing Data Validation map to /root/fsd1.map
15:47:31.006 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 1 seconds.
15:47:33.006 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 3 seconds.
15:47:35.012 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 5 seconds.
15:47:37.005 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 7 seconds.
15:47:38.007 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 8 seconds.
15:47:40.006 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 10 seconds.
15:47:41.008 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 11 seconds.
15:47:43.007 timeout=1 value exceeded for fsd=fsd1 on slave=localhost-0 for 13 seconds.
......
上面的日志可以看到有较多的 timeout=1 value exceeded,这意味着该FSD IO响应时间超过1秒 即 在连续的统计周期1s内，目标FSD的完成IO数量为零，并持续了至少13s。 这也表明后端存储出现了相应的故障导致IO中断（客户端即网络因素暂不考虑），若非人为预期的故障注入，需要调查后端存储是否出现了高可用问题。(PS：该阈值可根据 vdbench 执行参数 timeout 调整，比如timeout=（1，90） 表示IO超时1s 发出告警,超过90s 会终止vdbench 进程)。
flatfile 日志文件分析
对应上述errorlog 日志出现“timeout”时，flatfile 日志如下，其数据来自线程定时读取的各IO线程统计结果，对于IO中断时间的判断比较关键的几列数据分别为
- Rate ： 总IO完成速率（IOPS）
- Reqrate ： 请求发送速率（可能包含重试）
- Resp(ms) ： 总体平均响应时间
- Read_rate：读IO完成速率
- Write_rate：写IO完成速率
- Read_resp：读IO平均响应时间
- Write_res：写IO平均响应时间
下面，我仅粘贴出和IO中断相关的列进行分析，例子如下：
Time Interval Rate Reqrate Resp(ms) Read_rate Write_rate Read_resp Write_resp
07/02/2025-15:01:21-CST 1 513 9999988 10.6295 343 0 11.9906 3.3331
07/02/2025-15:01:22-CST 2 843 9999988 9.0279 543 0 10.1938 2.8051
07/02/2025-15:01:23-CST 3 846 9999988 9.1067 564 0 9.9486 3.5630
......
07/02/2025-15:01:37-CST 17 826 9999988 9.2634 531 0 10.4557 2.5029
07/02/2025-15:01:38-CST 18 565 9999988 12.7210 354 0 15.9799 2.6742
07/02/2025-15:01:39-CST 19 520 9999988 15.3111 343 0 18.7140 7.5279
07/02/2025-15:01:40-CST 20 728 9999988 10.4209 472 0 11.5669 4.0718
07/02/2025-15:01:41-CST 21 723 9999988 9.9312 461 0 11.0244 3.4462
07/02/2025-15:01:42-CST 22 0 9999988 0.0000 0 0 0.0000 0.0000 <== Rate 和 Resp从这里降为0
07/02/2025-15:01:43-CST 23 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:01:44-CST 24 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:01:45-CST 25 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:01:46-CST 26 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:01:47-CST 27 0 9999988 0.0000 0 0 0.0000 0.0000
.....
07/02/2025-15:03:21-CST 121 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:03:22-CST 122 342 9999988 16.6358 220 0 14.6156 24.1906 <== 从这里开始恢复正常
07/02/2025-15:03:23-CST 123 310 9999988 21.6378 197 0 15.9209 27.4677
07/02/2025-15:03:24-CST 124 392 9999988 19.6406 261 0 10.4393 26.6481
07/02/2025-15:03:25-CST 125 615 9999988 12.3238 394 0 13.5716 3.7917
07/02/2025-15:03:26-CST 126 645 9999988 11.2375 421 0 11.7855 4.5078
07/02/2025-15:03:27-CST 127 662 9999988 10.9222 441 0 11.2563 4.3261
从上面的日志信息可以看到 在 07/02/2025-15:03:22-CST 出现 IOPS 和 Resp(ms) 都降为0， 在 07/02/2025-15:03:22-CST IO 恢复，和前面的errorlog 日志相符。
特殊的情况
但是，在实际测试中，我发现，即便后端存储明确注入了故障，errorlog 日志没有任何“timeout=xxx value exceeded”日志出现。以某次 vdbench 执行日志为例：
errorlog 日志如下：
❯ cat errorlog.html
<title>Vdbench output/errorlog.html</title><pre>
Vdbench error log, created 15:00:34 Jul 02 2025 CST
Error log. If there are no error messages beyond this line then there were no Data Validation or I/O errors.
15:00:35.331 localhost-0: Created new mmap file: /tmp/vdbench.pid616799.fsd1.mmap.0 mmap size: 49.098k
15:00:35.332 localhost-0: Allocating Data Validation map: 50,276 one-byte entries for each 4,096-byte block.
15:00:35.332 localhost-0: Created new DV map: fsd1 size: 205,926,400 bytes; key block size: 4096; entries: 50,275
15:00:35.336 localhost-0: Creating journal file /root/fsd1.jnl
15:00:35.338 localhost-0: Writing Data Validation map to /root/fsd1.jnl
15:00:35.442 localhost-0: Writing Data Validation map to /root/fsd1.map
15:01:18.321 localhost-0: Writing Data Validation map to /root/fsd1.jnl
15:01:18.422 localhost-0: Writing Data Validation map to /root/fsd1.map
15:01:18.643 localhost-0: 15:01:18.643 Total amount of key blocks read and validated: 0; key blocks marked in error: 0
15:06:20.116 localhost-0: Writing Data Validation map to /root/fsd1.jnl
15:06:20.216 localhost-0: Writing Data Validation map to /root/fsd1.map
15:06:20.425 localhost-0: 15:06:20.424 Total amount of key blocks read and validated: 80,707; key blocks marked in error: 0
flatfile 信息如下：
❯ awk -f parse_flatfile.awk flatfile.html
Time Interval Rate Reqrate Resp(ms) Read_rate Write_rate Read_resp Write_resp
07/02/2025-15:01:40-CST 20 728 9999988 10.4209 472 0 11.5669 4.0718
07/02/2025-15:01:41-CST 21 723 9999988 9.9312 461 0 11.0244 3.4462
07/02/2025-15:01:42-CST 22 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:01:43-CST 23 0 9999988 0.0000 0 0 0.0000 0.0000
....
07/02/2025-15:02:09-CST 49 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:02:10-CST 50 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:02:11-CST 51 0 9999988 0.0000 0 0 0.0000 0.0000
....
07/02/2025-15:03:17-CST 117 0 9999988 0.0000 0 0 0.0000 0.0000
07/02/2025-15:03:18-CST 118 100 9999988 7756.4191 64 0 7570.1670 27129.4222
07/02/2025-15:03:19-CST 119 22 9999988 9.8833 15 0 9.4700 9.9524
从上面的日志可以看到，在后端主人故障之后（此次日志未提供），errorlog 中无任何“timeout=xxx value exceeded”字段，而 flatfile 日志中出现了明显的IO中断。
结论
errorlog 日志中 “timeout=xxx value exceeded”表示vdbench IO 在配置timeout时间内没有任何I/O完成，即出现了IO中断/超时。但当errorlog 日志中无该信息时，也并不意味着后端存储系统未出现故障。
flatfile 日志中 Rate 和 Resp(ms) 为0 时，并不能直接标志 IO处于停滞状态。有可能是因为这个时间点实际上没有发起IO请求（或IO请求已完成），导致Rate=0 和 Resp(ms)=0。
所以，如果要通过检测errorlog 日志来确认后端故障导致IO中断时长，需要保证 vdbench 的IO在故障发生时，一定有IO请求发出。避免故障注入期间出现测试阶段分段执行（比如前后有格式化、数据验证阶段等）同时增加负载连续性保障。
