public inbox for [email protected]
 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

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