basic verify - output shows start with read then write?
Strange but during a verify job the output shows that it executed the verify/read operation first then write:
randw/verify: (groupid=0, jobs=1): err= 0: pid=1647: Tue Feb 14 04:08:08 2017
read : io=10240MB, bw=64801KB/s, iops=63, runt=161816msec
slat (usec): min=48, max=16277, avg=423.53, stdev=2263.87
clat (msec): min=18, max=860, avg=488.46, stdev=34.60
lat (msec): min=18, max=860, avg=488.88, stdev=34.65
clat percentiles (msec):
| 1.00th=[ 461], 5.00th=[ 461], 10.00th=[ 465], 20.00th=[ 478],
| 30.00th=[ 482], 40.00th=[ 482], 50.00th=[ 482], 60.00th=[ 482],
| 70.00th=[ 498], 80.00th=[ 498], 90.00th=[ 498], 95.00th=[ 519],
| 99.00th=[ 619], 99.50th=[ 701], 99.90th=[ 783], 99.95th=[ 824],
| 99.99th=[ 840]
write: io=10240MB, bw=54791KB/s, iops=53, runt=191378msec
slat (usec): min=29, max=16341, avg=548.59, stdev=2596.46
clat (msec): min=17, max=1238, avg=578.37, stdev=61.50
lat (msec): min=17, max=1239, avg=578.92, stdev=61.52
clat percentiles (msec):
| 1.00th=[ 478], 5.00th=[ 502], 10.00th=[ 519], 20.00th=[ 523],
| 30.00th=[ 537], 40.00th=[ 603], 50.00th=[ 603], 60.00th=[ 603],
| 70.00th=[ 603], 80.00th=[ 619], 90.00th=[ 619], 95.00th=[ 627],
| 99.00th=[ 742], 99.50th=[ 873], 99.90th=[ 1057], 99.95th=[ 1106],
| 99.99th=[ 1237]bw (KB /s): min= 1549, max=69493, per=99.92%, avg=54747.92, stdev=5798.57 lat (msec) : 20=0.01%, 50=0.01%, 100=0.05%, 250=0.12%, 500=48.41% lat (msec) : 750=50.80%, 1000=0.48%, 2000=0.11%
I used the example from here:
https://github.com/axboe/fio/blob/master/examples/basic-verify.fio
Isn't the results suppose to show the write activity first then the verify/read?
The fio status clearly shows the correct order during the run:
Phase#1 write:
Jobs: 1 (f=1): [w(1)] [1.7% done] [0KB/40408KB/0KB /s] [0/1039/0 iops] [eta 08m:42s]
Phase#2 read/verify
Jobs: 1 (f=1): [V(1)] [51.2% done] [54217KB/0KB/0KB /s] [1052/0/0 iops] [eta 03m:46s]
My confusion was more on how the output file should report...ie write then read but instead its show read then write.
Quoted 32 lines · Slow bucks
Strange but during a verify job the output shows that it executed the verify/read operation first then write:
randw/verify: (groupid=0, jobs=1): err= 0: pid=1647: Tue Feb 14 04:08:08 2017
read : io=10240MB, bw=64801KB/s, iops=63, runt=161816msecslat (usec): min=48, max=16277, avg=423.53, stdev=2263.87 clat (msec): min=18, max=860, avg=488.46, stdev=34.60 lat (msec): min=18, max=860, avg=488.88, stdev=34.65 clat percentiles (msec): | 1.00th=[ 461], 5.00th=[ 461], 10.00th=[ 465], 20.00th=[ 478], | 30.00th=[ 482], 40.00th=[ 482], 50.00th=[ 482], 60.00th=[ 482], | 70.00th=[ 498], 80.00th=[ 498], 90.00th=[ 498], 95.00th=[ 519], | 99.00th=[ 619], 99.50th=[ 701], 99.90th=[ 783], 99.95th=[ 824], | 99.99th=[ 840] write: io=10240MB, bw=54791KB/s, iops=53, runt=191378msec slat (usec): min=29, max=16341, avg=548.59, stdev=2596.46 clat (msec): min=17, max=1238, avg=578.37, stdev=61.50 lat (msec): min=17, max=1239, avg=578.92, stdev=61.52 clat percentiles (msec): | 1.00th=[ 478], 5.00th=[ 502], 10.00th=[ 519], 20.00th=[ 523], | 30.00th=[ 537], 40.00th=[ 603], 50.00th=[ 603], 60.00th=[ 603], | 70.00th=[ 603], 80.00th=[ 619], 90.00th=[ 619], 95.00th=[ 627], | 99.00th=[ 742], 99.50th=[ 873], 99.90th=[ 1057], 99.95th=[ 1106], | 99.99th=[ 1237] bw (KB /s): min= 1549, max=69493, per=99.92%, avg=54747.92, stdev=5798.57 lat (msec) : 20=0.01%, 50=0.01%, 100=0.05%, 250=0.12%, 500=48.41% lat (msec) : 750=50.80%, 1000=0.48%, 2000=0.11%I used the example from here:
https://github.com/axboe/fio/blob/master/examples/basic-verify.fio
Isn't the results suppose to show the write activity first then the verify/read?