Huge reduction in write bandwidth with filesystem vs direct block device

Huge reduction in write bandwidth with filesystem vs direct block device

[Rick Warner]

Hi all,

We're working with NVME storage systems and are seeing a significant 
reduction in write speed with an XFS filesystem vs direct access to the 
block device.

Using a 5 disk software RAID5, we're able to get ~16GB/s write speed 
direct to the device.  If we put an XFS filesystem on the software RAID 
and run the same fio command (except --directory /xfs instead of 
--filename /dev/md11) we only get ~2.5GB/s write speed.

Are there any tunables that could improve this? Is performance 
degradation this big considered a bug?

The fio runs showing this are below:

*******Direct to /dev/md11 block device
[root@flashstore ~]# fio --filename=/dev/md11 --rw=write --numjobs=32 
--size=12G --bs=1M --name=1m --group_reporting
1m: (g=0): rw=write, bs=(R) 1024KiB-1024KiB, (W) 1024KiB-1024KiB, (T) 
1024KiB-1024KiB, ioengine=psync, iodepth=1
...
fio-3.7
Starting 32 processes
Jobs: 26 (f=26): 
[f(1),_(1),f(16),_(1),f(3),_(2),f(3),_(1),f(2),_(1),f(1)][100.0%][r=0KiB/s,w=0KiB/s][r=0,w=0 
IOPS][eta 00m:00s]
1m: (groupid=0, jobs=32): err= 0: pid=74592: Mon Jan 25 12:13:28 2021
   write: IOPS=15.4k, BW=15.0GiB/s (16.1GB/s)(384GiB/25551msec)
     clat (usec): min=230, max=31691, avg=2044.43, stdev=778.36
      lat (usec): min=245, max=31710, avg=2067.97, stdev=783.21
     clat percentiles (usec):
      |  1.00th=[  420],  5.00th=[ 1745], 10.00th=[ 1811], 20.00th=[ 1860],
      | 30.00th=[ 1893], 40.00th=[ 1926], 50.00th=[ 1942], 60.00th=[ 1975],
      | 70.00th=[ 2024], 80.00th=[ 2089], 90.00th=[ 2180], 95.00th=[ 2900],
      | 99.00th=[ 4490], 99.50th=[ 4883], 99.90th=[13829], 99.95th=[14746],
      | 99.99th=[20841]
    bw (  KiB/s): min=400606, max=679936, per=3.13%, avg=492489.85, 
stdev=53436.36, samples=1632
    iops        : min=  391, max=  664, avg=480.90, stdev=52.18, 
samples=1632
   lat (usec)   : 250=0.01%, 500=1.72%, 750=0.80%, 1000=0.09%
   lat (msec)   : 2=62.47%, 4=32.77%, 10=1.94%, 20=0.20%, 50=0.01%
   cpu          : usr=1.37%, sys=62.91%, ctx=38028757, majf=0, minf=60496
   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=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, 
 >=64=0.0%
      issued rwts: total=0,393216,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):
   WRITE: bw=15.0GiB/s (16.1GB/s), 15.0GiB/s-15.0GiB/s 
(16.1GB/s-16.1GB/s), io=384GiB (412GB), run=25551-25551msec

Disk stats (read/write):
     md11: ios=98/2237881, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, 
aggrios=10252/73455, aggrmerge=20863/582117, aggrticks=4425/138224, 
aggrin_queue=130116, aggrutil=17.71%
   nvme2n1: ios=12427/88141, merge=25370/698549, ticks=5030/163534, 
in_queue=153382, util=16.71%
   nvme3n1: ios=12210/88148, merge=24728/698544, ticks=4979/162745, 
in_queue=152592, util=16.84%
   nvme4n1: ios=12246/88150, merge=24861/698524, ticks=4875/165703, 
in_queue=156034, util=16.81%
   nvme5n1: ios=12289/88146, merge=25200/698533, ticks=5013/164900, 
in_queue=154398, util=16.96%
   nvme6n1: ios=12343/88149, merge=25021/698553, ticks=6655/172464, 
in_queue=164291, util=17.71%
   nvme22n1: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%

******* mkfs.xfs on /dev/md11 (w/ no flags) and fio run on that mount
[root@flashstore ~]# fio --directory=/xfs --rw=write --numjobs=32 
--size=12G --bs=1M --name=1m --group_reporting
1m: (g=0): rw=write, bs=(R) 1024KiB-1024KiB, (W) 1024KiB-1024KiB, (T) 
1024KiB-1024KiB, ioengine=psync, iodepth=1
...
fio-3.7
Starting 32 processes
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
1m: Laying out IO file (1 file / 12288MiB)
Jobs: 11 (f=11): 
[_(6),W(1),_(4),W(1),_(8),W(1),_(3),W(8)][99.4%][r=0KiB/s,w=1213MiB/s][r=0,w=1213 
IOPS][eta 00m:01s]
1m: (groupid=0, jobs=32): err= 0: pid=74782: Mon Jan 25 12:20:32 2021
   write: IOPS=2431, BW=2432MiB/s (2550MB/s)(384GiB/161704msec)
     clat (usec): min=251, max=117777, avg=13006.54, stdev=23856.18
      lat (usec): min=270, max=117787, avg=13027.39, stdev=23851.96
     clat percentiles (usec):
      |  1.00th=[  359],  5.00th=[  371], 10.00th=[  383], 20.00th=[ 408],
      | 30.00th=[  424], 40.00th=[  453], 50.00th=[  537], 60.00th=[ 578],
      | 70.00th=[  619], 80.00th=[55313], 90.00th=[58459], 95.00th=[60556],
      | 99.00th=[63177], 99.50th=[64226], 99.90th=[66323], 99.95th=[68682],
      | 99.99th=[80217]
    bw (  KiB/s): min=55296, max=1054720, per=3.15%, avg=78557.24, 
stdev=41896.99, samples=10233
    iops        : min=   54, max= 1030, avg=76.67, stdev=40.92, 
samples=10233
   lat (usec)   : 500=46.14%, 750=31.31%, 1000=0.78%
   lat (msec)   : 2=0.03%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.59%
   lat (msec)   : 100=21.13%, 250=0.01%
   cpu          : usr=0.12%, sys=3.83%, ctx=86515, majf=0, minf=22227
   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=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, 
 >=64=0.0%
      issued rwts: total=0,393216,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):
   WRITE: bw=2432MiB/s (2550MB/s), 2432MiB/s-2432MiB/s 
(2550MB/s-2550MB/s), io=384GiB (412GB), run=161704-161704msec

Disk stats (read/write):
     md11: ios=1/6097731, merge=0/0, ticks=0/0, in_queue=0, util=0.00%, 
aggrios=23774/2849499, aggrmerge=34232/17493878, 
aggrticks=28040/18125298, aggrin_queue=18363574, aggrutil=80.03%
   nvme2n1: ios=28860/3419298, merge=41127/20992122, 
ticks=39496/23053174, in_queue=23421586, util=75.76%
   nvme3n1: ios=28440/3419396, merge=41081/20992524, 
ticks=34881/23067448, in_queue=23411872, util=80.03%
   nvme4n1: ios=28457/3419413, merge=41361/20992713, 
ticks=30990/21139316, in_queue=21420720, util=78.03%
   nvme5n1: ios=28131/3419446, merge=40331/20992920, 
ticks=29288/20184431, in_queue=20418749, util=77.00%
   nvme6n1: ios=28759/3419446, merge=41496/20992991, 
ticks=33587/21307424, in_queue=21508518, util=77.04%
   nvme22n1: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%


Thanks,
Rick

Re: Huge reduction in write bandwidth with filesystem vs direct block device

[Dave Chinner]

On Mon, Jan 25, 2021 at 12:23:57PM -0500, Rick Warner wrote:
> Hi all,
> 
> We're working with NVME storage systems and are seeing a significant
> reduction in write speed with an XFS filesystem vs direct access to the
> block device.
> 
> Using a 5 disk software RAID5, we're able to get ~16GB/s write speed direct
> to the device.  If we put an XFS filesystem on the software RAID and run the
> same fio command (except --directory /xfs instead of --filename /dev/md11)
> we only get ~2.5GB/s write speed.

What kernel? What's the RAID configuration? What's the mkfs.xfs output?

https://xfs.org/index.php/XFS_FAQ#Q:_What_information_should_I_include_when_reporting_a_problem.3F


> Are there any tunables that could improve this? Is performance degradation
> this big considered a bug?

No evidence that there's a bug yet. You're not testing apples to
apples.

> 
> The fio runs showing this are below:
> 
> *******Direct to /dev/md11 block device
> [root@flashstore ~]# fio --filename=/dev/md11 --rw=write --numjobs=32
> --size=12G --bs=1M --name=1m --group_reporting
> 1m: (g=0): rw=write, bs=(R) 1024KiB-1024KiB, (W) 1024KiB-1024KiB, (T)
> 1024KiB-1024KiB, ioengine=psync, iodepth=1

This is writing 32 concurrent jobs all running from offset 0 in the
block device doing single, synchronous IOs. IOWs, 32 IOs from offset
0, 32 IOs from offset 1MB, etc all the way through the block device.

It's not the same thing as doing 32 concurrent IOs to 32 different
files, all of which will be located in different physical offsets in
the RAID device. You've got a 32x increase in dirty LBAs for the
filesystem test, and no overlap between any of the jobs. So the RAID
device and all the storage devices are doing 32x as much work as the
block device job...

To replicate the same IO on the block device, each job writing to
the block device needs to be allocated it's own 12GB region in the
block device (i.e. job 0 at offset 0, job 1 at offset 12GB, etc) so
there is no overlapping, concurrent IO to the same device offset....

Also, synchronous IO is the key here: individual job throughput is
IO latency bound for synchronous IO and device queue depths are
greatly limited. Hence any submission or completion delay is going
to greatly impact test throughput. Nobody uses synchronous IO for
high throughput applications these days...

> Starting 32 processes
> Jobs: 26 (f=26): [f(1),_(1),f(16),_(1),f(3),_(2),f(3),_(1),f(2),_(1),f(1)][100.0%][r=0KiB/s,w=0KiB/s][r=0,w=0
> IOPS][eta 00m:00s]
> 1m: (groupid=0, jobs=32): err= 0: pid=74592: Mon Jan 25 12:13:28 2021
>   write: IOPS=15.4k, BW=15.0GiB/s (16.1GB/s)(384GiB/25551msec)
>     clat (usec): min=230, max=31691, avg=2044.43, stdev=778.36
>      lat (usec): min=245, max=31710, avg=2067.97, stdev=783.21
>     clat percentiles (usec):
>      |  1.00th=[  420],  5.00th=[ 1745], 10.00th=[ 1811], 20.00th=[ 1860],
>      | 30.00th=[ 1893], 40.00th=[ 1926], 50.00th=[ 1942], 60.00th=[ 1975],
>      | 70.00th=[ 2024], 80.00th=[ 2089], 90.00th=[ 2180], 95.00th=[ 2900],
>      | 99.00th=[ 4490], 99.50th=[ 4883], 99.90th=[13829], 99.95th=[14746],
>      | 99.99th=[20841]

Note the IO latencies....

>    bw (  KiB/s): min=400606, max=679936, per=3.13%, avg=492489.85,
> stdev=53436.36, samples=1632
>    iops        : min=  391, max=  664, avg=480.90, stdev=52.18, samples=1632
>   lat (usec)   : 250=0.01%, 500=1.72%, 750=0.80%, 1000=0.09%
>   lat (msec)   : 2=62.47%, 4=32.77%, 10=1.94%, 20=0.20%, 50=0.01%
>   cpu          : usr=1.37%, sys=62.91%, ctx=38028757, majf=0, minf=60496
>   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=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
> >=64=0.0%
>      issued rwts: total=0,393216,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):
>   WRITE: bw=15.0GiB/s (16.1GB/s), 15.0GiB/s-15.0GiB/s (16.1GB/s-16.1GB/s),
> io=384GiB (412GB), run=25551-25551msec
> 
> Disk stats (read/write):
>     md11: ios=98/2237881, merge=0/0, ticks=0/0, in_queue=0, util=0.00%,
> aggrios=10252/73455, aggrmerge=20863/582117, aggrticks=4425/138224,
> aggrin_queue=130116, aggrutil=17.71%
>   nvme2n1: ios=12427/88141, merge=25370/698549, ticks=5030/163534,
> in_queue=153382, util=16.71%
>   nvme3n1: ios=12210/88148, merge=24728/698544, ticks=4979/162745,
> in_queue=152592, util=16.84%
>   nvme4n1: ios=12246/88150, merge=24861/698524, ticks=4875/165703,
> in_queue=156034, util=16.81%
>   nvme5n1: ios=12289/88146, merge=25200/698533, ticks=5013/164900,
> in_queue=154398, util=16.96%
>   nvme6n1: ios=12343/88149, merge=25021/698553, ticks=6655/172464,
> in_queue=164291, util=17.71%

Note the IOs reaching the disks here - ~90k writes each disk for the
entire test, so ~450,000 1MB IOs gives ~450GB which roughly matches
with the amount written when parity overhead is taken into account.

>   nvme22n1: ios=0/0, merge=0/0, ticks=0/0, in_queue=0, util=0.00%
> 
> ******* mkfs.xfs on /dev/md11 (w/ no flags) and fio run on that mount
> [root@flashstore ~]# fio --directory=/xfs --rw=write --numjobs=32 --size=12G
> --bs=1M --name=1m --group_reporting

--fallocate=none is needed to make the filesystem workload a pure
overwrite workload the same as the block device. Otherwise
preallocation is used to lay out the files, and that then requires
unwritten conversion of the IO range during IO completion. Unwritten
conversion increases IO completion latency, which reduces bandwidth
for synchronous IO submission/completion.

> 1m: (g=0): rw=write, bs=(R) 1024KiB-1024KiB, (W) 1024KiB-1024KiB, (T)
> 1024KiB-1024KiB, ioengine=psync, iodepth=1
> ...
> fio-3.7
> Starting 32 processes
> 1m: Laying out IO file (1 file / 12288MiB)
.....
> 1m: Laying out IO file (1 file / 12288MiB)
> Jobs: 11 (f=11): [_(6),W(1),_(4),W(1),_(8),W(1),_(3),W(8)][99.4%][r=0KiB/s,w=1213MiB/s][r=0,w=1213
> IOPS][eta 00m:01s]
> 1m: (groupid=0, jobs=32): err= 0: pid=74782: Mon Jan 25 12:20:32 2021
>   write: IOPS=2431, BW=2432MiB/s (2550MB/s)(384GiB/161704msec)
>     clat (usec): min=251, max=117777, avg=13006.54, stdev=23856.18
>      lat (usec): min=270, max=117787, avg=13027.39, stdev=23851.96
>     clat percentiles (usec):
>      |  1.00th=[  359],  5.00th=[  371], 10.00th=[  383], 20.00th=[ 408],
>      | 30.00th=[  424], 40.00th=[  453], 50.00th=[  537], 60.00th=[ 578],
>      | 70.00th=[  619], 80.00th=[55313], 90.00th=[58459], 95.00th=[60556],
>      | 99.00th=[63177], 99.50th=[64226], 99.90th=[66323], 99.95th=[68682],
>      | 99.99th=[80217]

Compare the IO latencies with the block device. Average is 13ms per
1MB IO for XFS vs 2ms for the block device. There's the entire
performance difference right there - 6x longer IO latency on XFS
means it will only acheive 1/6th the bandwidth of the block device
because synchronous IO.

It could just be that the filesystem isn't aligned to the underlying
RAID geometry, and so every 1MB IO the filesystem issues to the md
device is misaligned to the RAID stripe and so MD is doing huge
numbers of partial stripe writes and that's what is killing
performance....

That said, 13ms latency for a single 1MB IO on a device that should
take 2ms is potentially indicative of a scheduler bug: we've had
bugs in completion workqueue task scheduling that have caused
exactly this issue (10ms delays in IO completion task scheduling) in
recent times. This scheduler commit fixed multiple performance
regressions in XFS:

52262ee567ad ("sched/fair: Allow a per-CPU kthread waking a task to
stack on the same CPU, to fix XFS performance regression")

Which brings me back to "what kernel and platform are you
testing?"...

>    bw (  KiB/s): min=55296, max=1054720, per=3.15%, avg=78557.24,
> stdev=41896.99, samples=10233
>    iops        : min=   54, max= 1030, avg=76.67, stdev=40.92, samples=10233

Note that the per-job throughput peaked at over 1GB/s for a specific
job - that's what I'd expect to see on XFS for all jobs, not just an
occasional sample....

>   lat (usec)   : 500=46.14%, 750=31.31%, 1000=0.78%
>   lat (msec)   : 2=0.03%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.59%
>   lat (msec)   : 100=21.13%, 250=0.01%
>   cpu          : usr=0.12%, sys=3.83%, ctx=86515, majf=0, minf=22227
>   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=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
> >=64=0.0%
>      issued rwts: total=0,393216,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):
>   WRITE: bw=2432MiB/s (2550MB/s), 2432MiB/s-2432MiB/s (2550MB/s-2550MB/s),
> io=384GiB (412GB), run=161704-161704msec
> 
> Disk stats (read/write):
>     md11: ios=1/6097731, merge=0/0, ticks=0/0, in_queue=0, util=0.00%,
> aggrios=23774/2849499, aggrmerge=34232/17493878, aggrticks=28040/18125298,
> aggrin_queue=18363574, aggrutil=80.03%
>   nvme2n1: ios=28860/3419298, merge=41127/20992122, ticks=39496/23053174,
> in_queue=23421586, util=75.76%
>   nvme3n1: ios=28440/3419396, merge=41081/20992524, ticks=34881/23067448,
> in_queue=23411872, util=80.03%
>   nvme4n1: ios=28457/3419413, merge=41361/20992713, ticks=30990/21139316,
> in_queue=21420720, util=78.03%
>   nvme5n1: ios=28131/3419446, merge=40331/20992920, ticks=29288/20184431,
> in_queue=20418749, util=77.00%
>   nvme6n1: ios=28759/3419446, merge=41496/20992991, ticks=33587/21307424,
> in_queue=21508518, util=77.04%

That's not pretty. That looks like partial stripe writes - 3.4
million write IOs per device (instead of ~90,000) and 20m merges per
device is indicative of MD slicing and dicing the IO it is receiving
from the higher level up into a huge number of tiny IOs. i.e. the
devices are not getting well formed/well aligned IO so working out
why this is happening is probably the first thing to look at.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com