xfs: wire up aio_fsync method

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.

Quoted 3 lines · Christoph Hellwig

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.

Also, doing this implementation in fs/aio.c would mean we can't optimise it to reduce things like log forces by splitting up the work of concurrent fsyncs into a single log force of the highest LSN of the batch of fsyncs being run. We also want to be able to do "background fsync" where latency doesn't matter and we only want to trickle them out rather than issue them as fast as we possibly can.

So I really don't see this as the infrastructure solution that everyone uses. It could be made a generic method with the filesystem passing the workqueue to use to generic_aio_fsync(), but for XFS I see it turning into something much more complex and optimised...

Quoted 5 lines · Dave Chinner

Quoted 3 lines · Christoph Hellwig

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.

Quoted 3 lines

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.

I'm pretty sure if you
Cc linux-fsdevel you'll find plenty of testers. -fsdevel and -man should get a Cc anyway when implementing an ABI that had it's constants defines but never was implemented properly.

Talking about documentation: The kernel aio manpages (io_*.2) seems to not really be very useful, mostly because they don't explain how to set up the iocbs. Michael, any idea how to get started to improve this?

Quoted 6 lines

Also, doing this implementation in fs/aio.c would mean we can't optimise it to reduce things like log forces by splitting up the work of concurrent fsyncs into a single log force of the highest LSN of the batch of fsyncs being run. We also want to be able to do "background fsync" where latency doesn't matter and we only want to trickle them out rather than issue them as fast as we possibly can.

It didn't really sound like you were aiming for that. But in that case the current implementation is still useful as a generic_file_aio_fsync as suggested by Brian.

Quoted 4 lines

So I really don't see this as the infrastructure solution that everyone uses. It could be made a generic method with the filesystem passing the workqueue to use to generic_aio_fsync(), but for XFS I see it turning into something much more complex and optimised...

Why not have a common workqueue? In fact we already have a common workqueue to call ->fsync from aio code to implement aio O_SYNC anyway.

Quoted 6 lines · Christoph Hellwig

Quoted 5 lines · Dave Chinner

Quoted 3 lines · Christoph Hellwig

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.

Quoted 6 lines

Quoted 3 lines

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.

Quoted 14 lines · Dave Chinner

Quoted 6 lines · Christoph Hellwig

Quoted 5 lines · Dave Chinner

Quoted 3 lines · Christoph Hellwig

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.

Quoted 6 lines

Quoted 3 lines

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.

Quoted 7 lines

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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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.

This seems like bad behaviour to have on a congested block device, even a high performance one....

Quoted 146 lines · Dave Chinner

Quoted 14 lines · Dave Chinner

Quoted 6 lines · Christoph Hellwig

Quoted 5 lines · Dave Chinner

Quoted 3 lines · Christoph Hellwig

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.

Quoted 6 lines

Quoted 3 lines

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.

Quoted 7 lines

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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
...

Quoted 5 lines

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.

Quoted 2 lines

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

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.

Quoted 153 lines · Jens Axboe

Quoted 146 lines · Dave Chinner

Quoted 14 lines · Dave Chinner

Quoted 6 lines · Christoph Hellwig

Quoted 5 lines · Dave Chinner

Quoted 3 lines · Christoph Hellwig

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.

Quoted 6 lines

Quoted 3 lines

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.

Quoted 7 lines

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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
...

Quoted 5 lines

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.

Quoted 8 lines

With thousands of threads? I think not. Sanely submitted 3000 IOPS, correct, I would agree with you.

Quoted 2 lines

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

Quoted 8 lines

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 \

(quoted diff) +0 -6

-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.

Quoted 99 lines · Dave Chinner

Quoted 98 lines · Jens Axboe

Quoted 97 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
....

Can you try with this patch?

Quoted 100 lines · Jens Axboe

Quoted 99 lines · Dave Chinner

Quoted 98 lines · Jens Axboe

Quoted 97 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
....

.....

Quoted 1 line

Can you try with this patch?

Ok, context switches are back down in the realm of 400,000/s. It's better, but it's still a bit higher than that the 3.15 code. XFS is actually showing up in the context switch path profiles now...

However, performance is still excitingly variable and not much different to not having this patch applied. System time is unchanged (still around the 11m20s +/- 1m) and IOPS, wall time and files/s all show significant variance (at least +/-25%) from run to run. The worst case is not as slow as the unpatched kernel, but it's no better than the 3.15 worst case.

Profiles on a slow run look like:

(quoted diff) +0 -2

-  43.43%  [kernel]  [k] _raw_spin_unlock_irq
    - _raw_spin_unlock_irq
       - 64.23% blk_sq_make_request
            generic_make_request
           submit_bio                                                                                                                                                  ¿
       + 26.79% __schedule
...
-  15.00%  [kernel]  [k] _raw_spin_unlock_irqrestore
    - _raw_spin_unlock_irqrestore
       - 39.81% virtio_queue_rq
            __blk_mq_run_hw_queue
       + 24.13% complete
       + 17.74% prepare_to_wait_exclusive
       + 9.66% remove_wait_queue

Looks like the main contention problem is in blk_sq_make_request(). Also, there looks to be quite a bit of lock contention on the tag wait queues given that this patch made prepare_to_wait_exclusive() suddenly show up in the profiles.

FWIW, on a fast run there is very little time in blk_sq_make_request() lock contention, and overall spin lock/unlock overhead of these two functions is around 10% each....

So, yes, the patch reduces context switches but doesn't really reduce system time, improve performance noticably or address the run-to-run variability issue...

Quoted 137 lines · Dave Chinner

Quoted 100 lines · Jens Axboe

Quoted 99 lines · Dave Chinner

Quoted 98 lines · Jens Axboe

Quoted 97 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
....

.....

Quoted 1 line

Can you try with this patch?

Ok, context switches are back down in the realm of 400,000/s. It's better, but it's still a bit higher than that the 3.15 code. XFS is actually showing up in the context switch path profiles now...

However, performance is still excitingly variable and not much different to not having this patch applied. System time is unchanged (still around the 11m20s +/- 1m) and IOPS, wall time and files/s all show significant variance (at least +/-25%) from run to run. The worst case is not as slow as the unpatched kernel, but it's no better than the 3.15 worst case.

Profiles on a slow run look like:

(quoted diff) +0 -2

-  43.43%  [kernel]  [k] _raw_spin_unlock_irq
   - _raw_spin_unlock_irq
      - 64.23% blk_sq_make_request
           generic_make_request
          submit_bio                                                                                                                                                  ¿
      + 26.79% __schedule
...
-  15.00%  [kernel]  [k] _raw_spin_unlock_irqrestore
   - _raw_spin_unlock_irqrestore
      - 39.81% virtio_queue_rq
           __blk_mq_run_hw_queue
      + 24.13% complete
      + 17.74% prepare_to_wait_exclusive
      + 9.66% remove_wait_queue

Looks like the main contention problem is in blk_sq_make_request(). Also, there looks to be quite a bit of lock contention on the tag wait queues given that this patch made prepare_to_wait_exclusive() suddenly show up in the profiles.

Quoted 7 lines

FWIW, on a fast run there is very little time in blk_sq_make_request() lock contention, and overall spin lock/unlock overhead of these two functions is around 10% each....

So, yes, the patch reduces context switches but doesn't really reduce system time, improve performance noticably or address the run-to-run variability issue...

OK, so one more thing to try. With the same patch still applied, could you edit block/blk-mq-tag.h and change

BT_WAIT_QUEUES = 8,

to

BT_WAIT_QUEUES = 1,

and see if that smoothes things out?

On the road the next few days, so might take me a few days to get back to this. I was able to reproduce the horrible contention on the wait queue, but everything seemed to behave nicely with just the exclusive_wait/batch_wakeup for me. Looks like I might have to fire up kvm and set it you like you.

[cc linux-mm]

Quoted 149 lines · Jens Axboe

Quoted 137 lines · Dave Chinner

Quoted 100 lines · Jens Axboe

Quoted 99 lines · Dave Chinner

Quoted 98 lines · Jens Axboe

Quoted 97 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

(quoted diff) +0 -3

-  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:

(quoted diff) +0 -2

-  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
....

.....

Quoted 1 line

Can you try with this patch?

Ok, context switches are back down in the realm of 400,000/s. It's better, but it's still a bit higher than that the 3.15 code. XFS is actually showing up in the context switch path profiles now...

However, performance is still excitingly variable and not much different to not having this patch applied. System time is unchanged (still around the 11m20s +/- 1m) and IOPS, wall time and files/s all show significant variance (at least +/-25%) from run to run. The worst case is not as slow as the unpatched kernel, but it's no better than the 3.15 worst case.

Profiles on a slow run look like:

(quoted diff) +0 -2

-  43.43%  [kernel]  [k] _raw_spin_unlock_irq
    - _raw_spin_unlock_irq
       - 64.23% blk_sq_make_request
            generic_make_request
           submit_bio                                                                                                                                                  ¿
       + 26.79% __schedule
...
-  15.00%  [kernel]  [k] _raw_spin_unlock_irqrestore
    - _raw_spin_unlock_irqrestore
       - 39.81% virtio_queue_rq
            __blk_mq_run_hw_queue
       + 24.13% complete
       + 17.74% prepare_to_wait_exclusive
       + 9.66% remove_wait_queue

Looks like the main contention problem is in blk_sq_make_request(). Also, there looks to be quite a bit of lock contention on the tag wait queues given that this patch made prepare_to_wait_exclusive() suddenly show up in the profiles.

Quoted 7 lines

FWIW, on a fast run there is very little time in blk_sq_make_request() lock contention, and overall spin lock/unlock overhead of these two functions is around 10% each....

So, yes, the patch reduces context switches but doesn't really reduce system time, improve performance noticably or address the run-to-run variability issue...

OK, so one more thing to try. With the same patch still applied, could you edit block/blk-mq-tag.h and change

Quoted 7 lines

BT_WAIT_QUEUES = 8,

to

BT_WAIT_QUEUES = 1,

and see if that smoothes things out?

Ok, that smoothes things out to the point where I can see the trigger for the really nasty variable performance. The trigger is the machine running out of free memory. i.e. direct reclaim of clean pages for the data in the new files in the page cache drives the performance down by 25-50% and introduces significant variability.

So the variability doesn't seem to be solely related to the tag allocator; it is contributing some via wait queue contention, but it's definitely not the main contributor, nor the trigger...

MM-folk - the VM is running fake-numa=4 and has 16GB of RAM, and each step in the workload is generating 3.2GB of dirty pages (i.e. just on the dirty throttling threshold). It then does a concurrent asynchronous fsync of the 800,000 dirty files it just created, leaving 3.2GB of clean pages in the cache. The workload iterates this several times. Once the machine runs out of free memory (2.5 iterations in) performance drops by about 30% on average, but the drop varies between 20-60% randomly. I'm not concerned by a 30% drop when memory fills up - I'm concerned by the volatility of the drop that occurs. e.g:

FSUse% Count Size Files/sec App Overhead

      0       800000         4096      29938.0         13459475
      0      1600000         4096      28023.7         15662387
      0      2400000         4096      23704.6         16451761
      0      3200000         4096      16976.8         15029056
      0      4000000         4096      21858.3         15591604

Iteration 3 is where memory fills, and you can see that performance dropped by 25%. Iteration 4 drops another 25%, then iteration 5 regains it. If I keep running the workload for more iterations, this is pretty typical of the iteration-to-iteration variability, even though every iteration is identical in behaviour as are the initial conditions (i.e. memory full of clean, used-once pages).

This didn't happen in 3.15.0, but the behaviour may have been masked by the block layer tag allocator CPU overhead dominating the system behaviour.

Quoted 5 lines

On the road the next few days, so might take me a few days to get back to this. I was able to reproduce the horrible contention on the wait queue, but everything seemed to behave nicely with just the exclusive_wait/batch_wakeup for me. Looks like I might have to fire up kvm and set it you like you.

I'm guessing that the difference is that you weren't driving the machine into memory reclaim at the same time.

Quoted 13 lines · Dave Chinner

[cc linux-mm]

Quoted 10 lines · Jens Axboe

Quoted 9 lines · Dave Chinner

Quoted 8 lines · Jens Axboe

Quoted 7 lines · Dave Chinner

Quoted 6 lines · Jens Axboe

Quoted 5 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

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:

Quoted 12 lines

Quoted 12 lines

Quoted 12 lines

Quoted 1 line

Can you try with this patch?

Ok, context switches are back down in the realm of 400,000/s. It's better, but it's still a bit higher than that the 3.15 code. XFS is actually showing up in the context switch path profiles now...

However, performance is still excitingly variable and not much different to not having this patch applied. System time is unchanged (still around the 11m20s +/- 1m) and IOPS, wall time and files/s all show significant variance (at least +/-25%) from run to run. The worst case is not as slow as the unpatched kernel, but it's no better than the 3.15 worst case.

Quoted 59 lines

Quoted 16 lines

Quoted 5 lines

Looks like the main contention problem is in blk_sq_make_request(). Also, there looks to be quite a bit of lock contention on the tag wait queues given that this patch made prepare_to_wait_exclusive() suddenly show up in the profiles.

Quoted 7 lines

FWIW, on a fast run there is very little time in blk_sq_make_request() lock contention, and overall spin lock/unlock overhead of these two functions is around 10% each....

So, yes, the patch reduces context switches but doesn't really reduce system time, improve performance noticably or address the run-to-run variability issue...

OK, so one more thing to try. With the same patch still applied, could you edit block/blk-mq-tag.h and change

Quoted 7 lines

BT_WAIT_QUEUES = 8,

to

BT_WAIT_QUEUES = 1,

and see if that smoothes things out?

Ok, that smoothes things out to the point where I can see the trigger for the really nasty variable performance. The trigger is the machine running out of free memory. i.e. direct reclaim of clean pages for the data in the new files in the page cache drives the performance down by 25-50% and introduces significant variability.

So the variability doesn't seem to be solely related to the tag allocator; it is contributing some via wait queue contention, but it's definitely not the main contributor, nor the trigger...

MM-folk - the VM is running fake-numa=4 and has 16GB of RAM, and each step in the workload is generating 3.2GB of dirty pages (i.e. just on the dirty throttling threshold). It then does a concurrent asynchronous fsync of the 800,000 dirty files it just created, leaving 3.2GB of clean pages in the cache. The workload iterates this several times. Once the machine runs out of free memory (2.5 iterations in) performance drops by about 30% on average, but the drop varies between 20-60% randomly. I'm not concerned by a 30% drop when memory fills up - I'm concerned by the volatility of the drop that occurs. e.g:

FSUse%        Count         Size    Files/sec     App Overhead
     0       800000         4096      29938.0         13459475
     0      1600000         4096      28023.7         15662387
     0      2400000         4096      23704.6         16451761
     0      3200000         4096      16976.8         15029056
     0      4000000         4096      21858.3         15591604

Iteration 3 is where memory fills, and you can see that performance dropped by 25%. Iteration 4 drops another 25%, then iteration 5 regains it. If I keep running the workload for more iterations, this is pretty typical of the iteration-to-iteration variability, even though every iteration is identical in behaviour as are the initial conditions (i.e. memory full of clean, used-once pages).

Quoted 3 lines

This didn't happen in 3.15.0, but the behaviour may have been masked by the block layer tag allocator CPU overhead dominating the system behaviour.

OK, that's reassuring. I'll do some testing with the cyclic wait queues, but probably not until Thursday. Alexanders patches might potentially fix the variability as well, but if we can make-do without the multiple wait queues, I'd much rather just kill it.

Did you see any spinlock contention with BT_WAIT_QUEUES = 1?

Quoted 14 lines · Jens Axboe

Quoted 13 lines · Dave Chinner

[cc linux-mm]

Quoted 10 lines · Jens Axboe

Quoted 9 lines · Dave Chinner

Quoted 8 lines · Jens Axboe

Quoted 7 lines · Dave Chinner

Quoted 6 lines · Jens Axboe

Quoted 5 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

....

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

Quoted 24 lines

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:

....

Quoted 12 lines

Quoted 12 lines

Quoted 12 lines

Quoted 12 lines

Quoted 1 line

Can you try with this patch?

Ok, context switches are back down in the realm of 400,000/s. It's better, but it's still a bit higher than that the 3.15 code. XFS is actually showing up in the context switch path profiles now...

However, performance is still excitingly variable and not much different to not having this patch applied. System time is unchanged (still around the 11m20s +/- 1m) and IOPS, wall time and files/s all show significant variance (at least +/-25%) from run to run. The worst case is not as slow as the unpatched kernel, but it's no better than the 3.15 worst case.

....

Quoted 63 lines

Quoted 59 lines

Quoted 16 lines

Quoted 5 lines

Looks like the main contention problem is in blk_sq_make_request(). Also, there looks to be quite a bit of lock contention on the tag wait queues given that this patch made prepare_to_wait_exclusive() suddenly show up in the profiles.

Quoted 7 lines

FWIW, on a fast run there is very little time in blk_sq_make_request() lock contention, and overall spin lock/unlock overhead of these two functions is around 10% each....

So, yes, the patch reduces context switches but doesn't really reduce system time, improve performance noticably or address the run-to-run variability issue...

OK, so one more thing to try. With the same patch still applied, could you edit block/blk-mq-tag.h and change

Quoted 7 lines

BT_WAIT_QUEUES = 8,

to

BT_WAIT_QUEUES = 1,

and see if that smoothes things out?

Ok, that smoothes things out to the point where I can see the trigger for the really nasty variable performance. The trigger is the machine running out of free memory. i.e. direct reclaim of clean pages for the data in the new files in the page cache drives the performance down by 25-50% and introduces significant variability.

So the variability doesn't seem to be solely related to the tag allocator; it is contributing some via wait queue contention, but it's definitely not the main contributor, nor the trigger...

MM-folk - the VM is running fake-numa=4 and has 16GB of RAM, and each step in the workload is generating 3.2GB of dirty pages (i.e. just on the dirty throttling threshold). It then does a concurrent asynchronous fsync of the 800,000 dirty files it just created, leaving 3.2GB of clean pages in the cache. The workload iterates this several times. Once the machine runs out of free memory (2.5 iterations in) performance drops by about 30% on average, but the drop varies between 20-60% randomly. I'm not concerned by a 30% drop when memory fills up - I'm concerned by the volatility of the drop that occurs. e.g:

FSUse% Count Size Files/sec App Overhead

      0       800000         4096      29938.0         13459475
      0      1600000         4096      28023.7         15662387
      0      2400000         4096      23704.6         16451761
      0      3200000         4096      16976.8         15029056
      0      4000000         4096      21858.3         15591604

Iteration 3 is where memory fills, and you can see that performance dropped by 25%. Iteration 4 drops another 25%, then iteration 5 regains it. If I keep running the workload for more iterations, this is pretty typical of the iteration-to-iteration variability, even though every iteration is identical in behaviour as are the initial conditions (i.e. memory full of clean, used-once pages).

Quoted 3 lines

This didn't happen in 3.15.0, but the behaviour may have been masked by the block layer tag allocator CPU overhead dominating the system behaviour.

Quoted 6 lines

OK, that's reassuring. I'll do some testing with the cyclic wait queues, but probably not until Thursday. Alexanders patches might potentially fix the variability as well, but if we can make-do without the multiple wait queues, I'd much rather just kill it.

Did you see any spinlock contention with BT_WAIT_QUEUES = 1?

Yes. During the 15-20s of high IOPS dispatch rates the profile looks like this:

(quoted diff) +0 -2

-  36.00%  [kernel]  [k] _raw_spin_unlock_irq
    - _raw_spin_unlock_irq
       - 69.72% blk_sq_make_request
            generic_make_request
          + submit_bio
       + 24.81% __schedule
....
-  15.00%  [kernel]  [k] _raw_spin_unlock_irqrestore
    - _raw_spin_unlock_irqrestore
       - 32.87% prepare_to_wait_exclusive
            bt_get
            blk_mq_get_tag
            __blk_mq_alloc_request
            blk_mq_map_request
            blk_sq_make_request
            generic_make_request
          + submit_bio
       - 29.21% virtio_queue_rq
            __blk_mq_run_hw_queue
       + 11.69% complete
       + 8.21% finish_wait
         8.10% remove_wait_queue

But the IOPS rate has definitely increased with this config
- I just saw 90k, 100k and 110k IOPS in the last 3 iterations of the workload (the above profile is from the 100k IOPS period). However, the wall time was still only 3m58s, which again tends to implicate the write() portion of the benchmark for causing the slowdowns rather than the fsync() portion that is dispatching all the IO...

Quoted 29 lines · Dave Chinner

Quoted 14 lines · Jens Axboe

Quoted 13 lines · Dave Chinner

[cc linux-mm]

Quoted 10 lines · Jens Axboe

Quoted 9 lines · Dave Chinner

Quoted 8 lines · Jens Axboe

Quoted 7 lines · Dave Chinner

Quoted 6 lines · Jens Axboe

Quoted 5 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

....

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

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

Quoted 6 lines

But the IOPS rate has definitely increased with this config
- I just saw 90k, 100k and 110k IOPS in the last 3 iterations of the workload (the above profile is from the 100k IOPS period). However, the wall time was still only 3m58s, which again tends to implicate the write() portion of the benchmark for causing the slowdowns rather than the fsync() portion that is dispatching all the IO...

Some contention for this case is hard to avoid, and the above looks better than 3.15 does. So the big question is whether it's worth fixing the gaps with multiple waitqueues (and if that actually still buys us anything), or whether we should just disable them.

If I can get you to try one more thing, can you apply this patch and give that a whirl? Get rid of the other patches I sent first, this has everything.

From observation of all the performance metrics I graph in real

Quoted 30 lines · Jens Axboe

Quoted 29 lines · Dave Chinner

Quoted 14 lines · Jens Axboe

Quoted 13 lines · Dave Chinner

[cc linux-mm]

Quoted 10 lines · Jens Axboe

Quoted 9 lines · Dave Chinner

Quoted 8 lines · Jens Axboe

Quoted 7 lines · Dave Chinner

Quoted 6 lines · Jens Axboe

Quoted 5 lines · Dave Chinner

On Mon, Jun 16, 2014 at 08:33:23AM +1000, Dave Chinner wrote:
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:

....

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

Quoted 13 lines

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

....

Quoted 7 lines

Quoted 6 lines

But the IOPS rate has definitely increased with this config
- I just saw 90k, 100k and 110k IOPS in the last 3 iterations of the workload (the above profile is from the 100k IOPS period). However, the wall time was still only 3m58s, which again tends to implicate the write() portion of the benchmark for causing the slowdowns rather than the fsync() portion that is dispatching all the IO...

Quoted 8 lines

Some contention for this case is hard to avoid, and the above looks better than 3.15 does. So the big question is whether it's worth fixing the gaps with multiple waitqueues (and if that actually still buys us anything), or whether we should just disable them.

If I can get you to try one more thing, can you apply this patch and give that a whirl? Get rid of the other patches I sent first, this has everything.

Not much difference in the CPU usage profiles or base line performance. It runs at 3m10s from empty memory, and ~3m45s when memory starts full of clean pages. system time varies from 10m40s to 12m55s with no real correlation to overall runtime.

From observation of all the performance metrics I graph in real time, however, the pattern of the peaks and troughs from run to run and even iteration to iteration is much more regular than the previous patches. So from that perspective it is an improvement. Again, all the variability in the graphs show up when free memory runs out...

Talking about documentation: The kernel aio manpages (io_*.2) seems to not really be very useful, mostly because they don't explain how to set up the iocbs. Michael, any idea how to get started to improve this?

Quoted 4 lines

Talking about documentation: The kernel aio manpages (io_*.2) seems to not really be very useful, mostly because they don't explain how to set up the iocbs. Michael, any idea how to get started to improve this?

Well, it just needs someone knowledgeable to fill the gaps, and perhaps add an example program. I don't have that knowledge offhand myself...

From: Dave Chinner <[email protected]>

We've had plenty of requests for an asynchronous fsync over the past few years, and we've got the infrastructure there to do it. But nobody has wired it up to test it. The common request we get from userspace storage applications is to do a post-write pass over a set of files that were just written (i.e. bulk background fsync) for point-in-time checkpointing or flushing purposes.

So, just to see if I could brute force an effective implementation, wire up aio_fsync, add a workqueue and push all the fsync calls off to the workqueue. The workqueue will allow parallel dispatch, switch execution if a fsync blocks for any reason, etc. Brute force and very effective....

So, I hacked up fs_mark to enable fsync via the libaio io_fsync() interface to run some tests. The quick test is:

- write 10000 4k files into the cache
- run a post write open-fsync-close pass (sync mode 5)
- run 5 iterations
- run a single thread, then 4 threads.

First I ran it on a 500TB sparse filesystem on a SSD.

FSUse%        Count         Size    Files/sec     App Overhead
     0        10000         4096        599.1           153855
     0        20000         4096        739.2           151228
     0        30000         4096        672.2           152937
     0        40000         4096        719.9           150615
     0        50000         4096        708.4           154889

real    1m13.121s
user    0m0.825s
sys     0m11.024s

Runs at around 500 log forces a second and 1500 IOPS.

Using io_fsync():

FSUse%        Count         Size    Files/sec     App Overhead
     0        10000         4096       2700.5           130313
     0        20000         4096       3938.8           133602
     0        30000         4096       4608.7           107871
     0        40000         4096       4768.4            82965
     0        50000         4096       4615.0            89220

real    0m12.691s
user    0m0.460s
sys     0m7.389s

Runs at around 4,000 log forces a second and 4500 IOPS. Massive reduction in runtime through parallel dispatch of the fsync calls.

Run the same workload, 4 threads at a time. Normal fsync:

FSUse%        Count         Size    Files/sec     App Overhead
     0        40000         4096       2151.5           617010
     0        80000         4096       1953.0           613470
     0       120000         4096       1874.4           625027
     0       160000         4096       1907.4           624319
     0       200000         4096       1924.3           627567

real    1m42.243s
user    0m3.552s
sys     0m49.118s

Runs at ~2000 log forces/s and 3,500 IOPS.

Using io_fsync():

FSUse%        Count         Size    Files/sec     App Overhead
     0        40000         4096      11518.9           427666
     0        80000         4096      15668.8           401661
     0       120000         4096      15607.0           382279
     0       160000         4096      14935.0           399097
     0       200000         4096      15198.6           413965

real    0m14.192s
user    0m1.891s
sys     0m30.136s

Almost perfect scaling! ~15,000 log forces a second and ~20,000 IOPS.

Now run the tests on a HW RAID0 of spinning disk:

Threads files/s run time log force/s IOPS
1, fsync 800 1m 5.1s 800 1500
1, io_fsync 6000 8.4s 5000 5500
4, fsync 1800 1m47.1s 2200 3500
4, io_fsync 19000 10.3s 21000 26000

Pretty much the same results. Spinning disks don't scale much further. The SSD can go a bit higher, with 8 threads generating a consistent 24,000 files/s, but at that point we're starting to see non-linear system CPU usage (probably lock contention in the log).

But, regardless, there's a massive potential for speed gains for applications that need to do bulk fsync operations and don't need to care about the IO latency of individual fsync operations....

Signed-off-by Dave Chinner <[email protected]>

---

 fs/xfs/xfs_file.c  | 41 +++++++++++++++++++++++++++++++++++++++++
 fs/xfs/xfs_mount.h |  2 ++
 fs/xfs/xfs_super.c |  9 +++++++++
 3 files changed, 52 insertions(+)

fs/xfs/xfs_file.c +41 -0

index 077bcc8..9cdecee 100644
@@ -45,6 +45,7 @@
 #include <linux/pagevec.h>
 
 static const struct vm_operations_struct xfs_file_vm_ops;
+struct workqueue_struct *xfs_aio_fsync_wq;
 
 /*
  * Locking primitives for read and write IO paths to ensure we consistently use

@@ -228,6 +229,45 @@ xfs_file_fsync(
 	return error;
 }
 
+struct xfs_afsync_args {
+	struct work_struct	work;
+	struct kiocb		*iocb;
+	struct file		*file;
+	int			datasync;
+};
+
+STATIC void
+xfs_file_aio_fsync_work(
+	struct work_struct	*work)
+{
+	struct xfs_afsync_args	*args = container_of(work,
+						struct xfs_afsync_args, work);
+	int			error;
+
+	error = xfs_file_fsync(args->file, 0, -1LL, args->datasync);
+	aio_complete(args->iocb, error, 0);
+	kmem_free(args);
+}
+
+STATIC int
+xfs_file_aio_fsync(
+	struct kiocb		*iocb,
+	int			datasync)
+{
+	struct xfs_afsync_args	*args;
+
+	args = kmem_zalloc(sizeof(struct xfs_afsync_args), KM_SLEEP|KM_MAYFAIL);
+	if (!args)
+		return -ENOMEM;
+
+	INIT_WORK(&args->work, xfs_file_aio_fsync_work);
+	args->iocb = iocb;
+	args->file = iocb->ki_filp;
+	args->datasync = datasync;
+	queue_work(xfs_aio_fsync_wq, &args->work);
+	return -EIOCBQUEUED;
+}
+
 STATIC ssize_t
 xfs_file_aio_read(
 	struct kiocb		*iocb,

@@ -1475,6 +1515,7 @@ const struct file_operations xfs_file_operations = {
 	.open		= xfs_file_open,
 	.release	= xfs_file_release,
 	.fsync		= xfs_file_fsync,
+	.aio_fsync	= xfs_file_aio_fsync,
 	.fallocate	= xfs_file_fallocate,
 };
 

fs/xfs/xfs_mount.h +2 -0

index 7295a0b..dfcf37b 100644
@@ -390,6 +390,8 @@ extern int	xfs_dev_is_read_only(struct xfs_mount *, char *);
 
 extern void	xfs_set_low_space_thresholds(struct xfs_mount *);
 
+extern struct workqueue_struct *xfs_aio_fsync_wq;
+
 #endif	/* __KERNEL__ */
 
 #endif	/* __XFS_MOUNT_H__ */

fs/xfs/xfs_super.c +9 -0

index f2e5f8a..86d4923 100644
@@ -1718,12 +1718,21 @@ xfs_init_workqueues(void)
 	if (!xfs_alloc_wq)
 		return -ENOMEM;
 
+	xfs_aio_fsync_wq = alloc_workqueue("xfsfsync", 0, 0);
+	if (!xfs_aio_fsync_wq)
+		goto destroy_alloc_wq;
+
 	return 0;
+
+destroy_alloc_wq:
+	destroy_workqueue(xfs_alloc_wq);
+	return -ENOMEM;
 }
 
 STATIC void
 xfs_destroy_workqueues(void)
 {
+	destroy_workqueue(xfs_aio_fsync_wq);
 	destroy_workqueue(xfs_alloc_wq);
 }
 

Signature · 6 lines

2.0.0

_______________________________________________
xfs mailing list
[email protected]
http://oss.sgi.com/mailman/listinfo/xfs

Quoted 14 lines · Dave Chinner

From: Dave Chinner <[email protected]>

We've had plenty of requests for an asynchronous fsync over the past few years, and we've got the infrastructure there to do it. But nobody has wired it up to test it. The common request we get from userspace storage applications is to do a post-write pass over a set of files that were just written (i.e. bulk background fsync) for point-in-time checkpointing or flushing purposes.

So, just to see if I could brute force an effective implementation, wire up aio_fsync, add a workqueue and push all the fsync calls off to the workqueue. The workqueue will allow parallel dispatch, switch execution if a fsync blocks for any reason, etc. Brute force and very effective....

That looks great. This is something that could be quite beneficial to glusterfs, as a real world example. The replication mechanism does an xattr dance across servers and required addition of fsync's into the algorithm to ensure correctness in the case of failures. This had a notable impact on performance.

We thought a bit about hooking up aio_fsync(), but more along the lines of waiting for the log to force rather than forcing it explicitly, but didn't really go anywhere with it. I didn't consider we'd get such a benefit from simply dropping it into a workqueue. :)

I do like Christoph's idea... perhaps create a generic_file_aio_fsync() or some such?