fio reports verify: bad header rand_seed when using zoned random distribution

[theknowledge]

Running the following job results in corruption reported by FIO:

fio --filename=/dev/nvme0n1 --name=RandomIO_ReadWrite --runtime=1h --time_based=1 --ioengine=libaio --direct=1 --bsrange=4Ki-64Ki --iodepth=256 --numjobs=1 --rw=randrw --verify_interval=4096 --do_verify=1 --verify=crc32c --serialize_overlap=1 --random_distribution=zoned:10/20:10/20:10/20:70/40 --verify_fatal=1 --verify_dump=1

verify: bad header rand_seed 2995889608615900632, wanted 31539244515728664 at file /dev/nvme0n1 offset 43716608, length 4096 (requested block: offset=43716608, length=36864)
   hdr_fail data dumped as nvme0n1.43716608.hdr_fail

I've verified the corruption isn't real using a bus analyser: the device is returning the data that was written, which matches the rand_seed reported above.

The issue got broken somewhere between v3.1 and v3.7 and is resolved in recent releases if I remove the random_distribution parameter. version	zoned	not zoned
fio3.1	pass	pass
fio3.7	bad header	bad header
fio3.12	bad header	pass
fio3.21	bad header	pass

[axboe]

Can you run a git bisect between the two versions? That'd point the finger at the offending commit pretty quickly. Let me know if you need any help running a bisect.

[theknowledge]

Zoned distribution appears to work with verify up to v3.6. The issue first appears in v3.7

[sitsofe]

@theknowledge can you bisect it down to a commit please? See https://github.com/axboe/fio/issues/587#issuecomment-383567687 and below (also see https://github.com/axboe/fio/issues/805#issuecomment-514135835 and below) for examples of this.

[theknowledge]

Bisect came back with 363a5f6568b682071153e4c570ecc60186d6c814 is the first bad commit commit 363a5f6568b682071153e4c570ecc60186d6c814 Author: sscargal steve.scargall@intel.com Date: Mon Apr 16 16:47:47 2018 -0600

The last two tests (3.6-2-gc7d3 and 3.6-1-g363a) failed almost immediately with got signal=11 so didn't get as far as reporting corruption. I chalked those up as 'bad' results; but this may have polluted the conclusion

[vincentkfu]

I was able to reproduce this problem and bisect for me identified f31feaa21642929b6d9d5396b73669372fda9a0a as the first bad commit.

commit f31feaa21642929b6d9d5396b73669372fda9a0a
Author: Jens Axboe <axboe@kernel.dk>
Date:   Tue Apr 17 21:50:55 2018 -0600

    Deprecate verifysort and verifysort_nr

    It was an optimization to read back verifies in a sorted order,
    for rotational storage. But I don't think the option makes much
    sense, and I've never heard of anyone using it. Mark it as
    deprecated, and always verify in the same order that IO was
    written.

    Signed-off-by: Jens Axboe <axboe@kernel.dk>

:100644 100644 b28c3dbc4fd65fdf71b3ad4581a9b27e9aac7511 a2a0b3da61458f4e6171c868f2fb07b4b77faa38 M  backend.c
:100644 100644 585ed86469187a10eaf4e6d6327f4f59a0abaa5c 9e163b35fd68627e147f434adc0288e8cec926fd M  cconv.c
:100644 100644 2bfcac457c217693f1bce4aa6c855a2a67f6e014 4ce4991b57c1eb1a24b2b1304fbbc89cee84326a M  fio.h
:100644 100644 5fbb2386237de6ba8aa106917e9f222ae564e014 633f6175170f4c88004c71fa14e756cf55d22480 M  io_u.c
:100644 100644 3f0fc22bc049121ab7488fd81665adbeafec264b 598548d2f037ad4314254cb4b5f14f9722fb4ebf M  iolog.c
:100644 100644 fb28511953c79e7351eb7040c0414514f1bc7055 1b3ea04d203ac84c0a9179310182eb089518c26c M  options.c
:100644 100644 fdbece64d877ee0edd1e0f5359e2222db611483d 5c77a4e8ecb83089ad2fb6a0322aafcbcab2bc4c M  rate-submit.c
:100644 100644 944feafaf9281d4aab6fadef94ad29d5b7dfde74 4ec570dc12c65a45dac90e531eec00cde222c013 M  thread_options.h
:100644 100644 c5fa24110143cb46cee4a6dad1db9a7e878c6a01 40d484b5c60a6ac281a2d6da5f328be3b15e3f0a M  verify.c

The build with this commit fails:

$ ./fio-f31feaa2 --name=RandomIO_ReadWrite --runtime=30s --size=1G --time_based=1 --ioengine=libaio --direct=1 --bsrange=4Ki-64Ki --iodepth=256 --numjobs=1 --rw=randrw --verify_interval=4096 --do_verify=1 --verify=crc32c --serialize_overlap=1 --random_distribution=zoned:10/20:10/20:10/20:70/40 --verify_fatal=1 --verify_dump=1
RandomIO_ReadWrite: (g=0): rw=randrw, bs=(R) 4096B-64.0KiB, (W) 4096B-64.0KiB, (T) 4096B-64.0KiB, ioengine=libaio, iodepth=256
fio-3.6-5-gf31fe
Starting 1 process
verify: bad header rand_seed 4969837395275860009, wanted 9852480210356360750 at file RandomIO_ReadWrite.0.0 offset 622592, length 4096
       hdr_fail data dumped as RandomIO_ReadWrite.0.0.622592.hdr_fail
verify: bad header rand_seed 3215123527888520192, wanted 46386204153304124 at file RandomIO_ReadWrite.0.0 offset 163840, length 4096
       hdr_fail data dumped as RandomIO_ReadWrite.0.0.163840.hdr_fail
fio: pid=7063, err=84/file:io_u.c:2033, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character

RandomIO_ReadWrite: (groupid=0, jobs=1): err=84 (file:io_u.c:2033, func=io_u_queued_complete, error=Invalid or incomplete multibyte or wide character): pid=7063: Fri Jul 24 09:38:39 2020
   read: IOPS=13.0k, BW=379MiB/s (397MB/s)(512MiB/1353msec)
    slat (usec): min=2, max=10010, avg=22.57, stdev=83.39
    clat (usec): min=247, max=17208, avg=5345.66, stdev=2550.47
     lat (usec): min=280, max=17229, avg=5368.66, stdev=2550.90
    clat percentiles (usec):
     |  1.00th=[ 1012],  5.00th=[ 1762], 10.00th=[ 2311], 20.00th=[ 3064],
     | 30.00th=[ 3785], 40.00th=[ 4359], 50.00th=[ 4948], 60.00th=[ 5669],
     | 70.00th=[ 6521], 80.00th=[ 7570], 90.00th=[ 8848], 95.00th=[ 9765],
     | 99.00th=[12780], 99.50th=[13304], 99.90th=[15926], 99.95th=[16319],
     | 99.99th=[17171]
   bw (  KiB/s): min=364023, max=418297, per=100.00%, avg=391160.00, stdev=38377.51, samples=2
   iops        : min=12061, max=13867, avg=12964.00, stdev=1277.03, samples=2
  write: IOPS=12.9k, BW=379MiB/s (398MB/s)(512MiB/1349msec)
    slat (usec): min=3, max=5812, avg=39.19, stdev=67.18
    clat (usec): min=85, max=16821, avg=4908.84, stdev=2513.90
     lat (usec): min=127, max=17060, avg=4948.37, stdev=2516.41
    clat percentiles (usec):
     |  1.00th=[  644],  5.00th=[ 1336], 10.00th=[ 1860], 20.00th=[ 2704],
     | 30.00th=[ 3359], 40.00th=[ 3982], 50.00th=[ 4555], 60.00th=[ 5276],
     | 70.00th=[ 6063], 80.00th=[ 7046], 90.00th=[ 8455], 95.00th=[ 9241],
     | 99.00th=[11994], 99.50th=[12911], 99.90th=[15401], 99.95th=[15926],
     | 99.99th=[16712]
   bw (  KiB/s): min=363515, max=420332, per=100.00%, avg=391923.50, stdev=40175.69, samples=2
   iops        : min=12045, max=13928, avg=12986.50, stdev=1331.48, samples=2
  lat (usec)   : 100=0.01%, 250=0.05%, 500=0.28%, 750=0.58%, 1000=0.86%
  lat (msec)   : 2=7.38%, 4=27.65%, 10=59.06%, 20=3.42%
  cpu          : usr=24.85%, sys=69.75%, ctx=1749, majf=0, minf=270
  IO depths    : 1=0.1%, 2=0.1%, 4=0.2%, 8=0.9%, 16=3.2%, 32=11.5%, >=64=84.1%
     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.0%, 64=0.0%, >=64=0.1%
     issued rwts: total=17640,17368,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=256

Run status group 0 (all jobs):
   READ: bw=379MiB/s (397MB/s), 379MiB/s-379MiB/s (397MB/s-397MB/s), io=512MiB (537MB), run=1353-1353msec
  WRITE: bw=379MiB/s (398MB/s), 379MiB/s-379MiB/s (398MB/s-398MB/s), io=512MiB (537MB), run=1349-1349msec

Disk stats (read/write):
  sda: ios=17640/17380, merge=3/21, ticks=16608/8356, in_queue=24960, util=86.77%

But the build with its parent finishes without issue:

$ ./fio-c47537ee --name=RandomIO_ReadWrite --runtime=30s --size=1G --time_based=1 --ioengine=libaio --direct=1 --bsrange=4Ki-64Ki --iodepth=256 --numjobs=1 --rw=randrw --verify_interval=4096 --do_verify=1 --verify=crc32c --serialize_overlap=1 --random_distribution=zoned:10/20:10/20:10/20:70/40 --verify_fatal=1 --verify_dump=1
RandomIO_ReadWrite: (g=0): rw=randrw, bs=(R) 4096B-64.0KiB, (W) 4096B-64.0KiB, (T) 4096B-64.0KiB, ioengine=libaio, iodepth=256
fio-3.6-4-gc4753
Starting 1 process
Jobs: 1 (f=1): [m(1)][100.0%][r=521MiB/s,w=241MiB/s][r=18.6k,w=8175 IOPS][eta 00m:00s]
RandomIO_ReadWrite: (groupid=0, jobs=1): err= 0: pid=7895: Fri Jul 24 09:39:45 2020
   read: IOPS=15.8k, BW=451MiB/s (473MB/s)(13.2GiB/30001msec)
    slat (nsec): min=1520, max=9655.6k, avg=23958.74, stdev=59060.89
    clat (usec): min=116, max=33006, avg=6751.06, stdev=2775.88
     lat (usec): min=171, max=33589, avg=6775.39, stdev=2777.58
    clat percentiles (usec):
     |  1.00th=[ 1156],  5.00th=[ 2180], 10.00th=[ 2933], 20.00th=[ 4113],
     | 30.00th=[ 5145], 40.00th=[ 6325], 50.00th=[ 7308], 60.00th=[ 7832],
     | 70.00th=[ 8291], 80.00th=[ 8717], 90.00th=[ 9765], 95.00th=[10814],
     | 99.00th=[12911], 99.50th=[15008], 99.90th=[21890], 99.95th=[27657],
     | 99.99th=[31327]
   bw (  KiB/s): min=82128, max=469301, per=65.13%, avg=300931.17, stdev=101252.35, samples=59
   iops        : min= 2800, max=15494, avg=9972.76, stdev=3321.11, samples=59
  write: IOPS=12.4k, BW=366MiB/s (384MB/s)(8758MiB/23934msec)
    slat (usec): min=3, max=13209, avg=42.47, stdev=59.78
    clat (usec): min=24, max=18409, avg=5201.39, stdev=2552.82
     lat (usec): min=54, max=18442, avg=5244.19, stdev=2554.93
    clat percentiles (usec):
     |  1.00th=[  676],  5.00th=[ 1418], 10.00th=[ 2008], 20.00th=[ 2900],
     | 30.00th=[ 3621], 40.00th=[ 4293], 50.00th=[ 4948], 60.00th=[ 5669],
     | 70.00th=[ 6456], 80.00th=[ 7439], 90.00th=[ 8586], 95.00th=[ 9503],
     | 99.00th=[11863], 99.50th=[12780], 99.90th=[14877], 99.95th=[15533],
     | 99.99th=[16581]
   bw (  KiB/s): min=84288, max=461333, per=80.23%, avg=300633.02, stdev=98598.89, samples=59
   iops        : min= 2892, max=15245, avg=9963.64, stdev=3232.78, samples=59
  lat (usec)   : 50=0.01%, 100=0.01%, 250=0.04%, 500=0.21%, 750=0.42%
  lat (usec)   : 1000=0.66%
  lat (msec)   : 2=5.00%, 4=19.06%, 10=67.98%, 20=6.53%, 50=0.10%
  cpu          : usr=22.91%, sys=74.73%, ctx=23787, majf=0, minf=291
  IO depths    : 1=0.1%, 2=0.1%, 4=0.2%, 8=0.6%, 16=2.4%, 32=8.8%, >=64=87.9%
     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.0%, 64=0.0%, >=64=0.1%
     issued rwts: total=474744,297254,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=256

Run status group 0 (all jobs):
   READ: bw=451MiB/s (473MB/s), 451MiB/s-451MiB/s (473MB/s-473MB/s), io=13.2GiB (14.2GB), run=30001-30001msec
  WRITE: bw=366MiB/s (384MB/s), 366MiB/s-366MiB/s (384MB/s-384MB/s), io=8758MiB (9183MB), run=23934-23934msec

Disk stats (read/write):
  sda: ios=472177/296091, merge=1316/145, ticks=323732/114928, in_queue=438452, util=93.39%

[axboe]

@theknowledge That's definitely not right, you probably wanted to have used bisect skip for those.

@vincentkfu that seems more reasonable

So I wonder if this is really a problem elsewhere. If we make verify.c set the io_u->rand_seed unconditionally, does it pass? What I'm getting at is are we verifying something that wasn't written.

[sitsofe]

Ah it's a randrw verify job. OK I'd say this is #740, #746 and #844, #930 ...

[wangyihanlarry]

Any update on this thread?

[wangyihanlarry]

And what the latest version shall we use to by-pass this issue if possible?

[sitsofe]

@wangyihanlarry I'd recommend steering clear of randrw verification jobs - they are notorious for being difficult.