Re: [PATCH 00/19] fs: rework and optimize i_version handling in filesystems

From: Jeff Layton
Date: Wed Dec 13 2017 - 15:14:39 EST


On Wed, 2017-12-13 at 10:05 -0500, J. Bruce Fields wrote:
> This is great, thanks.
>
> On Wed, Dec 13, 2017 at 09:19:58AM -0500, Jeff Layton wrote:
> > With this, we reduce inode metadata updates across all 3 filesystems
> > down to roughly the frequency of the timestamp granularity, particularly
> > when it's not being queried (the vastly common case).
> >
> > The pessimal workload here is 1 byte writes, and it helps that
> > significantly. Of course, that's not what we'd consider a real-world
> > workload.
> >
> > A tiobench-example.fio workload also shows some modest performance
> > gains, and I've gotten mails from the kernel test robot that show some
> > significant performance gains on some microbenchmarks (case-msync-mt in
> > the vm-scalability testsuite to be specific), with an earlier version of
> > this set.
> >
> > With larger writes, the gains with this patchset mostly vaporize,
> > but it does not seem to cause performance to regress anywhere, AFAICT.
> >
> > I'm happy to run other workloads if anyone can suggest them.
> >
> > At this point, the patchset works and does what it's expected to do in
> > my own testing. It seems like it's at least a modest performance win
> > across all 3 major disk-based filesystems. It may also encourage others
> > to implement i_version as well since it reduces the cost.
>
> Do you have an idea what the remaining cost is?
>
> Especially in the ext4 case, are you still able to measure any
> difference in performance between the cases where i_version is turned on
> and off, after these patches?

Attached is a fio jobfile + the output from 3 different runs using it
with ext4. This one is using 4k writes. There was no querying of
i_version during the runs. I've done several runs with each and these
are pretty representative of the results:

old = 4.15-rc3, i_version enabled
ivers = 4.15-rc3 + these patches, i_version enabled
noivers = 4.15-rc3 + these patches, i_version disabled

To snip out the run status lines:

old:
WRITE: bw=85.6MiB/s (89.8MB/s), 9994KiB/s-11.1MiB/s (10.2MB/s-11.7MB/s), io=50.2GiB (53.8GB), run=600001-600001msec

ivers:
WRITE: bw=110MiB/s (115MB/s), 13.5MiB/s-14.2MiB/s (14.1MB/s-14.9MB/s), io=64.3GiB (69.0GB), run=600001-600001msec

noivers:
WRITE: bw=117MiB/s (123MB/s), 14.2MiB/s-15.2MiB/s (14.9MB/s-15.9MB/s), io=68.7GiB (73.8GB), run=600001-600001msec

So, I see some performance degradation with -o iversion compared to not
having it enabled (maybe due to the extra atomic fetches?), but this set
erases most of the difference.

> >
> > [1]: On ext4 it must be turned on with the i_version mount option,
> > mostly due to fears of incurring this impact, AFAICT.
>
> So xfs and btrfs both have i_version updates on by default at this
> point? (Assuming the filesystem's created with recent enough tools,
> etc.)
>

Yes. With xfs and btrfs, I don't think you can disable it these days.

--
Jeff Layton <jlayton@xxxxxxxxxx>file1: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-3.0
Starting 8 processes
Jobs: 8 (f=8): [W(8)][100.0%][r=0KiB/s,w=104MiB/s][r=0,w=26.7k IOPS][eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=1191: Wed Dec 13 14:48:18 2017
write: IOPS=3478, BW=13.6MiB/s (14.2MB/s)(8152MiB/600001msec)
slat (usec): min=4, max=1085.0k, avg=240.14, stdev=1750.72
clat (usec): min=58, max=1088.8k, avg=4143.72, stdev=7043.30
lat (usec): min=110, max=1088.9k, avg=4387.89, stdev=7296.91
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 12], 99.50th=[ 35], 99.90th=[ 102], 99.95th=[ 136],
| 99.99th=[ 218]
bw ( KiB/s): min= 993, max=19783, per=12.98%, avg=14575.57, stdev=3800.59, samples=1147
iops : min= 248, max= 4945, avg=3643.57, stdev=950.17, samples=1147
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.16%, 4=70.13%, 10=28.59%, 20=0.36%, 50=0.39%
lat (msec) : 100=0.25%, 250=0.10%, 500=0.01%, 2000=0.01%
cpu : usr=0.95%, sys=89.11%, ctx=452539, majf=0, minf=13
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2086817,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1192: Wed Dec 13 14:48:18 2017
write: IOPS=3626, BW=14.2MiB/s (14.9MB/s)(8500MiB/600001msec)
slat (usec): min=6, max=1084.3k, avg=234.36, stdev=1416.96
clat (usec): min=44, max=1114.2k, avg=3971.34, stdev=5623.69
lat (usec): min=145, max=1114.5k, avg=4208.76, stdev=5823.63
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 7], 99.50th=[ 20], 99.90th=[ 78], 99.95th=[ 106],
| 99.99th=[ 174]
bw ( KiB/s): min= 1595, max=21112, per=13.53%, avg=15201.53, stdev=2969.29, samples=1147
iops : min= 398, max= 5278, avg=3800.04, stdev=742.34, samples=1147
lat (usec) : 50=0.01%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.19%, 4=69.92%, 10=29.06%, 20=0.28%, 50=0.27%
lat (msec) : 100=0.15%, 250=0.05%, 500=0.01%, 2000=0.01%
cpu : usr=0.97%, sys=92.24%, ctx=261214, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2175888,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1193: Wed Dec 13 14:48:18 2017
write: IOPS=3452, BW=13.5MiB/s (14.1MB/s)(8092MiB/600001msec)
slat (usec): min=4, max=1154.9k, avg=242.30, stdev=1896.64
clat (usec): min=64, max=1164.4k, avg=4174.23, stdev=7654.32
lat (usec): min=109, max=1164.5k, avg=4420.55, stdev=7936.35
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 13], 99.50th=[ 36], 99.90th=[ 106], 99.95th=[ 144],
| 99.99th=[ 275]
bw ( KiB/s): min= 529, max=21258, per=12.90%, avg=14493.62, stdev=3880.36, samples=1147
iops : min= 132, max= 5314, avg=3623.03, stdev=970.10, samples=1147
lat (usec) : 100=0.01%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.15%, 4=70.16%, 10=28.51%, 20=0.37%, 50=0.40%
lat (msec) : 100=0.24%, 250=0.10%, 500=0.01%, 750=0.01%, 2000=0.01%
cpu : usr=0.94%, sys=88.67%, ctx=522998, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2071479,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1194: Wed Dec 13 14:48:18 2017
write: IOPS=3511, BW=13.7MiB/s (14.4MB/s)(8230MiB/600001msec)
slat (usec): min=4, max=1085.1k, avg=237.86, stdev=1687.05
clat (usec): min=39, max=1089.1k, avg=4104.43, stdev=6668.41
lat (usec): min=120, max=1089.4k, avg=4346.31, stdev=6898.94
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 12], 99.50th=[ 30], 99.90th=[ 96], 99.95th=[ 132],
| 99.99th=[ 211]
bw ( KiB/s): min= 1112, max=19776, per=13.09%, avg=14707.65, stdev=3393.04, samples=1147
iops : min= 278, max= 4944, avg=3676.69, stdev=848.28, samples=1147
lat (usec) : 50=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.11%, 4=69.99%, 10=28.82%, 20=0.37%, 50=0.39%
lat (msec) : 100=0.19%, 250=0.09%, 500=0.01%, 2000=0.01%
cpu : usr=1.00%, sys=89.85%, ctx=413785, majf=0, minf=12
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2106782,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1195: Wed Dec 13 14:48:18 2017
write: IOPS=3463, BW=13.5MiB/s (14.2MB/s)(8117MiB/600001msec)
slat (usec): min=4, max=1082.7k, avg=241.60, stdev=1838.26
clat (usec): min=63, max=1088.4k, avg=4161.37, stdev=7332.29
lat (usec): min=110, max=1088.7k, avg=4406.97, stdev=7592.92
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 13], 99.50th=[ 35], 99.90th=[ 107], 99.95th=[ 144],
| 99.99th=[ 243]
bw ( KiB/s): min= 496, max=21619, per=12.93%, avg=14528.62, stdev=3710.11, samples=1147
iops : min= 124, max= 5404, avg=3631.78, stdev=927.53, samples=1147
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.15%, 4=70.22%, 10=28.49%, 20=0.38%, 50=0.40%
lat (msec) : 100=0.24%, 250=0.10%, 500=0.01%, 750=0.01%, 2000=0.01%
cpu : usr=0.99%, sys=88.74%, ctx=465671, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2077865,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1196: Wed Dec 13 14:48:18 2017
write: IOPS=3550, BW=13.9MiB/s (14.5MB/s)(8321MiB/600001msec)
slat (usec): min=4, max=1084.5k, avg=234.71, stdev=1655.30
clat (usec): min=48, max=1089.2k, avg=4059.46, stdev=6479.65
lat (usec): min=110, max=1089.4k, avg=4298.19, stdev=6697.09
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 5], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 9], 99.50th=[ 25], 99.90th=[ 88], 99.95th=[ 124],
| 99.99th=[ 222]
bw ( KiB/s): min= 1386, max=19895, per=13.27%, avg=14907.27, stdev=2940.34, samples=1147
iops : min= 346, max= 4973, avg=3726.44, stdev=735.09, samples=1147
lat (usec) : 50=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.02%
lat (msec) : 2=0.12%, 4=69.78%, 10=29.15%, 20=0.34%, 50=0.33%
lat (msec) : 100=0.18%, 250=0.07%, 500=0.01%, 750=0.01%, 2000=0.01%
cpu : usr=0.98%, sys=90.70%, ctx=321526, majf=0, minf=10
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2130283,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1197: Wed Dec 13 14:48:18 2017
write: IOPS=3520, BW=13.8MiB/s (14.4MB/s)(8252MiB/600001msec)
slat (usec): min=4, max=1083.3k, avg=237.04, stdev=1668.77
clat (usec): min=45, max=1092.4k, avg=4093.45, stdev=6715.18
lat (usec): min=110, max=1092.6k, avg=4334.50, stdev=6950.68
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 11], 99.50th=[ 31], 99.90th=[ 95], 99.95th=[ 122],
| 99.99th=[ 215]
bw ( KiB/s): min= 128, max=22949, per=13.16%, avg=14785.06, stdev=3438.70, samples=1147
iops : min= 32, max= 5737, avg=3695.90, stdev=859.68, samples=1147
lat (usec) : 50=0.01%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.15%, 4=70.79%, 10=27.97%, 20=0.35%, 50=0.38%
lat (msec) : 100=0.21%, 250=0.08%, 500=0.01%, 750=0.01%, 2000=0.01%
cpu : usr=1.00%, sys=89.70%, ctx=410771, majf=0, minf=10
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2112511,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1198: Wed Dec 13 14:48:18 2017
write: IOPS=3477, BW=13.6MiB/s (14.2MB/s)(8151MiB/600001msec)
slat (usec): min=4, max=1082.9k, avg=240.13, stdev=1795.84
clat (usec): min=45, max=1115.8k, avg=4144.14, stdev=7175.43
lat (usec): min=115, max=1116.1k, avg=4388.33, stdev=7427.75
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 12], 99.50th=[ 34], 99.90th=[ 103], 99.95th=[ 146],
| 99.99th=[ 222]
bw ( KiB/s): min= 963, max=19951, per=12.99%, avg=14591.74, stdev=3637.39, samples=1147
iops : min= 240, max= 4987, avg=3647.55, stdev=909.34, samples=1147
lat (usec) : 50=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.15%, 4=70.37%, 10=28.36%, 20=0.38%, 50=0.37%
lat (msec) : 100=0.24%, 250=0.10%, 500=0.01%, 2000=0.01%
cpu : usr=0.97%, sys=88.97%, ctx=452510, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2086619,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
WRITE: bw=110MiB/s (115MB/s), 13.5MiB/s-14.2MiB/s (14.1MB/s-14.9MB/s), io=64.3GiB (69.0GB), run=600001-600001msec

Disk stats (read/write):
vdb: ios=0/46063, merge=0/6986, ticks=0/2294756, in_queue=1430067, util=8.76%
file1: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-3.0
Starting 8 processes
Jobs: 8 (f=8): [W(8)][100.0%][r=0KiB/s,w=123MiB/s][r=0,w=31.5k IOPS][eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=1218: Wed Dec 13 14:58:41 2017
write: IOPS=3839, BW=14.0MiB/s (15.7MB/s)(8999MiB/600001msec)
slat (usec): min=4, max=369392, avg=227.73, stdev=1229.83
clat (usec): min=113, max=373025, avg=3923.34, stdev=4848.17
lat (usec): min=118, max=373433, avg=4154.83, stdev=5012.74
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 6], 99.50th=[ 17], 99.90th=[ 79], 99.95th=[ 111],
| 99.99th=[ 194]
bw ( KiB/s): min= 3732, max=22216, per=12.82%, avg=15393.36, stdev=2641.49, samples=1200
iops : min= 933, max= 5554, avg=3847.98, stdev=660.39, samples=1200
lat (usec) : 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.03%
lat (msec) : 2=0.28%, 4=70.76%, 10=28.16%, 20=0.26%, 50=0.25%
lat (msec) : 100=0.13%, 250=0.06%, 500=0.01%
cpu : usr=1.07%, sys=91.99%, ctx=265847, majf=0, minf=12
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2303836,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1219: Wed Dec 13 14:58:41 2017
write: IOPS=3640, BW=14.2MiB/s (14.9MB/s)(8533MiB/600001msec)
slat (usec): min=4, max=367205, avg=242.26, stdev=1701.75
clat (usec): min=105, max=400086, avg=4137.17, stdev=6855.07
lat (usec): min=110, max=400553, avg=4383.15, stdev=7106.79
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 11], 99.50th=[ 35], 99.90th=[ 112], 99.95th=[ 148],
| 99.99th=[ 241]
bw ( KiB/s): min= 264, max=23358, per=12.15%, avg=14587.82, stdev=3928.56, samples=1200
iops : min= 66, max= 5839, avg=3646.64, stdev=982.14, samples=1200
lat (usec) : 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.03%
lat (msec) : 2=0.22%, 4=70.42%, 10=28.26%, 20=0.29%, 50=0.37%
lat (msec) : 100=0.25%, 250=0.11%, 500=0.01%
cpu : usr=0.98%, sys=88.04%, ctx=464380, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2184434,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1220: Wed Dec 13 14:58:41 2017
write: IOPS=3808, BW=14.9MiB/s (15.6MB/s)(8925MiB/600001msec)
slat (usec): min=4, max=348744, avg=230.25, stdev=1217.66
clat (usec): min=110, max=353791, avg=3955.93, stdev=4810.70
lat (usec): min=115, max=354077, avg=4189.87, stdev=4976.17
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 8], 99.50th=[ 22], 99.90th=[ 79], 99.95th=[ 104],
| 99.99th=[ 180]
bw ( KiB/s): min= 1360, max=21672, per=12.71%, avg=15258.19, stdev=2808.41, samples=1200
iops : min= 340, max= 5418, avg=3814.23, stdev=702.12, samples=1200
lat (usec) : 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.04%
lat (msec) : 2=0.25%, 4=70.75%, 10=28.05%, 20=0.32%, 50=0.32%
lat (msec) : 100=0.15%, 250=0.05%, 500=0.01%
cpu : usr=1.03%, sys=91.51%, ctx=315742, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2284898,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1221: Wed Dec 13 14:58:41 2017
write: IOPS=3699, BW=14.4MiB/s (15.2MB/s)(8670MiB/600001msec)
slat (usec): min=4, max=384286, avg=237.31, stdev=1556.89
clat (usec): min=69, max=456496, avg=4071.97, stdev=6252.37
lat (usec): min=109, max=456673, avg=4313.09, stdev=6477.02
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 10], 99.50th=[ 31], 99.90th=[ 104], 99.95th=[ 136],
| 99.99th=[ 211]
bw ( KiB/s): min= 793, max=24016, per=12.35%, avg=14826.33, stdev=3502.09, samples=1200
iops : min= 198, max= 6004, avg=3706.22, stdev=875.53, samples=1200
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.03%
lat (msec) : 2=0.26%, 4=70.92%, 10=27.75%, 20=0.31%, 50=0.36%
lat (msec) : 100=0.22%, 250=0.10%, 500=0.01%
cpu : usr=1.03%, sys=89.25%, ctx=473168, majf=0, minf=12
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2219487,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1222: Wed Dec 13 14:58:41 2017
write: IOPS=3625, BW=14.2MiB/s (14.9MB/s)(8498MiB/600001msec)
slat (usec): min=4, max=375714, avg=243.16, stdev=1737.37
clat (usec): min=59, max=387462, avg=4154.04, stdev=7013.84
lat (usec): min=109, max=387723, avg=4400.98, stdev=7271.32
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 13], 99.50th=[ 39], 99.90th=[ 116], 99.95th=[ 153],
| 99.99th=[ 236]
bw ( KiB/s): min= 729, max=21739, per=12.09%, avg=14519.35, stdev=3986.29, samples=1200
iops : min= 182, max= 5434, avg=3629.62, stdev=996.59, samples=1200
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.03%
lat (msec) : 2=0.28%, 4=70.67%, 10=27.86%, 20=0.33%, 50=0.40%
lat (msec) : 100=0.25%, 250=0.13%, 500=0.01%
cpu : usr=1.03%, sys=87.52%, ctx=510004, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2175576,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1223: Wed Dec 13 14:58:41 2017
write: IOPS=3891, BW=15.2MiB/s (15.9MB/s)(9120MiB/600001msec)
slat (usec): min=4, max=256927, avg=228.15, stdev=981.91
clat (usec): min=55, max=268950, avg=3869.74, stdev=3893.99
lat (usec): min=145, max=300244, avg=4100.95, stdev=4027.72
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 6], 99.50th=[ 15], 99.90th=[ 65], 99.95th=[ 90],
| 99.99th=[ 148]
bw ( KiB/s): min= 1638, max=22276, per=12.99%, avg=15599.33, stdev=2421.87, samples=1200
iops : min= 409, max= 5569, avg=3899.47, stdev=605.49, samples=1200
lat (usec) : 100=0.01%, 250=0.05%, 500=0.02%, 750=0.02%, 1000=0.05%
lat (msec) : 2=0.34%, 4=70.12%, 10=28.76%, 20=0.26%, 50=0.24%
lat (msec) : 100=0.11%, 250=0.03%, 500=0.01%
cpu : usr=1.06%, sys=93.28%, ctx=212422, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2334616,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1224: Wed Dec 13 14:58:41 2017
write: IOPS=3707, BW=14.5MiB/s (15.2MB/s)(8689MiB/600001msec)
slat (usec): min=4, max=356512, avg=237.42, stdev=1554.30
clat (usec): min=42, max=376204, avg=4063.23, stdev=6248.90
lat (usec): min=109, max=376508, avg=4304.36, stdev=6472.77
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 10], 99.50th=[ 31], 99.90th=[ 99], 99.95th=[ 132],
| 99.99th=[ 239]
bw ( KiB/s): min= 1124, max=22706, per=12.40%, avg=14881.48, stdev=3507.39, samples=1200
iops : min= 281, max= 5676, avg=3719.98, stdev=876.86, samples=1200
lat (usec) : 50=0.01%, 250=0.05%, 500=0.02%, 750=0.01%, 1000=0.03%
lat (msec) : 2=0.34%, 4=70.57%, 10=28.00%, 20=0.28%, 50=0.37%
lat (msec) : 100=0.22%, 250=0.09%, 500=0.01%
cpu : usr=1.02%, sys=89.30%, ctx=437871, majf=0, minf=10
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2224313,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1225: Wed Dec 13 14:58:41 2017
write: IOPS=3799, BW=14.8MiB/s (15.6MB/s)(8905MiB/600001msec)
slat (usec): min=4, max=361544, avg=230.35, stdev=1332.97
clat (usec): min=51, max=368069, avg=3965.33, stdev=5387.38
lat (usec): min=110, max=368366, avg=4199.48, stdev=5581.52
clat percentiles (msec):
| 1.00th=[ 3], 5.00th=[ 3], 10.00th=[ 3], 20.00th=[ 4],
| 30.00th=[ 4], 40.00th=[ 4], 50.00th=[ 4], 60.00th=[ 4],
| 70.00th=[ 4], 80.00th=[ 5], 90.00th=[ 5], 95.00th=[ 5],
| 99.00th=[ 7], 99.50th=[ 21], 99.90th=[ 89], 99.95th=[ 123],
| 99.99th=[ 197]
bw ( KiB/s): min= 963, max=22292, per=12.69%, avg=15237.54, stdev=3142.05, samples=1200
iops : min= 240, max= 5573, avg=3809.02, stdev=785.52, samples=1200
lat (usec) : 100=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.02%
lat (msec) : 2=0.23%, 4=71.18%, 10=27.77%, 20=0.26%, 50=0.27%
lat (msec) : 100=0.16%, 250=0.08%, 500=0.01%
cpu : usr=1.01%, sys=91.25%, ctx=341973, majf=0, minf=10
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,2279628,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
WRITE: bw=117MiB/s (123MB/s), 14.2MiB/s-15.2MiB/s (14.9MB/s-15.9MB/s), io=68.7GiB (73.8GB), run=600001-600001msec

Disk stats (read/write):
vdb: ios=1/50323, merge=0/451, ticks=0/1016470, in_queue=362769, util=5.81%
file1: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-3.0
Starting 8 processes
Jobs: 8 (f=8): [W(8)][100.0%][r=0KiB/s,w=82.1MiB/s][r=0,w=21.0k IOPS][eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=1178: Wed Dec 13 14:21:23 2017
write: IOPS=2809, BW=10.0MiB/s (11.5MB/s)(6584MiB/600001msec)
slat (usec): min=5, max=1731.0k, avg=321.00, stdev=4481.26
clat (usec): min=76, max=1736.5k, avg=5171.63, stdev=17687.91
lat (usec): min=141, max=1736.8k, avg=5495.42, stdev=18290.97
clat percentiles (usec):
| 1.00th=[ 1860], 5.00th=[ 2409], 10.00th=[ 2802], 20.00th=[ 3195],
| 30.00th=[ 3556], 40.00th=[ 3818], 50.00th=[ 4015], 60.00th=[ 4228],
| 70.00th=[ 4490], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6063],
| 99.00th=[ 14484], 99.50th=[ 69731], 99.90th=[250610], 99.95th=[337642],
| 99.99th=[574620]
bw ( KiB/s): min= 8, max=24673, per=13.42%, avg=11763.36, stdev=3943.17, samples=1148
iops : min= 2, max= 6168, avg=2940.54, stdev=985.79, samples=1148
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.03%, 1000=0.12%
lat (msec) : 2=1.21%, 4=47.10%, 10=50.36%, 20=0.29%, 50=0.26%
lat (msec) : 100=0.21%, 250=0.29%, 500=0.09%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.68%, sys=79.81%, ctx=652388, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1685538,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1179: Wed Dec 13 14:21:23 2017
write: IOPS=2557, BW=9.99MiB/s (10.5MB/s)(5993MiB/600001msec)
slat (usec): min=5, max=1827.2k, avg=355.53, stdev=5641.37
clat (usec): min=54, max=1833.8k, avg=5680.10, stdev=22700.65
lat (usec): min=139, max=1834.2k, avg=6038.34, stdev=23494.13
clat percentiles (usec):
| 1.00th=[ 1778], 5.00th=[ 2343], 10.00th=[ 2704], 20.00th=[ 3097],
| 30.00th=[ 3490], 40.00th=[ 3752], 50.00th=[ 3982], 60.00th=[ 4178],
| 70.00th=[ 4424], 80.00th=[ 4817], 90.00th=[ 5407], 95.00th=[ 6128],
| 99.00th=[ 35390], 99.50th=[122160], 99.90th=[320865], 99.95th=[387974],
| 99.99th=[918553]
bw ( KiB/s): min= 24, max=26497, per=12.28%, avg=10761.46, stdev=4879.74, samples=1143
iops : min= 6, max= 6624, avg=2690.01, stdev=1219.92, samples=1143
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.03%, 1000=0.14%
lat (msec) : 2=1.48%, 4=49.67%, 10=47.13%, 20=0.31%, 50=0.34%
lat (msec) : 100=0.29%, 250=0.42%, 500=0.15%, 750=0.02%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.63%, sys=72.85%, ctx=984304, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1534249,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1180: Wed Dec 13 14:21:23 2017
write: IOPS=2817, BW=11.0MiB/s (11.5MB/s)(6604MiB/600001msec)
slat (usec): min=5, max=1751.3k, avg=320.34, stdev=4558.52
clat (usec): min=69, max=1755.7k, avg=5156.99, stdev=18063.06
lat (usec): min=138, max=1755.0k, avg=5480.10, stdev=18680.79
clat percentiles (usec):
| 1.00th=[ 1876], 5.00th=[ 2409], 10.00th=[ 2802], 20.00th=[ 3195],
| 30.00th=[ 3556], 40.00th=[ 3785], 50.00th=[ 4015], 60.00th=[ 4228],
| 70.00th=[ 4490], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6063],
| 99.00th=[ 14353], 99.50th=[ 67634], 99.90th=[263193], 99.95th=[337642],
| 99.99th=[683672]
bw ( KiB/s): min= 80, max=20811, per=13.49%, avg=11827.88, stdev=3987.58, samples=1146
iops : min= 20, max= 5202, avg=2956.61, stdev=996.89, samples=1146
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.04%, 1000=0.12%
lat (msec) : 2=1.20%, 4=48.00%, 10=49.47%, 20=0.30%, 50=0.27%
lat (msec) : 100=0.20%, 250=0.29%, 500=0.09%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.66%, sys=79.82%, ctx=604829, majf=0, minf=10
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1690561,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1181: Wed Dec 13 14:21:23 2017
write: IOPS=2837, BW=11.1MiB/s (11.6MB/s)(6651MiB/600001msec)
slat (usec): min=5, max=1700.6k, avg=317.64, stdev=4338.76
clat (usec): min=36, max=1704.3k, avg=5119.44, stdev=16972.87
lat (usec): min=148, max=1704.8k, avg=5439.85, stdev=17539.15
clat percentiles (usec):
| 1.00th=[ 1975], 5.00th=[ 2507], 10.00th=[ 2835], 20.00th=[ 3261],
| 30.00th=[ 3589], 40.00th=[ 3851], 50.00th=[ 4047], 60.00th=[ 4293],
| 70.00th=[ 4555], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6063],
| 99.00th=[ 13829], 99.50th=[ 62129], 99.90th=[240124], 99.95th=[320865],
| 99.99th=[608175]
bw ( KiB/s): min= 48, max=23214, per=13.56%, avg=11881.25, stdev=3784.78, samples=1148
iops : min= 12, max= 5803, avg=2970.05, stdev=946.19, samples=1148
lat (usec) : 50=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.10%
lat (msec) : 2=0.96%, 4=46.54%, 10=51.25%, 20=0.27%, 50=0.30%
lat (msec) : 100=0.21%, 250=0.26%, 500=0.08%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.66%, sys=80.94%, ctx=559902, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1702735,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1182: Wed Dec 13 14:21:23 2017
write: IOPS=2498, BW=9994KiB/s (10.2MB/s)(5856MiB/600001msec)
slat (usec): min=5, max=1758.3k, avg=364.78, stdev=5607.81
clat (usec): min=51, max=1763.5k, avg=5813.05, stdev=22946.68
lat (usec): min=137, max=1763.8k, avg=6180.47, stdev=23776.43
clat percentiles (usec):
| 1.00th=[ 1745], 5.00th=[ 2376], 10.00th=[ 2769], 20.00th=[ 3228],
| 30.00th=[ 3589], 40.00th=[ 3818], 50.00th=[ 4015], 60.00th=[ 4228],
| 70.00th=[ 4490], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6128],
| 99.00th=[ 39060], 99.50th=[128451], 99.90th=[341836], 99.95th=[434111],
| 99.99th=[826278]
bw ( KiB/s): min= 8, max=23134, per=11.96%, avg=10486.76, stdev=5172.17, samples=1146
iops : min= 2, max= 5783, avg=2621.32, stdev=1293.02, samples=1146
lat (usec) : 100=0.01%, 250=0.03%, 500=0.01%, 750=0.03%, 1000=0.13%
lat (msec) : 2=1.44%, 4=47.17%, 10=49.65%, 20=0.28%, 50=0.33%
lat (msec) : 100=0.29%, 250=0.42%, 500=0.17%, 750=0.02%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.63%, sys=72.48%, ctx=1079470, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1499031,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1183: Wed Dec 13 14:21:23 2017
write: IOPS=2743, BW=10.7MiB/s (11.2MB/s)(6429MiB/600001msec)
slat (usec): min=5, max=1738.5k, avg=330.39, stdev=4825.27
clat (usec): min=46, max=1743.0k, avg=5295.46, stdev=19183.60
lat (usec): min=138, max=1744.3k, avg=5628.41, stdev=19855.76
clat percentiles (usec):
| 1.00th=[ 1860], 5.00th=[ 2343], 10.00th=[ 2737], 20.00th=[ 3130],
| 30.00th=[ 3523], 40.00th=[ 3785], 50.00th=[ 3982], 60.00th=[ 4178],
| 70.00th=[ 4424], 80.00th=[ 4817], 90.00th=[ 5342], 95.00th=[ 6063],
| 99.00th=[ 18744], 99.50th=[ 83362], 99.90th=[267387], 99.95th=[379585],
| 99.99th=[675283]
bw ( KiB/s): min= 64, max=23616, per=13.09%, avg=11474.50, stdev=4531.36, samples=1149
iops : min= 16, max= 5904, avg=2868.36, stdev=1132.85, samples=1149
lat (usec) : 50=0.01%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.20%
lat (msec) : 2=1.28%, 4=48.96%, 10=48.23%, 20=0.32%, 50=0.30%
lat (msec) : 100=0.25%, 250=0.31%, 500=0.10%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.63%, sys=77.48%, ctx=758312, majf=0, minf=9
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1645817,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1184: Wed Dec 13 14:21:23 2017
write: IOPS=2850, BW=11.1MiB/s (11.7MB/s)(6680MiB/600001msec)
slat (usec): min=5, max=1758.4k, avg=316.41, stdev=4456.60
clat (usec): min=61, max=1763.5k, avg=5098.26, stdev=17493.16
lat (usec): min=140, max=1763.7k, avg=5417.38, stdev=18076.15
clat percentiles (usec):
| 1.00th=[ 1942], 5.00th=[ 2442], 10.00th=[ 2802], 20.00th=[ 3228],
| 30.00th=[ 3589], 40.00th=[ 3818], 50.00th=[ 4047], 60.00th=[ 4228],
| 70.00th=[ 4490], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6063],
| 99.00th=[ 13042], 99.50th=[ 58983], 99.90th=[248513], 99.95th=[333448],
| 99.99th=[599786]
bw ( KiB/s): min= 32, max=21843, per=13.64%, avg=11953.28, stdev=3732.91, samples=1147
iops : min= 8, max= 5460, avg=2987.95, stdev=933.22, samples=1147
lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.17%
lat (msec) : 2=1.03%, 4=47.02%, 10=50.64%, 20=0.30%, 50=0.29%
lat (msec) : 100=0.19%, 250=0.25%, 500=0.08%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.70%, sys=80.63%, ctx=521547, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1710059,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16
file1: (groupid=0, jobs=1): err= 0: pid=1185: Wed Dec 13 14:21:23 2017
write: IOPS=2798, BW=10.9MiB/s (11.5MB/s)(6559MiB/600001msec)
slat (usec): min=5, max=1848.6k, avg=322.54, stdev=4583.84
clat (usec): min=38, max=1854.1k, avg=5191.27, stdev=18112.72
lat (usec): min=141, max=1854.5k, avg=5516.58, stdev=18734.21
clat percentiles (usec):
| 1.00th=[ 1909], 5.00th=[ 2409], 10.00th=[ 2769], 20.00th=[ 3163],
| 30.00th=[ 3556], 40.00th=[ 3785], 50.00th=[ 4015], 60.00th=[ 4228],
| 70.00th=[ 4490], 80.00th=[ 4883], 90.00th=[ 5407], 95.00th=[ 6063],
| 99.00th=[ 16057], 99.50th=[ 70779], 99.90th=[270533], 99.95th=[358613],
| 99.99th=[616563]
bw ( KiB/s): min= 80, max=23390, per=13.36%, avg=11711.75, stdev=4136.20, samples=1148
iops : min= 20, max= 5847, avg=2927.75, stdev=1034.06, samples=1148
lat (usec) : 50=0.01%, 250=0.01%, 500=0.01%, 750=0.02%, 1000=0.14%
lat (msec) : 2=1.13%, 4=48.61%, 10=48.88%, 20=0.29%, 50=0.29%
lat (msec) : 100=0.22%, 250=0.28%, 500=0.10%, 750=0.01%, 1000=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.69%, sys=79.14%, ctx=652094, majf=0, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.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=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwt: total=0,1679114,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
WRITE: bw=85.6MiB/s (89.8MB/s), 9994KiB/s-11.1MiB/s (10.2MB/s-11.7MB/s), io=50.2GiB (53.8GB), run=600001-600001msec

Disk stats (read/write):
vdb: ios=0/32561, merge=0/6598, ticks=0/5542527, in_queue=3752820, util=15.70%
; fio-seq-write.job for fiotest

[global]
name=fio-seq-write
rw=write
bs=4k
direct=0
time_based=1
runtime=600
numjobs=8

[file1]
filename=/mnt/test/fio.out
size=10G
ioengine=libaio
iodepth=16