[PATCH 0/2] slat and clat reporting with sqthread_poll

[PATCH 0/2] slat and clat reporting with sqthread_poll

[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

[PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll

[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

Re: [PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll

[Vincent Fu]

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

Re: [PATCH 1/2] engines:io_uring: slat and clat calculation with sqthread_poll

[Jens Axboe]

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

[PATCH 2/2] doc: update about sqthread_poll

[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