Re: [PATCH RFC for-next 0/8] io_uring: tw contention improvments

[Dylan Yudaken <dylany@fb.com>]

On Wed, 2022-06-22 at 19:24 +0800, Hao Xu wrote:
> On 6/22/22 19:16, Hao Xu wrote:
> > On 6/22/22 17:31, Dylan Yudaken wrote:
> > > On Tue, 2022-06-21 at 15:34 +0800, Hao Xu wrote:
> > > > On 6/21/22 15:03, Dylan Yudaken wrote:
> > > > > On Tue, 2022-06-21 at 13:10 +0800, Hao Xu wrote:
> > > > > > On 6/21/22 00:18, Dylan Yudaken wrote:
> > > > > > > Task work currently uses a spin lock to guard task_list
> > > > > > > and
> > > > > > > task_running. Some use cases such as networking can
> > > > > > > trigger
> > > > > > > task_work_add
> > > > > > > from multiple threads all at once, which suffers from
> > > > > > > contention
> > > > > > > here.
> > > > > > > 
> > > > > > > This can be changed to use a lockless list which seems to
> > > > > > > have
> > > > > > > better
> > > > > > > performance. Running the micro benchmark in [1] I see 20%
> > > > > > > improvment in
> > > > > > > multithreaded task work add. It required removing the
> > > > > > > priority
> > > > > > > tw
> > > > > > > list
> > > > > > > optimisation, however it isn't clear how important that
> > > > > > > optimisation is.
> > > > > > > Additionally it has fairly easy to break semantics.
> > > > > > > 
> > > > > > > Patch 1-2 remove the priority tw list optimisation
> > > > > > > Patch 3-5 add lockless lists for task work
> > > > > > > Patch 6 fixes a bug I noticed in io_uring event tracing
> > > > > > > Patch 7-8 adds tracing for task_work_run
> > > > > > > 
> > > > > > 
> > > > > > Compared to the spinlock overhead, the prio task list
> > > > > > optimization is
> > > > > > definitely unimportant, so I agree with removing it here.
> > > > > > Replace the task list with llisy was something I considered
> > > > > > but I
> > > > > > gave
> > > > > > it up since it changes the list to a stack which means we
> > > > > > have to
> > > > > > handle
> > > > > > the tasks in a reverse order. This may affect the latency,
> > > > > > do you
> > > > > > have
> > > > > > some numbers for it, like avg and 99% 95% lat?
> > > > > > 
> > > > > 
> > > > > Do you have an idea for how to test that? I used a
> > > > > microbenchmark
> > > > > as
> > > > > well as a network benchmark [1] to verify that overall
> > > > > throughput
> > > > > is
> > > > > higher. TW latency sounds a lot more complicated to measure
> > > > > as it's
> > > > > difficult to trigger accurately.
> > > > > 
> > > > > My feeling is that with reasonable batching (say 8-16 items)
> > > > > the
> > > > > latency will be low as TW is generally very quick, but if you
> > > > > have
> > > > > an
> > > > > idea for benchmarking I can take a look
> > > > > 
> > > > > [1]: https://github.com/DylanZA/netbench
> > > > 
> > > > It can be normal IO requests I think. We can test the latency
> > > > by fio
> > > > with small size IO to a fast block device(like nvme) in SQPOLL
> > > > mode(since for non-SQPOLL, it doesn't make difference). This
> > > > way we
> > > > can
> > > > see the influence of reverse order handling.
> > > > 
> > > > Regards,
> > > > Hao
> > > 
> > > I see little difference locally, but there is quite a big stdev
> > > so it's
> > > possible my test setup is a bit wonky
> > > 
> > > new:
> > >      clat (msec): min=2027, max=10544, avg=6347.10, stdev=2458.20
> > >       lat (nsec): min=1440, max=16719k, avg=119714.72,
> > > stdev=153571.49
> > > old:
> > >      clat (msec): min=2738, max=10550, avg=6700.68, stdev=2251.77
> > >       lat (nsec): min=1278, max=16610k, avg=121025.73,
> > > stdev=211896.14
> > > 
> > 
> > Hi Dylan,
> > 
> > Could you post the arguments you use and the 99% 95% latency as
> > well?
> > 
> > Regards,
> > Hao
> > 
> 
> One thing I'm worrying about is under heavy workloads, there are
> contiguous TWs coming in, thus the TWs at the end of the TW list
> doesn't
> get the chance to run, which leads to the latency of those ones
> becoming
> high.

Pavel mentioned I should change some arguments, so I reran it. I'll
just post all the output below as not sure exactly what you are looking
for. Note I checked that it was definitely batching and it is doing
batches of 10-20 in tctx_task_work


*** config ***

[global]
ioengine=io_uring
sqthread_poll=1
registerfiles=1
fixedbufs=1
hipri=0
thread=1
direct=0
rw=randread
time_based=1
runtime=600
ramp_time=30
randrepeat=0
group_reporting=0
sqthread_poll_cpu=15
iodepth=32

[job0]
filename=/dev/nullb0
cpus_allowed=1
bs=512

*** new ***
job0: (g=0): rw=randread, bs=(R) 512B-512B, (W) 512B-512B, (T) 512B-
512B, ioengine=io_uring, iodepth=32
fio-3.30-59-gd4bf5
Starting 1 thread
Jobs: 1 (f=0): [f(1)][100.0%][r=360MiB/s][r=738k IOPS][eta 00m:00s]
job0: (groupid=0, jobs=1): err= 0: pid=37255: Wed Jun 22 03:44:23 2022
  read: IOPS=596k, BW=291MiB/s (305MB/s)(171GiB/600001msec)
    clat (msec): min=30343, max=630343, avg=369885.75, stdev=164921.26
     lat (usec): min=14, max=1802, avg=53.23, stdev=18.84
    clat percentiles (msec):
     |  1.00th=[17113],  5.00th=[17113], 10.00th=[17113],
20.00th=[17113],
     | 30.00th=[17113], 40.00th=[17113], 50.00th=[17113],
60.00th=[17113],
     | 70.00th=[17113], 80.00th=[17113], 90.00th=[17113],
95.00th=[17113],
     | 99.00th=[17113], 99.50th=[17113], 99.90th=[17113],
99.95th=[17113],
     | 99.99th=[17113]
   bw (  KiB/s): min=169237, max=381603, per=100.00%, avg=298171.22,
stdev=70580.65, samples=1199
   iops        : min=338474, max=763206, avg=596342.60,
stdev=141161.31, samples=1199
  lat (msec)   : >=2000=100.00%
  cpu          : usr=99.98%, sys=0.00%, ctx=4378, majf=0, minf=9
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=100.0%,
>=64=0.0%
     submit    : 0=0.0%, 4=0.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.1%, 64=0.0%,
>=64=0.0%
     issued rwts: total=357661967,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=32

Run status group 0 (all jobs):
   READ: bw=291MiB/s (305MB/s), 291MiB/s-291MiB/s (305MB/s-305MB/s),
io=171GiB (183GB), run=600001-600001msec

Disk stats (read/write):
  nullb0: ios=72127555/0, merge=11/0, ticks=1396298/0,
in_queue=1396298, util=100.00%
  
*** old ***

job0: (g=0): rw=randread, bs=(R) 512B-512B, (W) 512B-512B, (T) 512B-
512B, ioengine=io_uring, iodepth=32
fio-3.30-59-gd4bf5
Starting 1 thread
Jobs: 1 (f=1): [r(1)][100.0%][r=367MiB/s][r=751k IOPS][eta 00m:00s]
job0: (groupid=0, jobs=1): err= 0: pid=19216: Wed Jun 22 04:43:36 2022
  read: IOPS=609k, BW=297MiB/s (312MB/s)(174GiB/600001msec)
    clat (msec): min=30333, max=630333, avg=368961.53, stdev=164532.01
     lat (usec): min=14, max=5830, avg=52.11, stdev=18.64
    clat percentiles (msec):
     |  1.00th=[17113],  5.00th=[17113], 10.00th=[17113],
20.00th=[17113],
     | 30.00th=[17113], 40.00th=[17113], 50.00th=[17113],
60.00th=[17113],
     | 70.00th=[17113], 80.00th=[17113], 90.00th=[17113],
95.00th=[17113],
     | 99.00th=[17113], 99.50th=[17113], 99.90th=[17113],
99.95th=[17113],
     | 99.99th=[17113]
   bw (  KiB/s): min=170273, max=386932, per=100.00%, avg=304548.39,
stdev=70732.20, samples=1200
   iops        : min=340547, max=773864, avg=609096.94,
stdev=141464.41, samples=1200
  lat (msec)   : >=2000=100.00%
  cpu          : usr=99.98%, sys=0.00%, ctx=3912, majf=0, minf=5
  IO depths    : 1=0.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=100.0%,
>=64=0.0%
     submit    : 0=0.0%, 4=0.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.1%, 64=0.0%,
>=64=0.0%
     issued rwts: total=365258392,0,0,0 short=0,0,0,0 dropped=0,0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=32

Run status group 0 (all jobs):
   READ: bw=297MiB/s (312MB/s), 297MiB/s-297MiB/s (312MB/s-312MB/s),
io=174GiB (187GB), run=600001-600001msec

Disk stats (read/write):
  nullb0: ios=69031421/0, merge=1/0, ticks=1323086/0, in_queue=1323086,
util=100.00%