Re: [PATCH] [RFC] xfs: wire up aio_fsync method

Dave Chinner
2014-06-16T07:20:14Z

On Sun, Jun 15, 2014 at 08:58:46PM -0600, Jens Axboe wrote:
> On 2014-06-15 20:00, Dave Chinner wrote:
> >On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
> >>On Fri, Jun 13, 2014 at 09:23:52AM -0700, Christoph Hellwig wrote:
> >>>On Fri, Jun 13, 2014 at 09:44:41AM +1000, Dave Chinner wrote:
> >>>>On Thu, Jun 12, 2014 at 07:13:29AM -0700, Christoph Hellwig wrote:
> >>>>>There doesn't really seem anything XFS specific here, so instead
> >>>>>of wiring up ->aio_fsync I'd implement IOCB_CMD_FSYNC in fs/aio.c
> >>>>>based on the workqueue and ->fsync.
> >>>>
> >>>>I really don't know whether the other ->fsync methods in other
> >>>>filesystems can stand alone like that. I also don't have the
> >>>>time to test that it works properly on all filesystems right now.
> >>>
> >>>Of course they can, as shown by various calls to vfs_fsync_range that
> >>>is nothing but a small wrapper around ->fsync.
> >>
> >>Sure, but that's not getting 10,000 concurrent callers, is it? And
> >>some fsync methods require journal credits, and others serialise
> >>completely, and so on.
> >>
> >>Besides, putting an *unbound, highly concurrent* aio queue into the
> >>kernel for an operation that can serialise the entire filesystem
> >>seems like a pretty nasty user-level DOS vector to me.
> >
> >FWIW, the non-linear system CPU overhead of a fs_mark test I've been
> >running isn't anything related to XFS. The async fsync workqueue
> >results in several thousand worker threads dispatching IO
> >concurrently across 16 CPUs:
> >
> >$ ps -ef |grep kworker |wc -l
> >4693
> >$
> >
> >Profiles from 3.15 + xfs for-next + xfs aio_fsync show:
> >
> >- 51.33% [kernel] [k] percpu_ida_alloc
> > - percpu_ida_alloc
> > + 85.73% blk_mq_wait_for_tags
> > + 14.23% blk_mq_get_tag
> >- 14.25% [kernel] [k] _raw_spin_unlock_irqrestore
> > - _raw_spin_unlock_irqrestore
> > - 66.26% virtio_queue_rq
> > - __blk_mq_run_hw_queue
> > - 99.65% blk_mq_run_hw_queue
> > + 99.47% blk_mq_insert_requests
> > + 0.53% blk_mq_insert_request
> >.....
> >- 7.91% [kernel] [k] _raw_spin_unlock_irq
> > - _raw_spin_unlock_irq
> > - 69.59% __schedule
> > - 86.49% schedule
> > + 47.72% percpu_ida_alloc
> > + 21.75% worker_thread
> > + 19.12% schedule_timeout
> >....
> > + 18.06% blk_mq_make_request
> >
> >Runtime:
> >
> >real 4m1.243s
> >user 0m47.724s
> >sys 11m56.724s
> >
> >Most of the excessive CPU usage is coming from the blk-mq layer, and
> >XFS is barely showing up in the profiles at all - the IDA tag
> >allocator is burning 8 CPUs at about 60,000 write IOPS....
> >
> >I know that the tag allocator has been rewritten, so I tested
> >against a current a current Linus kernel with the XFS aio-fsync
> >patch. The results are all over the place - from several sequential
> >runs of the same test (removing the files in between so each tests
> >starts from an empty fs):
> >
> >Wall time sys time IOPS files/s
> >4m58.151s 11m12.648s 30,000 13,500
> >4m35.075s 12m45.900s 45,000 15,000
> >3m10.665s 11m15.804s 65,000 21,000
> >3m27.384s 11m54.723s 85,000 20,000
> >3m59.574s 11m12.012s 50,000 16,500
> >4m12.704s 12m15.720s 50,000 17,000
> >
> >The 3.15 based kernel was pretty consistent around the 4m10 mark,
> >generally only +/-10s in runtime and not much change in system time.
> >The files/s rate reported by fs_mark doesn't vary that much, either.
> >So the new tag allocator seems to be no better in terms of IO
> >dispatch scalability, yet adds significant variability to IO
> >performance.
> >
> >What I noticed is a massive jump in context switch overhead: from
> >around 250,000/s to over 800,000/s and the CPU profiles show that
> >this comes from the new tag allocator:
> >
> >- 34.62% [kernel] [k] _raw_spin_unlock_irqrestore
> > - _raw_spin_unlock_irqrestore
> > - 58.22% prepare_to_wait
> > 100.00% bt_get
> > blk_mq_get_tag
> > __blk_mq_alloc_request
> > blk_mq_map_request
> > blk_sq_make_request
> > generic_make_request
> > - 22.51% virtio_queue_rq
> > __blk_mq_run_hw_queue
> >....
> >- 21.56% [kernel] [k] _raw_spin_unlock_irq
> > - _raw_spin_unlock_irq
> > - 58.73% __schedule
> > - 53.42% io_schedule
> > 99.88% bt_get
> > blk_mq_get_tag
> > __blk_mq_alloc_request
> > blk_mq_map_request
> > blk_sq_make_request
> > generic_make_request
> > - 35.58% schedule
> > + 49.31% worker_thread
> > + 32.45% schedule_timeout
> > + 10.35% _xfs_log_force_lsn
> > + 3.10% xlog_cil_force_lsn
> >....
> >
> >The new block-mq tag allocator is hammering the waitqueues and
> >that's generating a large amount of lock contention. It looks like
> >the new allocator replaces CPU burn doing work in the IDA allocator
> >with the same amount of CPU burn from extra context switch
> >overhead....
> >
> >Oh, OH. Now I understand!
> >
> ># echo 4 > /sys/block/vdc/queue/nr_requests
> >
> ><run workload>
> >
> >80.56% [kernel] [k] _raw_spin_unlock_irqrestore
> > - _raw_spin_unlock_irqrestore
> > - 98.49% prepare_to_wait
> > bt_get
> > blk_mq_get_tag
> > __blk_mq_alloc_request
> > blk_mq_map_request
> > blk_sq_make_request
> > generic_make_request
> > + submit_bio
> > + 1.07% finish_wait
> >+ 13.63% [kernel] [k] _raw_spin_unlock_irq
> >...
> >
> >It's context switch bound at 800,000 context switches/s, burning all
> >16 CPUs waking up and going to sleep and doing very little real
> >work. How little real work? About 3000 IOPS for 2MB/s of IO. That
> >amount of IO should only take a single digit CPU percentage of one
> >CPU.
>
> With thousands of threads? I think not. Sanely submitted 3000 IOPS,
> correct, I would agree with you.
>
> >This seems like bad behaviour to have on a congested block device,
> >even a high performance one....
>
> That is pretty much the suck. How do I reproduce this (eg what are
> you running, and what are the xfs aio fsync patches)? Even if

http://oss.sgi.com/pipermail/xfs/2014-June/036773.html

> dispatching thousands of threads to do IO is a bad idea (it very
> much is), gracefully handling is a must. I haven't seen any bad
> behavior from the new allocator, it seems to be well behaved (for
> most normal cases, anyway). I'd like to take a stab at ensuring this
> works, too.
>
> If you tell me exactly what you are running, I'll reproduce and get
> this fixed up tomorrow.

Test case - take fs_mark:

git://oss.sgi.com/dgc/fs_mark

Apply the patch for aio fsync support:

http://oss.sgi.com/pipermail/xfs/2014-June/036774.html

Run this test:

$ time ./fs_mark -D 10000 -S5 -n 50000 -s 4096 -L 5 -A \
-d /mnt/scratch/0 -d /mnt/scratch/1 -d /mnt/scratch/2 \
-d /mnt/scratch/3 -d /mnt/scratch/4 -d /mnt/scratch/5 \
-d /mnt/scratch/6 -d /mnt/scratch/7 -d /mnt/scratch/8 \
-d /mnt/scratch/9 -d /mnt/scratch/10 -d /mnt/scratch/11 \
-d /mnt/scratch/12 -d /mnt/scratch/13 -d /mnt/scratch/14 \
-d /mnt/scratch/15

Drop the "-A" if you want to use normal fsync (but then you won't
see the problem).

Use a XFS filesystem that has at least 32 AGs (I'm using
a sparse 500TB fs image on a virtio device). I'm also using mkfs
options of "-m crc=1,finobt=1", but to use that last one you'll need
a mkfs built from the xfsprogs git tree. It shouldn't make any
difference to the result, though. I'm running on a VM with 16 CPUs
and 16GB RAM, using fakenuma=4.

Cheers,

Dave.
--
Dave Chinner
david@fromorbit.com