md5 verify with runtime report bad header rand_seed

[jidanjianiunai]

Please acknowledge the following before creating a ticket

• [ v] I have read the GitHub issues section of REPORTING-BUGS.

Description of the bug:
fio --buffer_compress_percentage=82 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 --rw=randrw --verify=md5 --ioengine=libaio --bs=127k --iodepth=32 --numjobs=1 --size=20G --mem_align=512 --rwmixread=30 --group_reporting --name=randrw_30rwmixread_127k_4job_32QD_512mem --runtime=1800 --time_based

randrw_30rwmixread_127k_4job_32QD_512mem: (g=0): rw=randrw, bs=(R) 127KiB-127KiB, (W) 127KiB-127KiB, (T) 127KiB-127KiB, ioengine=libaio, iodepth=32
fio-3.36
Starting 1 thread
verify: bad header rand_seed 2648634942919779000, wanted 53579819933698815 at file /dev/nvme0n1 offset 16910531584, length 130048 (requested block: offset=16910531584, length=130048)
fio: pid=2232122, err=84/file:io_u.c:2213, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character

randrw_30rwmixread_127k_4job_32QD_512mem: (groupid=0, jobs=1): err=84 (file:io_u.c:2213, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character): pid=2232122: Wed May 14 01:47:21 2025
read: IOPS=4309, BW=534MiB/s (560MB/s)(16.6GiB/31807msec)
slat (nsec): min=842, max=10951, avg=1801.98, stdev=683.43
clat (usec): min=98, max=5802, avg=4246.24, stdev=607.89
lat (usec): min=104, max=5805, avg=4248.04, stdev=607.89
clat percentiles (usec):
| 1.00th=[ 2769], 5.00th=[ 3097], 10.00th=[ 3261], 20.00th=[ 3556],
| 30.00th=[ 3884], 40.00th=[ 4621], 50.00th=[ 4621], 60.00th=[ 4621],
| 70.00th=[ 4621], 80.00th=[ 4621], 90.00th=[ 4621], 95.00th=[ 4686],
| 99.00th=[ 5211], 99.50th=[ 5211], 99.90th=[ 5211], 99.95th=[ 5211],
| 99.99th=[ 5211]
bw ( KiB/s): min=125222, max=359664, per=60.90%, avg=333261.37, stdev=35858.98, samples=38
iops : min= 986, max= 2832, avg=2624.11, stdev=282.35, samples=38
write: IOPS=6167, BW=765MiB/s (802MB/s)(14.0GiB/18690msec); 0 zone resets
slat (usec): min=149, max=909, avg=151.84, stdev= 3.85
clat (usec): min=85, max=6276, avg=3503.24, stdev=400.22
lat (usec): min=236, max=6428, avg=3655.08, stdev=400.38
clat percentiles (usec):
| 1.00th=[ 2606], 5.00th=[ 2769], 10.00th=[ 2933], 20.00th=[ 3097],
| 30.00th=[ 3261], 40.00th=[ 3392], 50.00th=[ 3556], 60.00th=[ 3556],
| 70.00th=[ 3720], 80.00th=[ 3884], 90.00th=[ 4015], 95.00th=[ 4178],
| 99.00th=[ 4359], 99.50th=[ 4490], 99.90th=[ 4621], 99.95th=[ 4686],
| 99.99th=[ 4817]
bw ( KiB/s): min=282956, max=787146, per=98.37%, avg=770509.00, stdev=81453.08, samples=38
iops : min= 2228, max= 6198, avg=6067.00, stdev=641.36, samples=38
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.02%, 4=56.80%, 10=43.17%
cpu : usr=97.95%, sys=1.31%, ctx=45, majf=0, minf=3154
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=100.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.1%, 64=0.0%, >=64=0.0%
issued rwts: total=137058,115273,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=32

Run status group 0 (all jobs):
READ: bw=534MiB/s (560MB/s), 534MiB/s-534MiB/s (560MB/s-560MB/s), io=16.6GiB (17.8GB), run=31807-31807msec
WRITE: bw=765MiB/s (802MB/s), 765MiB/s-765MiB/s (802MB/s-802MB/s), io=14.0GiB (15.0GB), run=18690-18690msec

Disk stats (read/write):
nvme0n1: ios=204204/172850, sectors=34551796/29279342, merge=0/0, ticks=18516/2769, in_queue=21285, util=99.74%

Form the ssd data the seed is indeed wrong.

Environment: kernel : 5.14.0-362.24.1.el9_3.x86_64 Red Hat Enterprise Linux 9.3

fio version: 3.36

Reproduction steps
1.make sure the ssd sector size is 512B
2. run the same command as above:
fio --buffer_compress_percentage=82 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 --rw=randrw --verify=md5 --ioengine=libaio --bs=127k --iodepth=32 --numjobs=1 --size=20G --mem_align=512 --rwmixread=30 --group_reporting --name=randrw_30rwmixread_127k_4job_32QD_512mem --runtime=1800 --time_based

3.if the setp 2 can't reproduce the error ,you can try below one:
fio --buffer_compress_percentage=0 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 --rw=randrw --verify=md5 --ioengine=libaio --bs=3k --iodepth=32 --numjobs=1 --size=1m --rwmixread=30 --group_reporting --name=randrw_30rwmixread_3k_4job_32QD_512mem --runtime=20 -time_based

[sitsofe]

Hi @jidanjianiunai,

If we focus on your second job for now can you:

• Remove every option that doesn't stop the problem from happening (e.g. I can tell that --group_reporting won't have an impact but I'm sure there are more). Don't stop removing options at the first option that stops the problem from happening - put it back and then check all the other options.
• Can you check if the problem still occurs if you use a block size that evenly divides the size you're writing over (i.e. does the problem still happen with --bs=4k --size=1m)
• Does the problem still happen with a pure write job (i.e. --rw=randwrite)?
• Does the problem happen if you set --serialize_overlap=1?

[jidanjianiunai]

Hi @sitsofe ,
Please refer to the below test results.

• Remove every option that doesn't stop the problem from happening (e.g. I can tell that --group_reporting won't have an impact but I'm sure there are more). Don't stop removing options at the first option that stops the problem from happening - put it back and then check all the other options.

  remove "--group_reporting" --> FAIL
  remove "--rwmixread=30" --> PASS ( mean the pecentage of write and read are 50) and I try any value of rwmixread value
  less than 43 will fail

• Can you check if the problem still occurs if you use a block size that evenly divides the size you're writing over (i.e. does the problem still happen with --bs=4k --size=1m)
  Use "--bs=4k --size=1m" the second job can run pass:

  fio --buffer_compress_percentage=0 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 --rw=randrw --verify=md5 --ioengine=libaio --bs=4k --iodepth=32 --numjobs=1 --size=1m --rwmixread=30 --group_reporting --name=randrw_30rwmixread_3k_4job_32QD_512mem --runtime=20 -time_based

• Does the problem still happen with a pure write job (i.e. --rw=randwrite)?
  Use "--rw=randwrite" the second job can run pass:

  fio --buffer_compress_percentage=0 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 -- rw=randwrite --verify=md5 --ioengine=libaio --bs=3k --iodepth=32 --numjobs=1 --size=1m --rwmixread=30 --group_reporting --name=randrw_30rwmixread_3k_4job_32QD_512mem --runtime=20 -time_based

• Does the problem happen if you set --serialize_overlap=1?
  Use "serialize_overlap=1" the second job still fail:

  fio --buffer_compress_percentage=0 --buffer_compress_chunk=512 --thread=1 --filename=/dev/nvme0n1 --direct=1 --rw=randrw --verify=md5 --ioengine=libaio --bs=3k --iodepth=32 --numjobs=1 --size=1m --rwmixread=30 --group_reporting --name=randrw_30rwmixread_3k_4job_32QD_512mem --runtime=20 -time_based --serialize_overlap=1

[sitsofe]

This one is strange. I can reproduce the issue 100% of the time with the following:

$ rm -f /tmp/fio.tmp; ./fio --randseed=100 --zero_buffers --verify=md5 --name=test --size=128k --bs=3k --filename=/tmp/fio.tmp --rw=randrw --ioengine=posixaio --iodepth=1 --time_based --runtime=1
[...]
test: (g=0): rw=randrw, bs=(R) 3072B-3072B, (W) 3072B-3072B, (T) 3072B-3072B, ioengine=posixaio, iodepth=1
fio-3.39
Starting 1 process
test: Laying out IO file (1 file / 0MiB)
verify: bad header rand_seed 3187153235204045082, wanted 1795698489843369858 at file /tmp/fio.tmp offset 12288, length 3072 (requested block: offset=12288, length=3072)
fio: pid=1851625, err=84/file:io_u.c:2290, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character

The problem requires an asynchronous I/O engine (e.g. libaio, io_uring, posixaio) even though iodepth=1 and never happens with synchronous I/O engines.

@vincentkfu any ideas?

[vincentkfu]

I was hoping that this was one of the cases @ankit-sam fixed up with the verify patches from a few months ago but no such luck.

I changed your reproducer and set size=4k. The problem is that fio writes 3k blocks at offset 0 twice and then tries to verify. It expects the header seed to be the seed from the first block written but of course this data is no longer there and what is read back is the header seed from the second write.

So I think the verify code is fine; we just need to make sure fio starts verifying after the first 3k block is written. It is strange that this does not happen with sync ioengines.

One work-around is to set verify_header_seed=0 although this is only available in fio builds since March.

Here is output with added debug prints illustrating the issue:

vincent@fio-dev:~/fio-dev/fio-canonical$ ./fio --randseed=100 --zero_buffers --verify=md5 --name=test --size=4k --bs=3k --filename=/tmp/fio.tmp --rw=randrw --ioengine=posixaio --iodepth=1 --time_based --runtime=1 --debug=io,verify
fio: set debug option io
fio: set debug option verify
verify   5127  td->trim_verify=0
test: (g=0): rw=randrw, bs=(R) 3072B-3072B, (W) 3072B-3072B, (T) 3072B-3072B, ioengine=posixaio, iodepth=1
fio-3.39-61-g171e1-dirty
Starting 1 process
verify   5129  saving verify_state, s1 = 18214480664391586905
io       5129  declare unneeded cache /tmp/fio.tmp: 0/4096
io       5129  fill: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: ret=0
io       5129  queue: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  calling ->commit(), depth 1
io       5129  io_u_queued_complete: min=1
io       5129  getevents: 1
io       5129  complete: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  declare unneeded cache /tmp/fio.tmp: 0/4096
io       5129  fill: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: ret=0
io       5129  queue: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  calling ->commit(), depth 1
io       5129  io_u_queued_complete: min=1
io       5129  getevents: 1
io       5129  complete: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
verify   5129  restoring verify_state, s1 = 18214480664391586905
verify   5129  starting loop
verify   5129  get_next_verify: empty
verify   5129  exiting loop
verify   5129  saving verify_state, s1 = 18214480664391586905
io       5129  declare unneeded cache /tmp/fio.tmp: 0/4096
io       5129  fill: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: ret=0
verify   5129  fill random bytes len=3072
verify   5129  rand_seed = 5043760469812167271
verify   5129  fill md5 io_u 0x557b2807f340, len 3072
io       5129  queue: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  calling ->commit(), depth 1
io       5129  io_u_queued_complete: min=1
io       5129  getevents: 1
io       5129  complete: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  declare unneeded cache /tmp/fio.tmp: 0/4096
io       5129  fill: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: ret=0
verify   5129  fill random bytes len=3072
verify   5129  rand_seed = 1914133739899155789
verify   5129  fill md5 io_u 0x557b2807f340, len 3072
io       5129  queue: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
io       5129  calling ->commit(), depth 1
io       5129  io_u_queued_complete: min=1
io       5129  getevents: 1
io       5129  complete: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=1,file=/tmp/fio.tmp
verify   5129  restoring verify_state, s1 = 18214480664391586905
verify   5129  starting loop
io       5129  declare unneeded cache /tmp/fio.tmp: 0/4096
verify   5129  get_next_verify: ret io_u 0x557b2807f340
io       5129  prep: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  prep: io_u 0x557b2807f340: ret=0
io       5129  queue: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
io       5129  calling ->commit(), depth 1
io       5129  io_u_queued_complete: min=1
io       5129  getevents: 1
io       5129  complete: io_u 0x557b2807f340: off=0x0,len=0xc00,ddir=0,file=/tmp/fio.tmp
verify: bad header rand_seed 1914133739899155789, wanted 5043760469812167271 at file /tmp/fio.tmp offset 0, length 3072 (requested block: offset=0, length=3072)
io       5129  io_u_queued_complete: min=0
io       5129  getevents: 0
verify   5129  exiting loop
fio: pid=5129, err=84/file:io_u.c:2301, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character
io       5129  close ioengine posixaio
io       5129  free ioengine posixaio

test: (groupid=0, jobs=1): err=84 (file:io_u.c:2301, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character): pid=5129: Fri May 16 09:36:48 2025
  read: IOPS=3000, BW=9000KiB/s (9216kB/s)(9216B/1msec)
    slat (usec): min=14, max=113, avg=49.28, stdev=55.49
    clat (usec): min=48, max=120, avg=74.02, stdev=40.49
     lat (usec): min=63, max=165, avg=123.31, stdev=53.53
    clat percentiles (usec):
     |  1.00th=[   49],  5.00th=[   49], 10.00th=[   49], 20.00th=[   49],
     | 30.00th=[   49], 40.00th=[   53], 50.00th=[   53], 60.00th=[   53],
     | 70.00th=[  121], 80.00th=[  121], 90.00th=[  121], 95.00th=[  121],
     | 99.00th=[  121], 99.50th=[  121], 99.90th=[  121], 99.95th=[  121],
     | 99.99th=[  121]
  write: IOPS=2000, BW=6000KiB/s (6144kB/s)(6144B/1msec); 0 zone resets
    slat (nsec): min=37902, max=38943, avg=38422.50, stdev=736.10
    clat (nsec): min=50786, max=58620, avg=54703.00, stdev=5539.47
     lat (nsec): min=89729, max=96522, avg=93125.50, stdev=4803.38
    clat percentiles (nsec):
     |  1.00th=[50944],  5.00th=[50944], 10.00th=[50944], 20.00th=[50944],
     | 30.00th=[50944], 40.00th=[50944], 50.00th=[50944], 60.00th=[58624],
     | 70.00th=[58624], 80.00th=[58624], 90.00th=[58624], 95.00th=[58624],
     | 99.00th=[58624], 99.50th=[58624], 99.90th=[58624], 99.95th=[58624],
     | 99.99th=[58624]
  lat (usec)   : 50=20.00%, 100=60.00%, 250=20.00%
  cpu          : usr=0.00%, sys=0.00%, ctx=5, majf=0, minf=27
  IO depths    : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=9.1%, 4=90.9%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwts: total=3,2,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
   READ: bw=9000KiB/s (9216kB/s), 9000KiB/s-9000KiB/s (9216kB/s-9216kB/s), io=9216B (9216B), run=1-1msec
  WRITE: bw=6000KiB/s (6144kB/s), 6000KiB/s-6000KiB/s (6144kB/s-6144kB/s), io=6144B (6144B), run=1-1msec
...