* [PATCH 0/2] slat and clat reporting with sqthread_poll [not found] <CGME20221104112440epcas5p24f13b6a1c3db0b38b8453a896fb31575@epcas5p2.samsung.com> @ 2022-11-04 11:13 ` Ankit Kumar 2022-11-04 11:13 ` [PATCH 1/2] engines:io_uring: slat and clat calculation " Ankit Kumar 2022-11-04 11:13 ` [PATCH 2/2] doc: update about sqthread_poll Ankit Kumar 0 siblings, 2 replies; 5+ messages in thread From: Ankit Kumar @ 2022-11-04 11:13 UTC (permalink / raw) To: axboe; +Cc: fio, vincentfu, Ankit Kumar When sqthread_poll is specified for io_uring and io_uring_cmd I/O engines, fio doesn't report submission latency and the completion latency is too big. Latency data before: fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 clat (msec): min=1120.1k, max=1120.1k, avg=1120092.65, stdev= 8.32 lat (usec): min=104, max=5312, avg=132.81, stdev=325.05 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] lat (msec) : >=2000=100.00% As kernel polling thread handles the submission, there is no way to know when the actual submission happened. We can only rely on the commit hook and measure the issue time. Latency data after the change: fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 slat (nsec): min=50, max=2230, avg=146.68, stdev=138.08 clat (usec): min=105, max=5151, avg=132.98, stdev=314.89 lat (usec): min=105, max=5153, avg=133.13, stdev=315.03 clat percentiles (usec): | 1.00th=[ 106], 5.00th=[ 108], 10.00th=[ 109], 20.00th=[ 110], | 30.00th=[ 111], 40.00th=[ 113], 50.00th=[ 114], 60.00th=[ 115], | 70.00th=[ 117], 80.00th=[ 118], 90.00th=[ 119], 95.00th=[ 121], | 99.00th=[ 123], 99.50th=[ 123], 99.90th=[ 5145], 99.95th=[ 5145], | 99.99th=[ 5145] lat (usec) : 250=99.61% lat (msec) : 10=0.39% This fixes the issue: https://github.com/axboe/fio/issues/1484 Ankit Kumar (2): engines:io_uring: slat and clat calculation with sqthread_poll doc: update about sqthread_poll HOWTO.rst | 4 +++- engines/io_uring.c | 4 ++++ fio.1 | 4 +++- 3 files changed, 10 insertions(+), 2 deletions(-) -- 2.17.1 ^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll 2022-11-04 11:13 ` [PATCH 0/2] slat and clat reporting with sqthread_poll Ankit Kumar @ 2022-11-04 11:13 ` Ankit Kumar 2022-11-22 22:25 ` Vincent Fu 2022-11-04 11:13 ` [PATCH 2/2] doc: update about sqthread_poll Ankit Kumar 1 sibling, 1 reply; 5+ messages in thread From: Ankit Kumar @ 2022-11-04 11:13 UTC (permalink / raw) To: axboe; +Cc: fio, vincentfu, Ankit Kumar When sqthread_poll is specified for io_uring and io_uring_cmd I/O engines, fio doesn't report submission latency and the completion latency is too big. Latency data before: fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 clat (msec): min=1120.1k, max=1120.1k, avg=1120092.65, stdev= 8.32 lat (usec): min=104, max=5312, avg=132.81, stdev=325.05 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] lat (msec) : >=2000=100.00% As kernel polling thread handles the submission, there is no way to know when the actual submission happened. We can only rely on the commit hook and measure the issue time. Latency data after the change: fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 slat (nsec): min=50, max=2230, avg=146.68, stdev=138.08 clat (usec): min=105, max=5151, avg=132.98, stdev=314.89 lat (usec): min=105, max=5153, avg=133.13, stdev=315.03 clat percentiles (usec): | 1.00th=[ 106], 5.00th=[ 108], 10.00th=[ 109], 20.00th=[ 110], | 30.00th=[ 111], 40.00th=[ 113], 50.00th=[ 114], 60.00th=[ 115], | 70.00th=[ 117], 80.00th=[ 118], 90.00th=[ 119], 95.00th=[ 121], | 99.00th=[ 123], 99.50th=[ 123], 99.90th=[ 5145], 99.95th=[ 5145], | 99.99th=[ 5145] lat (usec) : 250=99.61% lat (msec) : 10=0.39% Signed-off-by: Ankit Kumar <ankit.kumar@samsung.com> --- engines/io_uring.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/engines/io_uring.c b/engines/io_uring.c index 6906e0a4..0d18fd4a 100644 --- a/engines/io_uring.c +++ b/engines/io_uring.c @@ -637,12 +637,16 @@ static int fio_ioring_commit(struct thread_data *td) */ if (o->sqpoll_thread) { struct io_sq_ring *ring = &ld->sq_ring; + unsigned start = *ld->sq_ring.head; unsigned flags; flags = atomic_load_acquire(ring->flags); if (flags & IORING_SQ_NEED_WAKEUP) io_uring_enter(ld, ld->queued, 0, IORING_ENTER_SQ_WAKEUP); + fio_ioring_queued(td, start, ld->queued); + io_u_mark_submit(td, ld->queued); + ld->queued = 0; return 0; } -- 2.17.1 ^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll 2022-11-04 11:13 ` [PATCH 1/2] engines:io_uring: slat and clat calculation " Ankit Kumar @ 2022-11-22 22:25 ` Vincent Fu 2022-11-22 22:56 ` Jens Axboe 0 siblings, 1 reply; 5+ messages in thread From: Vincent Fu @ 2022-11-22 22:25 UTC (permalink / raw) To: Ankit Kumar, axboe; +Cc: fio On 11/4/22 07:13, Ankit Kumar wrote: > When sqthread_poll is specified for io_uring and io_uring_cmd I/O engines, > fio doesn't report submission latency and the completion latency is too big. > Latency data before: > > fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 > clat (msec): min=1120.1k, max=1120.1k, avg=1120092.65, stdev= 8.32 > lat (usec): min=104, max=5312, avg=132.81, stdev=325.05 > 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] > lat (msec) : >=2000=100.00% > > As kernel polling thread handles the submission, there is no way to know when > the actual submission happened. We can only rely on the commit hook and > measure the issue time. > Latency data after the change: > > fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 > slat (nsec): min=50, max=2230, avg=146.68, stdev=138.08 > clat (usec): min=105, max=5151, avg=132.98, stdev=314.89 > lat (usec): min=105, max=5153, avg=133.13, stdev=315.03 > clat percentiles (usec): > | 1.00th=[ 106], 5.00th=[ 108], 10.00th=[ 109], 20.00th=[ 110], > | 30.00th=[ 111], 40.00th=[ 113], 50.00th=[ 114], 60.00th=[ 115], > | 70.00th=[ 117], 80.00th=[ 118], 90.00th=[ 119], 95.00th=[ 121], > | 99.00th=[ 123], 99.50th=[ 123], 99.90th=[ 5145], 99.95th=[ 5145], > | 99.99th=[ 5145] > lat (usec) : 250=99.61% > lat (msec) : 10=0.39% > > Signed-off-by: Ankit Kumar <ankit.kumar@samsung.com> > --- > engines/io_uring.c | 4 ++++ > 1 file changed, 4 insertions(+) > > diff --git a/engines/io_uring.c b/engines/io_uring.c > index 6906e0a4..0d18fd4a 100644 > --- a/engines/io_uring.c > +++ b/engines/io_uring.c > @@ -637,12 +637,16 @@ static int fio_ioring_commit(struct thread_data *td) > */ > if (o->sqpoll_thread) { > struct io_sq_ring *ring = &ld->sq_ring; > + unsigned start = *ld->sq_ring.head; > unsigned flags; > > flags = atomic_load_acquire(ring->flags); > if (flags & IORING_SQ_NEED_WAKEUP) > io_uring_enter(ld, ld->queued, 0, > IORING_ENTER_SQ_WAKEUP); > + fio_ioring_queued(td, start, ld->queued); > + io_u_mark_submit(td, ld->queued); > + > ld->queued = 0; > return 0; > } Ankit, I think the important point here is to make sure that the reported slat and clat values when sqthread_poll=1 can be meaningfully compared to corresponding values when sqthread_poll=0. That means we need to record issue_time at corresponding points in the submission process but it's not obvious to me where to record issue_time when sqthread_poll=1. I can think of two reasonable solutions when sqthread_poll is enabled: 1) suppress slat and clat when sqthread_poll=1 because we don't have a good place to record issue_time 2) record issue_time and the end of fio_ioring_queue() when IORING_SQ_NEED_WAKEUP is not set and in commit() as you have above when it is flagged What do you think? Jens, do you have an opinion here? Vincent ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll 2022-11-22 22:25 ` Vincent Fu @ 2022-11-22 22:56 ` Jens Axboe 0 siblings, 0 replies; 5+ messages in thread From: Jens Axboe @ 2022-11-22 22:56 UTC (permalink / raw) To: Vincent Fu, Ankit Kumar; +Cc: fio On 11/22/22 3:25?PM, Vincent Fu wrote: > On 11/4/22 07:13, Ankit Kumar wrote: >> When sqthread_poll is specified for io_uring and io_uring_cmd I/O engines, >> fio doesn't report submission latency and the completion latency is too big. >> Latency data before: >> >> fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 >> ???? clat (msec): min=1120.1k, max=1120.1k, avg=1120092.65, stdev= 8.32 >> ????? lat (usec): min=104, max=5312, avg=132.81, stdev=325.05 >> ???? 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] >> ?? lat (msec)?? : >=2000=100.00% >> >> As kernel polling thread handles the submission, there is no way to know when >> the actual submission happened. We can only rely on the commit hook and >> measure the issue time. >> Latency data after the change: >> >> fio --name=test --size=1M --rw=randread --ioengine=io_uring --sqthread_poll=1 >> ???? slat (nsec): min=50, max=2230, avg=146.68, stdev=138.08 >> ???? clat (usec): min=105, max=5151, avg=132.98, stdev=314.89 >> ????? lat (usec): min=105, max=5153, avg=133.13, stdev=315.03 >> ???? clat percentiles (usec): >> ????? |? 1.00th=[? 106],? 5.00th=[? 108], 10.00th=[? 109], 20.00th=[? 110], >> ????? | 30.00th=[? 111], 40.00th=[? 113], 50.00th=[? 114], 60.00th=[? 115], >> ????? | 70.00th=[? 117], 80.00th=[? 118], 90.00th=[? 119], 95.00th=[? 121], >> ????? | 99.00th=[? 123], 99.50th=[? 123], 99.90th=[ 5145], 99.95th=[ 5145], >> ????? | 99.99th=[ 5145] >> ?? lat (usec)?? : 250=99.61% >> ?? lat (msec)?? : 10=0.39% >> >> Signed-off-by: Ankit Kumar <ankit.kumar@samsung.com> >> --- >> ? engines/io_uring.c | 4 ++++ >> ? 1 file changed, 4 insertions(+) >> >> diff --git a/engines/io_uring.c b/engines/io_uring.c >> index 6906e0a4..0d18fd4a 100644 >> --- a/engines/io_uring.c >> +++ b/engines/io_uring.c >> @@ -637,12 +637,16 @@ static int fio_ioring_commit(struct thread_data *td) >> ?????? */ >> ????? if (o->sqpoll_thread) { >> ????????? struct io_sq_ring *ring = &ld->sq_ring; >> +??????? unsigned start = *ld->sq_ring.head; >> ????????? unsigned flags; >> ? ????????? flags = atomic_load_acquire(ring->flags); >> ????????? if (flags & IORING_SQ_NEED_WAKEUP) >> ????????????? io_uring_enter(ld, ld->queued, 0, >> ????????????????????? IORING_ENTER_SQ_WAKEUP); >> +??????? fio_ioring_queued(td, start, ld->queued); >> +??????? io_u_mark_submit(td, ld->queued); >> + >> ????????? ld->queued = 0; >> ????????? return 0; >> ????? } > > Ankit, I think the important point here is to make sure that the > reported slat and clat values when sqthread_poll=1 can be meaningfully > compared to corresponding values when sqthread_poll=0. > > That means we need to record issue_time at corresponding points in the > submission process but it's not obvious to me where to record > issue_time when sqthread_poll=1. > > I can think of two reasonable solutions when sqthread_poll is enabled: > > 1) suppress slat and clat when sqthread_poll=1 because we don't have a > good place to record issue_time > > 2) record issue_time and the end of fio_ioring_queue() when > IORING_SQ_NEED_WAKEUP is not set and in commit() as you have above > when it is flagged > > What do you think? > > Jens, do you have an opinion here? Submission latency for SQPOLL is really just the time it takes to fill in the SQ ring entries, and any syscall if IORING_SQ_NEED_WAKEUP is set. For normal fio use, that flag will never be set and we'll basically just fill in SQEs. I'm not convinced logging that time separate makes sense, so perhaps the sanest to suppress SLAT if SQPOLL is set? CLAT definitely does make sense, as it's the time from doing the submit call (whether wakeup is set or not) and until we reap the completion. -- Jens Axboe ^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH 2/2] doc: update about sqthread_poll 2022-11-04 11:13 ` [PATCH 0/2] slat and clat reporting with sqthread_poll Ankit Kumar 2022-11-04 11:13 ` [PATCH 1/2] engines:io_uring: slat and clat calculation " Ankit Kumar @ 2022-11-04 11:13 ` Ankit Kumar 1 sibling, 0 replies; 5+ messages in thread From: Ankit Kumar @ 2022-11-04 11:13 UTC (permalink / raw) To: axboe; +Cc: fio, vincentfu, Ankit Kumar Update that when sqthread_poll is enabled the submission and completion latencies reported may not be accurate. This is because the actual submission is done by the kernel polling thread. Signed-off-by: Ankit Kumar <ankit.kumar@samsung.com> --- HOWTO.rst | 4 +++- fio.1 | 4 +++- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/HOWTO.rst b/HOWTO.rst index 0fb5593e..dea625fe 100644 --- a/HOWTO.rst +++ b/HOWTO.rst @@ -2299,7 +2299,9 @@ with the caveat that when used on the command line, they must come after the kernel of available items in the SQ ring. If this option is set, the act of submitting IO will be done by a polling thread in the kernel. This frees up cycles for fio, at the cost of using more CPU in the - system. + system. The submission and completion latencies reported may not be + accurate as fio has no idea when the kernel polling thread submits the + actual I/O. .. option:: sqthread_poll_cpu : [io_uring] [io_uring_cmd] diff --git a/fio.1 b/fio.1 index 4324a975..95c5ce55 100644 --- a/fio.1 +++ b/fio.1 @@ -2090,7 +2090,9 @@ sqthread_poll option. Normally fio will submit IO by issuing a system call to notify the kernel of available items in the SQ ring. If this option is set, the act of submitting IO will be done by a polling thread in the kernel. This frees up cycles for fio, at -the cost of using more CPU in the system. +the cost of using more CPU in the system. The submission and completion +latencies reported may not be accurate as fio has no idea when the kernel +polling thread submits the actual I/O. .TP .BI (io_uring,io_uring_cmd)sqthread_poll_cpu When `sqthread_poll` is set, this option provides a way to define which CPU -- 2.17.1 ^ permalink raw reply related [flat|nested] 5+ messages in thread
end of thread, other threads:[~2022-11-22 22:56 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
[not found] <CGME20221104112440epcas5p24f13b6a1c3db0b38b8453a896fb31575@epcas5p2.samsung.com>
2022-11-04 11:13 ` [PATCH 0/2] slat and clat reporting with sqthread_poll Ankit Kumar
2022-11-04 11:13 ` [PATCH 1/2] engines:io_uring: slat and clat calculation " Ankit Kumar
2022-11-22 22:25 ` Vincent Fu
2022-11-22 22:56 ` Jens Axboe
2022-11-04 11:13 ` [PATCH 2/2] doc: update about sqthread_poll Ankit Kumar
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).