io-uring.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
* Buffered IO async context overhead
@ 2020-02-14 19:50 Andres Freund
  2020-02-14 20:13 ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Andres Freund @ 2020-02-14 19:50 UTC (permalink / raw)
  To: io-uring, axboe

Hi,

For workloads where a lot of buffered IO is done, I see considerably
higher overhead when going through io_uring, then when just doing the IO
synchronously.

This example is on a samsung 970 pro nvme (i.e. decent, but not top
class). I've limited the amount of dirty buffers allowed to 2/4 GB to
keep the test times in check.   This is with a relatively recent kernel,
33b40134e5cfbbccad7f3040d1919889537a3df7 .

fio --name=t --time_based=1 --runtime=100 --ioengine=io_uring --rw=write --bs=8k --filesize=300G --iodepth=1

Jobs: 1 (f=1): [W(1)][100.0%][w=1049MiB/s][w=134k IOPS][eta 00m:00s]
t: (groupid=0, jobs=1): err= 0: pid=46625: Fri Feb 14 11:22:05 2020
  write: IOPS=73.4k, BW=573MiB/s (601MB/s)(55.0GiB/100001msec); 0 zone resets
    slat (nsec): min=571, max=607779, avg=2927.18, stdev=1213.47
    clat (nsec): min=40, max=1400.7k, avg=9947.92, stdev=2606.65
     lat (usec): min=4, max=1403, avg=12.94, stdev= 3.28
    clat percentiles (nsec):
     |  1.00th=[ 4960],  5.00th=[ 6368], 10.00th=[ 8032], 20.00th=[ 8640],
     | 30.00th=[ 9024], 40.00th=[ 9280], 50.00th=[ 9664], 60.00th=[10048],
     | 70.00th=[10560], 80.00th=[11072], 90.00th=[11968], 95.00th=[13120],
     | 99.00th=[21632], 99.50th=[23424], 99.90th=[26752], 99.95th=[28288],
     | 99.99th=[35584]
   bw (  KiB/s): min=192408, max=1031483, per=79.92%, avg=468998.16, stdev=108691.70, samples=199
   iops        : min=24051, max=128935, avg=58624.37, stdev=13586.54, samples=199
  lat (nsec)   : 50=0.01%, 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
  lat (nsec)   : 1000=0.01%
  lat (usec)   : 2=0.01%, 4=0.01%, 10=56.98%, 20=41.67%, 50=1.32%
  lat (usec)   : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
  lat (msec)   : 2=0.01%
  cpu          : usr=15.63%, sys=34.79%, ctx=7333387, majf=0, minf=41
  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,7335827,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=573MiB/s (601MB/s), 573MiB/s-573MiB/s (601MB/s-601MB/s), io=55.0GiB (60.1GB), run=100001-100001msec

Disk stats (read/write):
  nvme0n1: ios=0/49033, merge=0/12, ticks=0/1741787, in_queue=1717299, util=20.89%


During this most of the time there's a number of tasks with decent CPU usage
  46627 root      20   0       0      0      0 R  99.7   0.0   1:07.74 io_wqe_worker-0
  46625 root      20   0  756920   6708   1984 S  51.0   0.0   0:34.56 fio
  42818 root      20   0       0      0      0 I   3.3   0.0   0:03.23 kworker/u82:6-flush-259:0
  43338 root      20   0       0      0      0 I   1.3   0.0   0:02.06 kworker/u82:18-events_unbound


Comparing that to using sync:
fio --name=t --time_based=1 --runtime=100 --ioengine=sync --rw=write --bs=8k --filesize=300G --iodepth=1
Jobs: 1 (f=1): [W(1)][100.0%][w=1607MiB/s][w=206k IOPS][eta 00m:00s]
t: (groupid=0, jobs=1): err= 0: pid=46690: Fri Feb 14 11:24:17 2020
  write: IOPS=234k, BW=1831MiB/s (1920MB/s)(179GiB/100001msec); 0 zone resets
    clat (nsec): min=1612, max=6649.7k, avg=3913.39, stdev=3170.65
     lat (nsec): min=1653, max=6649.7k, avg=3955.30, stdev=3172.59
    clat percentiles (nsec):
     |  1.00th=[ 2512],  5.00th=[ 2544], 10.00th=[ 2576], 20.00th=[ 2640],
     | 30.00th=[ 2672], 40.00th=[ 2768], 50.00th=[ 3376], 60.00th=[ 3792],
     | 70.00th=[ 4192], 80.00th=[ 4832], 90.00th=[ 5792], 95.00th=[ 7008],
     | 99.00th=[11968], 99.50th=[15552], 99.90th=[22656], 99.95th=[26496],
     | 99.99th=[40192]
   bw (  MiB/s): min=  989, max= 2118, per=82.26%, avg=1506.28, stdev=169.56, samples=193
   iops        : min=126684, max=271118, avg=192803.37, stdev=21703.94, samples=193
  lat (usec)   : 2=0.01%, 4=66.33%, 10=32.14%, 20=1.34%, 50=0.19%
  lat (usec)   : 100=0.01%, 250=0.01%, 500=0.01%, 1000=0.01%
  lat (msec)   : 2=0.01%, 10=0.01%
  cpu          : usr=8.35%, sys=91.55%, ctx=6183, majf=0, minf=74
  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,23437892,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=1831MiB/s (1920MB/s), 1831MiB/s-1831MiB/s (1920MB/s-1920MB/s), io=179GiB (192GB), run=100001-100001msec

Disk stats (read/write):
  nvme0n1: ios=0/152371, merge=0/587772, ticks=0/5657236, in_queue=5580764, util=67.57%

Tasks:
  46690 root      20   0  756912   6524   1800 R 100.0   0.0   1:24.64 fio
   2913 root      20   0       0      0      0 S  32.2   0.0   0:09.57 kswapd1
  45683 root      20   0       0      0      0 I  13.2   0.0   0:08.57 kworker/u82:16-events_unbound
  42816 root      20   0       0      0      0 I  11.2   0.0   0:09.71 kworker/u82:1-flush-259:0
  36087 root      20   0       0      0      0 I   1.6   0.0   0:01.51 kworker/27:2-xfs-conv/nvme0n1

I.e. sync did about three times the throughput of io_uring.


It's possible to make io_uring perform better, by batching
submissions/completions:
fio --name=t --time_based=1 --runtime=100 --ioengine=io_uring --rw=write --bs=8k --filesize=300G --iodepth=64 --iodepth_batch_submit=32 --iodepth_batch_complete_min=16 --iodepth_low=16
t: (g=0): rw=write, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=io_uring, iodepth=64
fio-3.17
Starting 1 process
Jobs: 1 (f=1): [W(1)][100.0%][w=1382MiB/s][w=177k IOPS][eta 00m:00s]
t: (groupid=0, jobs=1): err= 0: pid=46849: Fri Feb 14 11:28:13 2020
  write: IOPS=194k, BW=1513MiB/s (1587MB/s)(148GiB/100001msec); 0 zone resets
    slat (usec): min=4, max=455, avg=48.09, stdev=18.20
    clat (usec): min=6, max=25435, avg=164.91, stdev=104.69
     lat (usec): min=66, max=25512, avg=213.03, stdev=101.19
    clat percentiles (usec):
     |  1.00th=[   60],  5.00th=[   68], 10.00th=[   78], 20.00th=[   94],
     | 30.00th=[  108], 40.00th=[  127], 50.00th=[  143], 60.00th=[  180],
     | 70.00th=[  210], 80.00th=[  227], 90.00th=[  265], 95.00th=[  302],
     | 99.00th=[  379], 99.50th=[  441], 99.90th=[  562], 99.95th=[  611],
     | 99.99th=[  816]
   bw (  MiB/s): min=  289, max= 1802, per=81.00%, avg=1225.72, stdev=173.92, samples=197
   iops        : min=37086, max=230692, avg=156891.42, stdev=22261.80, samples=197
  lat (usec)   : 10=0.01%, 50=0.09%, 100=25.74%, 250=60.50%, 500=13.46%
  lat (usec)   : 750=0.19%, 1000=0.01%
  lat (msec)   : 2=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
  cpu          : usr=31.80%, sys=26.04%, ctx=793383, majf=0, minf=1301
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=66.7%, >=64=33.3%
     submit    : 0=0.0%, 4=0.0%, 8=0.0%, 16=50.0%, 32=50.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=0.0%, 8=0.0%, 16=100.0%, 32=0.1%, 64=0.0%, >=64=0.0%
     issued rwts: total=0,19369087,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=64

Run status group 0 (all jobs):
  WRITE: bw=1513MiB/s (1587MB/s), 1513MiB/s-1513MiB/s (1587MB/s-1587MB/s), io=148GiB (159GB), run=100001-100001msec

Disk stats (read/write):
  nvme0n1: ios=0/127095, merge=0/15, ticks=0/4936953, in_queue=4873341, util=55.82%

but that's still worse than the plain sync one. And doesn't work well
for reads.


Now, it's clear that there's some overhead in backgrounding small IOs to
the async context, but this seems awfully high. There's still a slowdown
when using considerably larger pieces of IO (128k).

For the 128k, iodepth 1 case I get:
sync:
-   97.77%     0.04%  fio      fio                     [.] fio_syncio_queue
     97.73% fio_syncio_queue
      - __libc_write
         - __libc_write
            - 97.50% entry_SYSCALL_64
               - 97.31% do_syscall_64
                  - 97.25% ksys_write
                     - 97.10% vfs_write
                        - 96.91% new_sync_write
                           - 96.82% xfs_file_buffered_aio_write
                              - 96.13% iomap_file_buffered_write
                                 - iomap_apply
                                    - 95.52% iomap_write_actor
                                       + 37.66% iov_iter_copy_from_user_atomic
                                       + 26.83% iomap_write_begin
                                       + 26.64% iomap_write_end.isra.0
                                         2.26% iov_iter_fault_in_readable
                                         0.87% balance_dirty_pages_ratelimited
and --no-children shows:
+   36.57%  fio      [kernel.vmlinux]    [k] copy_user_enhanced_fast_string
+   14.31%  fio      [kernel.vmlinux]    [k] iomap_set_range_uptodate
+    3.85%  fio      [kernel.vmlinux]    [k] get_page_from_freelist
+    3.34%  fio      [kernel.vmlinux]    [k] queued_spin_lock_slowpath
+    2.94%  fio      [kernel.vmlinux]    [k] xas_load
+    2.66%  fio      [kernel.vmlinux]    [k] __add_to_page_cache_locked
+    2.51%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irqsave
+    2.28%  fio      [kernel.vmlinux]    [k] iov_iter_fault_in_readable
+    1.87%  fio      [kernel.vmlinux]    [k] __lru_cache_add
+    1.80%  fio      [kernel.vmlinux]    [k] __pagevec_lru_add_fn
+    1.59%  fio      [kernel.vmlinux]    [k] node_dirty_ok
+    1.30%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irq
+    1.30%  fio      [kernel.vmlinux]    [k] iomap_set_page_dirty
+    1.25%  fio      fio                 [.] get_io_u
+    1.18%  fio      [kernel.vmlinux]    [k] xas_start

io_uring (the io_wqe_worker-0):
-  100.00%    22.64%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
   - 77.36% io_wqe_worker
      - 77.18% io_worker_handle_work
         - 75.80% io_rw_async
            - io_wq_submit_work
               - 75.57% io_issue_sqe
                  - io_write
                     - 70.96% xfs_file_buffered_aio_write
                        - 70.37% iomap_file_buffered_write
                           - iomap_apply
                              - 70.08% iomap_write_actor
                                 + 30.05% iov_iter_copy_from_user_atomic
                                 - 18.38% iomap_write_begin
                                    - 17.64% grab_cache_page_write_begin
                                       + 16.73% pagecache_get_page
                                         0.51% wait_for_stable_page
                                 - 16.96% iomap_write_end.isra.0
                                      8.72% iomap_set_range_uptodate
                                    + 7.35% iomap_set_page_dirty
                                   3.45% iov_iter_fault_in_readable
                                   0.56% balance_dirty_pages_ratelimited
                     - 4.36% kiocb_done
                        - 3.56% io_cqring_ev_posted
                           + __wake_up_common_lock
                          0.61% io_cqring_add_event
           0.56% io_free_req
--no-children:
+   29.55%  io_wqe_worker-0  [kernel.vmlinux]  [k] copy_user_enhanced_fast_string
+   22.64%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
+    8.71%  io_wqe_worker-0  [kernel.vmlinux]  [k] iomap_set_range_uptodate
+    3.41%  io_wqe_worker-0  [kernel.vmlinux]  [k] iov_iter_fault_in_readable
+    2.50%  io_wqe_worker-0  [kernel.vmlinux]  [k] get_page_from_freelist
+    2.24%  io_wqe_worker-0  [kernel.vmlinux]  [k] xas_load
+    1.82%  io_wqe_worker-0  [kernel.vmlinux]  [k] queued_spin_lock_slowpath
+    1.80%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irqsave
+    1.72%  io_wqe_worker-0  [kernel.vmlinux]  [k] __add_to_page_cache_locked
+    1.58%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irq
+    1.29%  io_wqe_worker-0  [kernel.vmlinux]  [k] __lru_cache_add
+    1.27%  io_wqe_worker-0  [kernel.vmlinux]  [k] __pagevec_lru_add_fn
+    1.08%  io_wqe_worker-0  [kernel.vmlinux]  [k] xas_start

So it seems the biggest difference is the cpu time in io_wqe_worker
itself. Which in turn appears to mostly be:

       │       mov    %rbp,%rdi
       │     → callq  io_worker_handle_work
       │       mov    $0x3e7,%eax
       │     ↓ jmp    28c
       │     rep_nop():
       │     }
       │
       │     /* REP NOP (PAUSE) is a good thing to insert into busy-wait loops. */
       │     static __always_inline void rep_nop(void)
       │     {
       │     asm volatile("rep; nop" ::: "memory");
 74.50 │281:   pause
       │     io_worker_spin_for_work():
       │     while (++i < 1000) {
 11.15 │       sub    $0x1,%eax
       │     ↑ je     9b
       │     __read_once_size():
       │     __READ_ONCE_SIZE;
  9.53 │28c:   mov    0x8(%rbx),%rdx
       │     io_wqe_run_queue():
       │     if (!wq_list_empty(&wqe->work_list) &&
       │       test   %rdx,%rdx
  2.68 │     ↓ je     29f
       │     io_worker_spin_for_work():


With 8k it looks similar, but more extreme:
sync (fio itself):
+   29.89%  fio      [kernel.vmlinux]    [k] copy_user_enhanced_fast_string
+   14.10%  fio      [kernel.vmlinux]    [k] iomap_set_range_uptodate
+    2.80%  fio      [kernel.vmlinux]    [k] get_page_from_freelist
+    2.66%  fio      [kernel.vmlinux]    [k] queued_spin_lock_slowpath
+    2.46%  fio      [kernel.vmlinux]    [k] xas_load
+    1.97%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irqsave
+    1.94%  fio      [kernel.vmlinux]    [k] __add_to_page_cache_locked
+    1.79%  fio      [kernel.vmlinux]    [k] iomap_set_page_dirty
+    1.64%  fio      [kernel.vmlinux]    [k] iov_iter_fault_in_readable
+    1.61%  fio      fio                 [.] __fio_gettime
+    1.49%  fio      [kernel.vmlinux]    [k] __pagevec_lru_add_fn
+    1.39%  fio      [kernel.vmlinux]    [k] __lru_cache_add
     1.30%  fio      fio                 [.] get_io_u
+    1.11%  fio      [kernel.vmlinux]    [k] up_write
+    1.10%  fio      [kernel.vmlinux]    [k] node_dirty_ok
+    1.09%  fio      [kernel.vmlinux]    [k] down_write

io_uring (io_wqe_worker-0 again):
+   54.13%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
+   11.01%  io_wqe_worker-0  [kernel.vmlinux]  [k] copy_user_enhanced_fast_string
+    2.70%  io_wqe_worker-0  [kernel.vmlinux]  [k] iomap_set_range_uptodate
+    2.62%  io_wqe_worker-0  [kernel.vmlinux]  [k] iov_iter_fault_in_readable
+    1.91%  io_wqe_worker-0  [kernel.vmlinux]  [k] __slab_free
+    1.85%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irqsave
+    1.66%  io_wqe_worker-0  [kernel.vmlinux]  [k] try_to_wake_up
+    1.62%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_cqring_fill_event
+    1.55%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_rw_async
+    1.43%  io_wqe_worker-0  [kernel.vmlinux]  [k] __wake_up_common
+    1.37%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irq
+    1.20%  io_wqe_worker-0  [kernel.vmlinux]  [k] rw_verify_area

which I think is pretty clear evidence we're hitting fairly significant
contention on the queue lock.


I am hitting this in postgres originally, not fio, but I thought it's
easier to reproduce this way.  There's obviously benefit to doing things
in the background - but it requires odd logic around deciding when to
use io_uring, and when not.

To be clear, none of this happens with DIO, but I don't forsee switching
to DIO for all IO by default ever (too high demands on accurate
configuration).

Greetings,

Andres Freund

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-14 19:50 Buffered IO async context overhead Andres Freund
@ 2020-02-14 20:13 ` Jens Axboe
  2020-02-14 20:31   ` Andres Freund
  0 siblings, 1 reply; 10+ messages in thread
From: Jens Axboe @ 2020-02-14 20:13 UTC (permalink / raw)
  To: Andres Freund, io-uring

On 2/14/20 12:50 PM, Andres Freund wrote:
> Hi,
> 
> For workloads where a lot of buffered IO is done, I see considerably
> higher overhead when going through io_uring, then when just doing the IO
> synchronously.
> 
> This example is on a samsung 970 pro nvme (i.e. decent, but not top
> class). I've limited the amount of dirty buffers allowed to 2/4 GB to
> keep the test times in check.   This is with a relatively recent kernel,
> 33b40134e5cfbbccad7f3040d1919889537a3df7 .
> 
> fio --name=t --time_based=1 --runtime=100 --ioengine=io_uring --rw=write --bs=8k --filesize=300G --iodepth=1
> 
> Jobs: 1 (f=1): [W(1)][100.0%][w=1049MiB/s][w=134k IOPS][eta 00m:00s]
> t: (groupid=0, jobs=1): err= 0: pid=46625: Fri Feb 14 11:22:05 2020
>   write: IOPS=73.4k, BW=573MiB/s (601MB/s)(55.0GiB/100001msec); 0 zone resets
>     slat (nsec): min=571, max=607779, avg=2927.18, stdev=1213.47
>     clat (nsec): min=40, max=1400.7k, avg=9947.92, stdev=2606.65
>      lat (usec): min=4, max=1403, avg=12.94, stdev= 3.28
>     clat percentiles (nsec):
>      |  1.00th=[ 4960],  5.00th=[ 6368], 10.00th=[ 8032], 20.00th=[ 8640],
>      | 30.00th=[ 9024], 40.00th=[ 9280], 50.00th=[ 9664], 60.00th=[10048],
>      | 70.00th=[10560], 80.00th=[11072], 90.00th=[11968], 95.00th=[13120],
>      | 99.00th=[21632], 99.50th=[23424], 99.90th=[26752], 99.95th=[28288],
>      | 99.99th=[35584]
>    bw (  KiB/s): min=192408, max=1031483, per=79.92%, avg=468998.16, stdev=108691.70, samples=199
>    iops        : min=24051, max=128935, avg=58624.37, stdev=13586.54, samples=199
>   lat (nsec)   : 50=0.01%, 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
>   lat (nsec)   : 1000=0.01%
>   lat (usec)   : 2=0.01%, 4=0.01%, 10=56.98%, 20=41.67%, 50=1.32%
>   lat (usec)   : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%
>   lat (msec)   : 2=0.01%
>   cpu          : usr=15.63%, sys=34.79%, ctx=7333387, majf=0, minf=41
>   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,7335827,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=573MiB/s (601MB/s), 573MiB/s-573MiB/s (601MB/s-601MB/s), io=55.0GiB (60.1GB), run=100001-100001msec
> 
> Disk stats (read/write):
>   nvme0n1: ios=0/49033, merge=0/12, ticks=0/1741787, in_queue=1717299, util=20.89%
> 
> 
> During this most of the time there's a number of tasks with decent CPU usage
>   46627 root      20   0       0      0      0 R  99.7   0.0   1:07.74 io_wqe_worker-0
>   46625 root      20   0  756920   6708   1984 S  51.0   0.0   0:34.56 fio
>   42818 root      20   0       0      0      0 I   3.3   0.0   0:03.23 kworker/u82:6-flush-259:0
>   43338 root      20   0       0      0      0 I   1.3   0.0   0:02.06 kworker/u82:18-events_unbound
> 
> 
> Comparing that to using sync:
> fio --name=t --time_based=1 --runtime=100 --ioengine=sync --rw=write --bs=8k --filesize=300G --iodepth=1
> Jobs: 1 (f=1): [W(1)][100.0%][w=1607MiB/s][w=206k IOPS][eta 00m:00s]
> t: (groupid=0, jobs=1): err= 0: pid=46690: Fri Feb 14 11:24:17 2020
>   write: IOPS=234k, BW=1831MiB/s (1920MB/s)(179GiB/100001msec); 0 zone resets
>     clat (nsec): min=1612, max=6649.7k, avg=3913.39, stdev=3170.65
>      lat (nsec): min=1653, max=6649.7k, avg=3955.30, stdev=3172.59
>     clat percentiles (nsec):
>      |  1.00th=[ 2512],  5.00th=[ 2544], 10.00th=[ 2576], 20.00th=[ 2640],
>      | 30.00th=[ 2672], 40.00th=[ 2768], 50.00th=[ 3376], 60.00th=[ 3792],
>      | 70.00th=[ 4192], 80.00th=[ 4832], 90.00th=[ 5792], 95.00th=[ 7008],
>      | 99.00th=[11968], 99.50th=[15552], 99.90th=[22656], 99.95th=[26496],
>      | 99.99th=[40192]
>    bw (  MiB/s): min=  989, max= 2118, per=82.26%, avg=1506.28, stdev=169.56, samples=193
>    iops        : min=126684, max=271118, avg=192803.37, stdev=21703.94, samples=193
>   lat (usec)   : 2=0.01%, 4=66.33%, 10=32.14%, 20=1.34%, 50=0.19%
>   lat (usec)   : 100=0.01%, 250=0.01%, 500=0.01%, 1000=0.01%
>   lat (msec)   : 2=0.01%, 10=0.01%
>   cpu          : usr=8.35%, sys=91.55%, ctx=6183, majf=0, minf=74
>   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,23437892,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=1831MiB/s (1920MB/s), 1831MiB/s-1831MiB/s (1920MB/s-1920MB/s), io=179GiB (192GB), run=100001-100001msec
> 
> Disk stats (read/write):
>   nvme0n1: ios=0/152371, merge=0/587772, ticks=0/5657236, in_queue=5580764, util=67.57%
> 
> Tasks:
>   46690 root      20   0  756912   6524   1800 R 100.0   0.0   1:24.64 fio
>    2913 root      20   0       0      0      0 S  32.2   0.0   0:09.57 kswapd1
>   45683 root      20   0       0      0      0 I  13.2   0.0   0:08.57 kworker/u82:16-events_unbound
>   42816 root      20   0       0      0      0 I  11.2   0.0   0:09.71 kworker/u82:1-flush-259:0
>   36087 root      20   0       0      0      0 I   1.6   0.0   0:01.51 kworker/27:2-xfs-conv/nvme0n1
> 
> I.e. sync did about three times the throughput of io_uring.
> 
> 
> It's possible to make io_uring perform better, by batching
> submissions/completions:
> fio --name=t --time_based=1 --runtime=100 --ioengine=io_uring --rw=write --bs=8k --filesize=300G --iodepth=64 --iodepth_batch_submit=32 --iodepth_batch_complete_min=16 --iodepth_low=16
> t: (g=0): rw=write, bs=(R) 8192B-8192B, (W) 8192B-8192B, (T) 8192B-8192B, ioengine=io_uring, iodepth=64
> fio-3.17
> Starting 1 process
> Jobs: 1 (f=1): [W(1)][100.0%][w=1382MiB/s][w=177k IOPS][eta 00m:00s]
> t: (groupid=0, jobs=1): err= 0: pid=46849: Fri Feb 14 11:28:13 2020
>   write: IOPS=194k, BW=1513MiB/s (1587MB/s)(148GiB/100001msec); 0 zone resets
>     slat (usec): min=4, max=455, avg=48.09, stdev=18.20
>     clat (usec): min=6, max=25435, avg=164.91, stdev=104.69
>      lat (usec): min=66, max=25512, avg=213.03, stdev=101.19
>     clat percentiles (usec):
>      |  1.00th=[   60],  5.00th=[   68], 10.00th=[   78], 20.00th=[   94],
>      | 30.00th=[  108], 40.00th=[  127], 50.00th=[  143], 60.00th=[  180],
>      | 70.00th=[  210], 80.00th=[  227], 90.00th=[  265], 95.00th=[  302],
>      | 99.00th=[  379], 99.50th=[  441], 99.90th=[  562], 99.95th=[  611],
>      | 99.99th=[  816]
>    bw (  MiB/s): min=  289, max= 1802, per=81.00%, avg=1225.72, stdev=173.92, samples=197
>    iops        : min=37086, max=230692, avg=156891.42, stdev=22261.80, samples=197
>   lat (usec)   : 10=0.01%, 50=0.09%, 100=25.74%, 250=60.50%, 500=13.46%
>   lat (usec)   : 750=0.19%, 1000=0.01%
>   lat (msec)   : 2=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
>   cpu          : usr=31.80%, sys=26.04%, ctx=793383, majf=0, minf=1301
>   IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=66.7%, >=64=33.3%
>      submit    : 0=0.0%, 4=0.0%, 8=0.0%, 16=50.0%, 32=50.0%, 64=0.0%, >=64=0.0%
>      complete  : 0=0.0%, 4=0.0%, 8=0.0%, 16=100.0%, 32=0.1%, 64=0.0%, >=64=0.0%
>      issued rwts: total=0,19369087,0,0 short=0,0,0,0 dropped=0,0,0,0
>      latency   : target=0, window=0, percentile=100.00%, depth=64
> 
> Run status group 0 (all jobs):
>   WRITE: bw=1513MiB/s (1587MB/s), 1513MiB/s-1513MiB/s (1587MB/s-1587MB/s), io=148GiB (159GB), run=100001-100001msec
> 
> Disk stats (read/write):
>   nvme0n1: ios=0/127095, merge=0/15, ticks=0/4936953, in_queue=4873341, util=55.82%
> 
> but that's still worse than the plain sync one. And doesn't work well
> for reads.
> 
> 
> Now, it's clear that there's some overhead in backgrounding small IOs to
> the async context, but this seems awfully high. There's still a slowdown
> when using considerably larger pieces of IO (128k).
> 
> For the 128k, iodepth 1 case I get:
> sync:
> -   97.77%     0.04%  fio      fio                     [.] fio_syncio_queue
>      97.73% fio_syncio_queue
>       - __libc_write
>          - __libc_write
>             - 97.50% entry_SYSCALL_64
>                - 97.31% do_syscall_64
>                   - 97.25% ksys_write
>                      - 97.10% vfs_write
>                         - 96.91% new_sync_write
>                            - 96.82% xfs_file_buffered_aio_write
>                               - 96.13% iomap_file_buffered_write
>                                  - iomap_apply
>                                     - 95.52% iomap_write_actor
>                                        + 37.66% iov_iter_copy_from_user_atomic
>                                        + 26.83% iomap_write_begin
>                                        + 26.64% iomap_write_end.isra.0
>                                          2.26% iov_iter_fault_in_readable
>                                          0.87% balance_dirty_pages_ratelimited
> and --no-children shows:
> +   36.57%  fio      [kernel.vmlinux]    [k] copy_user_enhanced_fast_string
> +   14.31%  fio      [kernel.vmlinux]    [k] iomap_set_range_uptodate
> +    3.85%  fio      [kernel.vmlinux]    [k] get_page_from_freelist
> +    3.34%  fio      [kernel.vmlinux]    [k] queued_spin_lock_slowpath
> +    2.94%  fio      [kernel.vmlinux]    [k] xas_load
> +    2.66%  fio      [kernel.vmlinux]    [k] __add_to_page_cache_locked
> +    2.51%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irqsave
> +    2.28%  fio      [kernel.vmlinux]    [k] iov_iter_fault_in_readable
> +    1.87%  fio      [kernel.vmlinux]    [k] __lru_cache_add
> +    1.80%  fio      [kernel.vmlinux]    [k] __pagevec_lru_add_fn
> +    1.59%  fio      [kernel.vmlinux]    [k] node_dirty_ok
> +    1.30%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irq
> +    1.30%  fio      [kernel.vmlinux]    [k] iomap_set_page_dirty
> +    1.25%  fio      fio                 [.] get_io_u
> +    1.18%  fio      [kernel.vmlinux]    [k] xas_start
> 
> io_uring (the io_wqe_worker-0):
> -  100.00%    22.64%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
>    - 77.36% io_wqe_worker
>       - 77.18% io_worker_handle_work
>          - 75.80% io_rw_async
>             - io_wq_submit_work
>                - 75.57% io_issue_sqe
>                   - io_write
>                      - 70.96% xfs_file_buffered_aio_write
>                         - 70.37% iomap_file_buffered_write
>                            - iomap_apply
>                               - 70.08% iomap_write_actor
>                                  + 30.05% iov_iter_copy_from_user_atomic
>                                  - 18.38% iomap_write_begin
>                                     - 17.64% grab_cache_page_write_begin
>                                        + 16.73% pagecache_get_page
>                                          0.51% wait_for_stable_page
>                                  - 16.96% iomap_write_end.isra.0
>                                       8.72% iomap_set_range_uptodate
>                                     + 7.35% iomap_set_page_dirty
>                                    3.45% iov_iter_fault_in_readable
>                                    0.56% balance_dirty_pages_ratelimited
>                      - 4.36% kiocb_done
>                         - 3.56% io_cqring_ev_posted
>                            + __wake_up_common_lock
>                           0.61% io_cqring_add_event
>            0.56% io_free_req
> --no-children:
> +   29.55%  io_wqe_worker-0  [kernel.vmlinux]  [k] copy_user_enhanced_fast_string
> +   22.64%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
> +    8.71%  io_wqe_worker-0  [kernel.vmlinux]  [k] iomap_set_range_uptodate
> +    3.41%  io_wqe_worker-0  [kernel.vmlinux]  [k] iov_iter_fault_in_readable
> +    2.50%  io_wqe_worker-0  [kernel.vmlinux]  [k] get_page_from_freelist
> +    2.24%  io_wqe_worker-0  [kernel.vmlinux]  [k] xas_load
> +    1.82%  io_wqe_worker-0  [kernel.vmlinux]  [k] queued_spin_lock_slowpath
> +    1.80%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irqsave
> +    1.72%  io_wqe_worker-0  [kernel.vmlinux]  [k] __add_to_page_cache_locked
> +    1.58%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irq
> +    1.29%  io_wqe_worker-0  [kernel.vmlinux]  [k] __lru_cache_add
> +    1.27%  io_wqe_worker-0  [kernel.vmlinux]  [k] __pagevec_lru_add_fn
> +    1.08%  io_wqe_worker-0  [kernel.vmlinux]  [k] xas_start
> 
> So it seems the biggest difference is the cpu time in io_wqe_worker
> itself. Which in turn appears to mostly be:
> 
>        │       mov    %rbp,%rdi
>        │     → callq  io_worker_handle_work
>        │       mov    $0x3e7,%eax
>        │     ↓ jmp    28c
>        │     rep_nop():
>        │     }
>        │
>        │     /* REP NOP (PAUSE) is a good thing to insert into busy-wait loops. */
>        │     static __always_inline void rep_nop(void)
>        │     {
>        │     asm volatile("rep; nop" ::: "memory");
>  74.50 │281:   pause
>        │     io_worker_spin_for_work():
>        │     while (++i < 1000) {
>  11.15 │       sub    $0x1,%eax
>        │     ↑ je     9b
>        │     __read_once_size():
>        │     __READ_ONCE_SIZE;
>   9.53 │28c:   mov    0x8(%rbx),%rdx
>        │     io_wqe_run_queue():
>        │     if (!wq_list_empty(&wqe->work_list) &&
>        │       test   %rdx,%rdx
>   2.68 │     ↓ je     29f
>        │     io_worker_spin_for_work():
> 
> 
> With 8k it looks similar, but more extreme:
> sync (fio itself):
> +   29.89%  fio      [kernel.vmlinux]    [k] copy_user_enhanced_fast_string
> +   14.10%  fio      [kernel.vmlinux]    [k] iomap_set_range_uptodate
> +    2.80%  fio      [kernel.vmlinux]    [k] get_page_from_freelist
> +    2.66%  fio      [kernel.vmlinux]    [k] queued_spin_lock_slowpath
> +    2.46%  fio      [kernel.vmlinux]    [k] xas_load
> +    1.97%  fio      [kernel.vmlinux]    [k] _raw_spin_lock_irqsave
> +    1.94%  fio      [kernel.vmlinux]    [k] __add_to_page_cache_locked
> +    1.79%  fio      [kernel.vmlinux]    [k] iomap_set_page_dirty
> +    1.64%  fio      [kernel.vmlinux]    [k] iov_iter_fault_in_readable
> +    1.61%  fio      fio                 [.] __fio_gettime
> +    1.49%  fio      [kernel.vmlinux]    [k] __pagevec_lru_add_fn
> +    1.39%  fio      [kernel.vmlinux]    [k] __lru_cache_add
>      1.30%  fio      fio                 [.] get_io_u
> +    1.11%  fio      [kernel.vmlinux]    [k] up_write
> +    1.10%  fio      [kernel.vmlinux]    [k] node_dirty_ok
> +    1.09%  fio      [kernel.vmlinux]    [k] down_write
> 
> io_uring (io_wqe_worker-0 again):
> +   54.13%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_wqe_worker
> +   11.01%  io_wqe_worker-0  [kernel.vmlinux]  [k] copy_user_enhanced_fast_string
> +    2.70%  io_wqe_worker-0  [kernel.vmlinux]  [k] iomap_set_range_uptodate
> +    2.62%  io_wqe_worker-0  [kernel.vmlinux]  [k] iov_iter_fault_in_readable
> +    1.91%  io_wqe_worker-0  [kernel.vmlinux]  [k] __slab_free
> +    1.85%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irqsave
> +    1.66%  io_wqe_worker-0  [kernel.vmlinux]  [k] try_to_wake_up
> +    1.62%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_cqring_fill_event
> +    1.55%  io_wqe_worker-0  [kernel.vmlinux]  [k] io_rw_async
> +    1.43%  io_wqe_worker-0  [kernel.vmlinux]  [k] __wake_up_common
> +    1.37%  io_wqe_worker-0  [kernel.vmlinux]  [k] _raw_spin_lock_irq
> +    1.20%  io_wqe_worker-0  [kernel.vmlinux]  [k] rw_verify_area
> 
> which I think is pretty clear evidence we're hitting fairly significant
> contention on the queue lock.
> 
> 
> I am hitting this in postgres originally, not fio, but I thought it's
> easier to reproduce this way.  There's obviously benefit to doing things
> in the background - but it requires odd logic around deciding when to
> use io_uring, and when not.
> 
> To be clear, none of this happens with DIO, but I don't forsee switching
> to DIO for all IO by default ever (too high demands on accurate
> configuration).

Can you try with this added?


diff --git a/fs/io_uring.c b/fs/io_uring.c
index 76cbf474c184..207daf83f209 100644
--- a/fs/io_uring.c
+++ b/fs/io_uring.c
@@ -620,6 +620,7 @@ static const struct io_op_def io_op_defs[] = {
 		.async_ctx		= 1,
 		.needs_mm		= 1,
 		.needs_file		= 1,
+		.hash_reg_file		= 1,
 		.unbound_nonreg_file	= 1,
 	},
 	[IORING_OP_WRITEV] = {
@@ -634,6 +635,7 @@ static const struct io_op_def io_op_defs[] = {
 	},
 	[IORING_OP_READ_FIXED] = {
 		.needs_file		= 1,
+		.hash_reg_file		= 1,
 		.unbound_nonreg_file	= 1,
 	},
 	[IORING_OP_WRITE_FIXED] = {
@@ -711,11 +713,13 @@ static const struct io_op_def io_op_defs[] = {
 	[IORING_OP_READ] = {
 		.needs_mm		= 1,
 		.needs_file		= 1,
+		.hash_reg_file		= 1,
 		.unbound_nonreg_file	= 1,
 	},
 	[IORING_OP_WRITE] = {
 		.needs_mm		= 1,
 		.needs_file		= 1,
+		.hash_reg_file		= 1,
 		.unbound_nonreg_file	= 1,
 	},
 	[IORING_OP_FADVISE] = {
@@ -955,7 +959,7 @@ static inline bool io_prep_async_work(struct io_kiocb *req,
 	bool do_hashed = false;
 
 	if (req->flags & REQ_F_ISREG) {
-		if (def->hash_reg_file)
+		if (!(req->kiocb->ki_flags & IOCB_DIRECT) && def->hash_reg_file)
 			do_hashed = true;
 	} else {
 		if (def->unbound_nonreg_file)

-- 
Jens Axboe


^ permalink raw reply related	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-14 20:13 ` Jens Axboe
@ 2020-02-14 20:31   ` Andres Freund
  2020-02-14 20:49     ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Andres Freund @ 2020-02-14 20:31 UTC (permalink / raw)
  To: Jens Axboe; +Cc: io-uring

Hi,

On 2020-02-14 13:13:35 -0700, Jens Axboe wrote:
> On 2/14/20 12:50 PM, Andres Freund wrote:
> > which I think is pretty clear evidence we're hitting fairly significant
> > contention on the queue lock.
> > 
> > 
> > I am hitting this in postgres originally, not fio, but I thought it's
> > easier to reproduce this way.  There's obviously benefit to doing things
> > in the background - but it requires odd logic around deciding when to
> > use io_uring, and when not.
> > 
> > To be clear, none of this happens with DIO, but I don't forsee switching
> > to DIO for all IO by default ever (too high demands on accurate
> > configuration).
> 
> Can you try with this added?
> 
> 
> diff --git a/fs/io_uring.c b/fs/io_uring.c
> index 76cbf474c184..207daf83f209 100644
> --- a/fs/io_uring.c
> +++ b/fs/io_uring.c
> @@ -620,6 +620,7 @@ static const struct io_op_def io_op_defs[] = {
>  		.async_ctx		= 1,
>  		.needs_mm		= 1,
>  		.needs_file		= 1,
> +		.hash_reg_file		= 1,
>  		.unbound_nonreg_file	= 1,
>  	},
>  	[IORING_OP_WRITEV] = {
> @@ -634,6 +635,7 @@ static const struct io_op_def io_op_defs[] = {
>  	},
>  	[IORING_OP_READ_FIXED] = {
>  		.needs_file		= 1,
> +		.hash_reg_file		= 1,
>  		.unbound_nonreg_file	= 1,
>  	},
>  	[IORING_OP_WRITE_FIXED] = {
> @@ -711,11 +713,13 @@ static const struct io_op_def io_op_defs[] = {
>  	[IORING_OP_READ] = {
>  		.needs_mm		= 1,
>  		.needs_file		= 1,
> +		.hash_reg_file		= 1,
>  		.unbound_nonreg_file	= 1,
>  	},
>  	[IORING_OP_WRITE] = {
>  		.needs_mm		= 1,
>  		.needs_file		= 1,
> +		.hash_reg_file		= 1,
>  		.unbound_nonreg_file	= 1,
>  	},
>  	[IORING_OP_FADVISE] = {
> @@ -955,7 +959,7 @@ static inline bool io_prep_async_work(struct io_kiocb *req,
>  	bool do_hashed = false;
>  
>  	if (req->flags & REQ_F_ISREG) {
> -		if (def->hash_reg_file)
> +		if (!(req->kiocb->ki_flags & IOCB_DIRECT) && def->hash_reg_file)
>  			do_hashed = true;
>  	} else {
>  		if (def->unbound_nonreg_file)

I can (will do Sunday, on the road till then). But I'm a bit doubtful
it'll help. This is using WRITEV after all, and I only see a single
worker?

Greetings,

Andres Freund

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-14 20:31   ` Andres Freund
@ 2020-02-14 20:49     ` Jens Axboe
  2020-02-24  9:35       ` Andres Freund
  0 siblings, 1 reply; 10+ messages in thread
From: Jens Axboe @ 2020-02-14 20:49 UTC (permalink / raw)
  To: Andres Freund; +Cc: io-uring

On 2/14/20 1:31 PM, Andres Freund wrote:
> Hi,
> 
> On 2020-02-14 13:13:35 -0700, Jens Axboe wrote:
>> On 2/14/20 12:50 PM, Andres Freund wrote:
>>> which I think is pretty clear evidence we're hitting fairly significant
>>> contention on the queue lock.
>>>
>>>
>>> I am hitting this in postgres originally, not fio, but I thought it's
>>> easier to reproduce this way.  There's obviously benefit to doing things
>>> in the background - but it requires odd logic around deciding when to
>>> use io_uring, and when not.
>>>
>>> To be clear, none of this happens with DIO, but I don't forsee switching
>>> to DIO for all IO by default ever (too high demands on accurate
>>> configuration).
>>
>> Can you try with this added?
>>
>>
>> diff --git a/fs/io_uring.c b/fs/io_uring.c
>> index 76cbf474c184..207daf83f209 100644
>> --- a/fs/io_uring.c
>> +++ b/fs/io_uring.c
>> @@ -620,6 +620,7 @@ static const struct io_op_def io_op_defs[] = {
>>  		.async_ctx		= 1,
>>  		.needs_mm		= 1,
>>  		.needs_file		= 1,
>> +		.hash_reg_file		= 1,
>>  		.unbound_nonreg_file	= 1,
>>  	},
>>  	[IORING_OP_WRITEV] = {
>> @@ -634,6 +635,7 @@ static const struct io_op_def io_op_defs[] = {
>>  	},
>>  	[IORING_OP_READ_FIXED] = {
>>  		.needs_file		= 1,
>> +		.hash_reg_file		= 1,
>>  		.unbound_nonreg_file	= 1,
>>  	},
>>  	[IORING_OP_WRITE_FIXED] = {
>> @@ -711,11 +713,13 @@ static const struct io_op_def io_op_defs[] = {
>>  	[IORING_OP_READ] = {
>>  		.needs_mm		= 1,
>>  		.needs_file		= 1,
>> +		.hash_reg_file		= 1,
>>  		.unbound_nonreg_file	= 1,
>>  	},
>>  	[IORING_OP_WRITE] = {
>>  		.needs_mm		= 1,
>>  		.needs_file		= 1,
>> +		.hash_reg_file		= 1,
>>  		.unbound_nonreg_file	= 1,
>>  	},
>>  	[IORING_OP_FADVISE] = {
>> @@ -955,7 +959,7 @@ static inline bool io_prep_async_work(struct io_kiocb *req,
>>  	bool do_hashed = false;
>>  
>>  	if (req->flags & REQ_F_ISREG) {
>> -		if (def->hash_reg_file)
>> +		if (!(req->kiocb->ki_flags & IOCB_DIRECT) && def->hash_reg_file)
>>  			do_hashed = true;
>>  	} else {
>>  		if (def->unbound_nonreg_file)
> 
> I can (will do Sunday, on the road till then). But I'm a bit doubtful
> it'll help. This is using WRITEV after all, and I only see a single
> worker?

Because I'm working on other items, I didn't read carefully enough. Yes
this won't change the situation for writes. I'll take a look at this when
I get time, maybe there's something we can do to improve the situation.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-14 20:49     ` Jens Axboe
@ 2020-02-24  9:35       ` Andres Freund
  2020-02-24 15:22         ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Andres Freund @ 2020-02-24  9:35 UTC (permalink / raw)
  To: Jens Axboe; +Cc: io-uring

Hi,

On 2020-02-14 13:49:31 -0700, Jens Axboe wrote:
> [description of buffered write workloads being slower via io_uring
> than plain writes]
> Because I'm working on other items, I didn't read carefully enough. Yes
> this won't change the situation for writes. I'll take a look at this when
> I get time, maybe there's something we can do to improve the situation.

I looked a bit into this.

I think one issue is the spinning the workers do:

static int io_wqe_worker(void *data)
{

	while (!test_bit(IO_WQ_BIT_EXIT, &wq->state)) {
		set_current_state(TASK_INTERRUPTIBLE);
loop:
		if (did_work)
			io_worker_spin_for_work(wqe);
		spin_lock_irq(&wqe->lock);
		if (io_wqe_run_queue(wqe)) {

static inline void io_worker_spin_for_work(struct io_wqe *wqe)
{
	int i = 0;

	while (++i < 1000) {
		if (io_wqe_run_queue(wqe))
			break;
		if (need_resched())
			break;
		cpu_relax();
	}
}

even with the cpu_relax(), that causes quite a lot of cross socket
traffic, slowing down the submission side. Which after all frequently
needs to take the wqe->lock, just to be able to submit a queue
entry.

lock, work_list, flags all reside in one cacheline, so it's pretty
likely that a single io_wqe_enqueue would get the cacheline "stolen"
several times during one enqueue - without allowing any progress in the
worker, of course.


I also wonder if we can't avoid dequeuing entries one-by-one within the
worker, at least for the IO_WQ_WORK_HASHED case. Especially when writes
are just hitting the page cache, they're pretty fast, making it
plausible to cause pretty bad contention on the spinlock (even without
the spining above). Whereas the submission side is at least somewhat
likely to be able to submit several queue entries while the worker is
processing one job, that's pretty unlikely for workers.

In the hashed case there shouldn't be another worker processing entries
for the same hash. So it seems quite possible for the wqe to drain a few
of the entries for that hash within one spinlock acquisition, and then
process them one-by-one?

Greetings,

Andres Freund

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-24  9:35       ` Andres Freund
@ 2020-02-24 15:22         ` Jens Axboe
  2020-03-09 20:03           ` Pavel Begunkov
  0 siblings, 1 reply; 10+ messages in thread
From: Jens Axboe @ 2020-02-24 15:22 UTC (permalink / raw)
  To: Andres Freund; +Cc: io-uring

On 2/24/20 2:35 AM, Andres Freund wrote:
> Hi,
> 
> On 2020-02-14 13:49:31 -0700, Jens Axboe wrote:
>> [description of buffered write workloads being slower via io_uring
>> than plain writes]
>> Because I'm working on other items, I didn't read carefully enough. Yes
>> this won't change the situation for writes. I'll take a look at this when
>> I get time, maybe there's something we can do to improve the situation.
> 
> I looked a bit into this.
> 
> I think one issue is the spinning the workers do:
> 
> static int io_wqe_worker(void *data)
> {
> 
> 	while (!test_bit(IO_WQ_BIT_EXIT, &wq->state)) {
> 		set_current_state(TASK_INTERRUPTIBLE);
> loop:
> 		if (did_work)
> 			io_worker_spin_for_work(wqe);
> 		spin_lock_irq(&wqe->lock);
> 		if (io_wqe_run_queue(wqe)) {
> 
> static inline void io_worker_spin_for_work(struct io_wqe *wqe)
> {
> 	int i = 0;
> 
> 	while (++i < 1000) {
> 		if (io_wqe_run_queue(wqe))
> 			break;
> 		if (need_resched())
> 			break;
> 		cpu_relax();
> 	}
> }
> 
> even with the cpu_relax(), that causes quite a lot of cross socket
> traffic, slowing down the submission side. Which after all frequently
> needs to take the wqe->lock, just to be able to submit a queue
> entry.
> 
> lock, work_list, flags all reside in one cacheline, so it's pretty
> likely that a single io_wqe_enqueue would get the cacheline "stolen"
> several times during one enqueue - without allowing any progress in the
> worker, of course.

Since it's provably harmful for this case, and the gain was small (but
noticeable) on single issue cases, I think we should just kill it. With
the poll retry stuff for 5.7, there'll be even less of a need for it.

Care to send a patch for 5.6 to kill it?

> I also wonder if we can't avoid dequeuing entries one-by-one within the
> worker, at least for the IO_WQ_WORK_HASHED case. Especially when writes
> are just hitting the page cache, they're pretty fast, making it
> plausible to cause pretty bad contention on the spinlock (even without
> the spining above). Whereas the submission side is at least somewhat
> likely to be able to submit several queue entries while the worker is
> processing one job, that's pretty unlikely for workers.
> 
> In the hashed case there shouldn't be another worker processing entries
> for the same hash. So it seems quite possible for the wqe to drain a few
> of the entries for that hash within one spinlock acquisition, and then
> process them one-by-one?

Yeah, I think that'd be a good optimization for hashed work. Work N+1
can't make any progress before work N is done anyway, so might as well
grab a batch at the time.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-02-24 15:22         ` Jens Axboe
@ 2020-03-09 20:03           ` Pavel Begunkov
  2020-03-09 20:41             ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Pavel Begunkov @ 2020-03-09 20:03 UTC (permalink / raw)
  To: Jens Axboe, Andres Freund; +Cc: io-uring

On 24/02/2020 18:22, Jens Axboe wrote:
> On 2/24/20 2:35 AM, Andres Freund wrote:
>> Hi,
>>
>> On 2020-02-14 13:49:31 -0700, Jens Axboe wrote:
>>> [description of buffered write workloads being slower via io_uring
>>> than plain writes]
>>> Because I'm working on other items, I didn't read carefully enough. Yes
>>> this won't change the situation for writes. I'll take a look at this when
>>> I get time, maybe there's something we can do to improve the situation.
>>
>> I looked a bit into this.
>>
>> I think one issue is the spinning the workers do:
>>
>> static int io_wqe_worker(void *data)
>> {
>>
>> 	while (!test_bit(IO_WQ_BIT_EXIT, &wq->state)) {
>> 		set_current_state(TASK_INTERRUPTIBLE);
>> loop:
>> 		if (did_work)
>> 			io_worker_spin_for_work(wqe);
>> 		spin_lock_irq(&wqe->lock);
>> 		if (io_wqe_run_queue(wqe)) {
>>
>> static inline void io_worker_spin_for_work(struct io_wqe *wqe)
>> {
>> 	int i = 0;
>>
>> 	while (++i < 1000) {
>> 		if (io_wqe_run_queue(wqe))
>> 			break;
>> 		if (need_resched())
>> 			break;
>> 		cpu_relax();
>> 	}
>> }
>>
>> even with the cpu_relax(), that causes quite a lot of cross socket
>> traffic, slowing down the submission side. Which after all frequently
>> needs to take the wqe->lock, just to be able to submit a queue
>> entry.
>>
>> lock, work_list, flags all reside in one cacheline, so it's pretty
>> likely that a single io_wqe_enqueue would get the cacheline "stolen"
>> several times during one enqueue - without allowing any progress in the
>> worker, of course.
> 
> Since it's provably harmful for this case, and the gain was small (but
> noticeable) on single issue cases, I think we should just kill it. With
> the poll retry stuff for 5.7, there'll be even less of a need for it.
> 
> Care to send a patch for 5.6 to kill it?
> 
>> I also wonder if we can't avoid dequeuing entries one-by-one within the
>> worker, at least for the IO_WQ_WORK_HASHED case. Especially when writes
>> are just hitting the page cache, they're pretty fast, making it
>> plausible to cause pretty bad contention on the spinlock (even without
>> the spining above). Whereas the submission side is at least somewhat
>> likely to be able to submit several queue entries while the worker is
>> processing one job, that's pretty unlikely for workers.
>>
>> In the hashed case there shouldn't be another worker processing entries
>> for the same hash. So it seems quite possible for the wqe to drain a few
>> of the entries for that hash within one spinlock acquisition, and then
>> process them one-by-one?
> 
> Yeah, I think that'd be a good optimization for hashed work. Work N+1
> can't make any progress before work N is done anyway, so might as well
> grab a batch at the time.
> 

A problem here is that we actually have a 2D array of works because of linked
requests.

We can io_wqe_enqueue() dependant works, if have hashed requests, so delegating
it to other threads. But if the work->list is not per-core, it will hurt
locality. Either re-enqueue hashed ones if there is a dependant work. Need to
think how to do better.

-- 
Pavel Begunkov

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-03-09 20:03           ` Pavel Begunkov
@ 2020-03-09 20:41             ` Jens Axboe
  2020-03-09 21:02               ` Pavel Begunkov
  0 siblings, 1 reply; 10+ messages in thread
From: Jens Axboe @ 2020-03-09 20:41 UTC (permalink / raw)
  To: Pavel Begunkov, Andres Freund; +Cc: io-uring

On 3/9/20 2:03 PM, Pavel Begunkov wrote:
> On 24/02/2020 18:22, Jens Axboe wrote:
>> On 2/24/20 2:35 AM, Andres Freund wrote:
>>> Hi,
>>>
>>> On 2020-02-14 13:49:31 -0700, Jens Axboe wrote:
>>>> [description of buffered write workloads being slower via io_uring
>>>> than plain writes]
>>>> Because I'm working on other items, I didn't read carefully enough. Yes
>>>> this won't change the situation for writes. I'll take a look at this when
>>>> I get time, maybe there's something we can do to improve the situation.
>>>
>>> I looked a bit into this.
>>>
>>> I think one issue is the spinning the workers do:
>>>
>>> static int io_wqe_worker(void *data)
>>> {
>>>
>>> 	while (!test_bit(IO_WQ_BIT_EXIT, &wq->state)) {
>>> 		set_current_state(TASK_INTERRUPTIBLE);
>>> loop:
>>> 		if (did_work)
>>> 			io_worker_spin_for_work(wqe);
>>> 		spin_lock_irq(&wqe->lock);
>>> 		if (io_wqe_run_queue(wqe)) {
>>>
>>> static inline void io_worker_spin_for_work(struct io_wqe *wqe)
>>> {
>>> 	int i = 0;
>>>
>>> 	while (++i < 1000) {
>>> 		if (io_wqe_run_queue(wqe))
>>> 			break;
>>> 		if (need_resched())
>>> 			break;
>>> 		cpu_relax();
>>> 	}
>>> }
>>>
>>> even with the cpu_relax(), that causes quite a lot of cross socket
>>> traffic, slowing down the submission side. Which after all frequently
>>> needs to take the wqe->lock, just to be able to submit a queue
>>> entry.
>>>
>>> lock, work_list, flags all reside in one cacheline, so it's pretty
>>> likely that a single io_wqe_enqueue would get the cacheline "stolen"
>>> several times during one enqueue - without allowing any progress in the
>>> worker, of course.
>>
>> Since it's provably harmful for this case, and the gain was small (but
>> noticeable) on single issue cases, I think we should just kill it. With
>> the poll retry stuff for 5.7, there'll be even less of a need for it.
>>
>> Care to send a patch for 5.6 to kill it?
>>
>>> I also wonder if we can't avoid dequeuing entries one-by-one within the
>>> worker, at least for the IO_WQ_WORK_HASHED case. Especially when writes
>>> are just hitting the page cache, they're pretty fast, making it
>>> plausible to cause pretty bad contention on the spinlock (even without
>>> the spining above). Whereas the submission side is at least somewhat
>>> likely to be able to submit several queue entries while the worker is
>>> processing one job, that's pretty unlikely for workers.
>>>
>>> In the hashed case there shouldn't be another worker processing entries
>>> for the same hash. So it seems quite possible for the wqe to drain a few
>>> of the entries for that hash within one spinlock acquisition, and then
>>> process them one-by-one?
>>
>> Yeah, I think that'd be a good optimization for hashed work. Work N+1
>> can't make any progress before work N is done anyway, so might as well
>> grab a batch at the time.
>>
> 
> A problem here is that we actually have a 2D array of works because of linked
> requests.

You could either skip anything with a link, or even just ignore it and
simply re-queue a dependent link if it isn't hashed when it's done if
grabbed in a batch.

> We can io_wqe_enqueue() dependant works, if have hashed requests, so delegating
> it to other threads. But if the work->list is not per-core, it will hurt
> locality. Either re-enqueue hashed ones if there is a dependant work. Need to
> think how to do better.

If we ignore links for a second, I think we can all agree that it'd be a
big win to do the batch.

With links, worst case would then be something where every other link is
hashed.

For a first patch, I'd be quite happy to just stop the batch if there's
a link on a request. The normal case here is buffered writes, and
that'll handle that case perfectly. Links will be no worse than before.
Seems like a no-brainer to me.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-03-09 20:41             ` Jens Axboe
@ 2020-03-09 21:02               ` Pavel Begunkov
  2020-03-09 21:29                 ` Jens Axboe
  0 siblings, 1 reply; 10+ messages in thread
From: Pavel Begunkov @ 2020-03-09 21:02 UTC (permalink / raw)
  To: Jens Axboe, Andres Freund; +Cc: io-uring

On 09/03/2020 23:41, Jens Axboe wrote:
> On 3/9/20 2:03 PM, Pavel Begunkov wrote:
>> On 24/02/2020 18:22, Jens Axboe wrote:
>> A problem here is that we actually have a 2D array of works because of linked
>> requests.
> 
> You could either skip anything with a link, or even just ignore it and
> simply re-queue a dependent link if it isn't hashed when it's done if
> grabbed in a batch.
> 
>> We can io_wqe_enqueue() dependant works, if have hashed requests, so delegating
>> it to other threads. But if the work->list is not per-core, it will hurt
>> locality. Either re-enqueue hashed ones if there is a dependant work. Need to
>> think how to do better.
> 
> If we ignore links for a second, I think we can all agree that it'd be a
> big win to do the batch.

Definitely

> 
> With links, worst case would then be something where every other link is
> hashed.
> 
> For a first patch, I'd be quite happy to just stop the batch if there's
> a link on a request. The normal case here is buffered writes, and
> that'll handle that case perfectly. Links will be no worse than before.
> Seems like a no-brainer to me.

That isn't really a problem, just pointing that there could be optimisations for
different cases.

-- 
Pavel Begunkov

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Buffered IO async context overhead
  2020-03-09 21:02               ` Pavel Begunkov
@ 2020-03-09 21:29                 ` Jens Axboe
  0 siblings, 0 replies; 10+ messages in thread
From: Jens Axboe @ 2020-03-09 21:29 UTC (permalink / raw)
  To: Pavel Begunkov, Andres Freund; +Cc: io-uring

On 3/9/20 3:02 PM, Pavel Begunkov wrote:
> On 09/03/2020 23:41, Jens Axboe wrote:
>> On 3/9/20 2:03 PM, Pavel Begunkov wrote:
>>> On 24/02/2020 18:22, Jens Axboe wrote:
>>> A problem here is that we actually have a 2D array of works because of linked
>>> requests.
>>
>> You could either skip anything with a link, or even just ignore it and
>> simply re-queue a dependent link if it isn't hashed when it's done if
>> grabbed in a batch.
>>
>>> We can io_wqe_enqueue() dependant works, if have hashed requests, so delegating
>>> it to other threads. But if the work->list is not per-core, it will hurt
>>> locality. Either re-enqueue hashed ones if there is a dependant work. Need to
>>> think how to do better.
>>
>> If we ignore links for a second, I think we can all agree that it'd be a
>> big win to do the batch.
> 
> Definitely
> 
>>
>> With links, worst case would then be something where every other link is
>> hashed.
>>
>> For a first patch, I'd be quite happy to just stop the batch if there's
>> a link on a request. The normal case here is buffered writes, and
>> that'll handle that case perfectly. Links will be no worse than before.
>> Seems like a no-brainer to me.
> 
> That isn't really a problem, just pointing that there could be
> optimisations for different cases.

Definitely, in case it wasn't clear, my suggestion was merely to go for
the main win and ignore the link side for now. It's best done separately
anyway, with the link stuff tweaking the batch behavior.

-- 
Jens Axboe


^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2020-03-09 21:29 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-02-14 19:50 Buffered IO async context overhead Andres Freund
2020-02-14 20:13 ` Jens Axboe
2020-02-14 20:31   ` Andres Freund
2020-02-14 20:49     ` Jens Axboe
2020-02-24  9:35       ` Andres Freund
2020-02-24 15:22         ` Jens Axboe
2020-03-09 20:03           ` Pavel Begunkov
2020-03-09 20:41             ` Jens Axboe
2020-03-09 21:02               ` Pavel Begunkov
2020-03-09 21:29                 ` Jens Axboe

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).