LinuxLists.cc - [PATCH v3] io_uring: Statistics of the true utilization of sq threads.

2023-11-15 12:33:17

Subject: [PATCH v3] io_uring: Statistics of the true utilization of sq threads.

v3:
1.Since the sq thread has a while(1) structure, during this process,
there may be a lot of time that is not processing IO but does not
exceed the timeout period, therefore, the sqpoll thread will keep
running and will keep occupying the CPU. Obviously, the CPU is wasted at
this time;Our goal is to count the part of the time that the sqpoll
thread actually processes IO, so as to reflect the part of the CPU it
uses to process IO, which can be used to help improve the actual
utilization of the CPU in the future.

2."work_time" in the code represents the sum of the jiffies count of the
sq thread actually processing IO, that is, how many milliseconds it
actually takes to process IO. "total_time" represents the total time
that the sq thread has elapsed from the beginning of the loop to the
current time point, that is, how many milliseconds it has spent in
total.
The output "SqBusy" represents the percentage of time utilization that
the sq thread actually uses to process IO.

3.The task_pid value in the io_sq_data structure should be assigned
after the sq thread is created, otherwise the pid of its parent
process will be recorded.

4.After many tests, we do not need to obtain ctx->uring_lock in advance
when obtaining ctx->sq_data. We can avoid null pointer references by
judging that ctx is not null.

Signed-off-by: Xiaobing Li <[email protected]>

The test results are as follows:
Every 0.5s: cat /proc/281126/fdinfo/6 | grep Sq
SqMask: 0x3
SqHead: 1168417
SqTail: 1168418
CachedSqHead: 1168418
SqThread: 281126
SqThreadCpu: 55
SqBusy: 96%
---
io_uring/fdinfo.c | 31 ++++++++++++++++---------------
io_uring/sqpoll.c | 20 ++++++++++++++++----
io_uring/sqpoll.h | 2 ++
3 files changed, 34 insertions(+), 19 deletions(-)

diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c
index f04a43044d91..b9e2e339140d 100644
--- a/io_uring/fdinfo.c
+++ b/io_uring/fdinfo.c
@@ -64,6 +64,7 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
unsigned int sq_shift = 0;
unsigned int sq_entries, cq_entries;
int sq_pid = -1, sq_cpu = -1;
+ int sq_busy = 0;
bool has_lock;
unsigned int i;

@@ -134,6 +135,21 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
seq_printf(m, "\n");
}

+ if (ctx && (ctx->flags & IORING_SETUP_SQPOLL)) {
+ struct io_sq_data *sq = ctx->sq_data;
+
+ if (sq && sq->total_time != 0)
+ sq_busy = (int)(sq->work_time * 100 / sq->total_time);
+
+ sq_pid = sq->task_pid;
+ sq_cpu = sq->sq_cpu;
+ }
+
+ seq_printf(m, "SqThread:\t%d\n", sq_pid);
+ seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
+ seq_printf(m, "SqBusy:\t%d%%\n", sq_busy);
+ seq_printf(m, "UserFiles:\t%u\n", ctx->nr_user_files);
+
/*
* Avoid ABBA deadlock between the seq lock and the io_uring mutex,
* since fdinfo case grabs it in the opposite direction of normal use
@@ -142,21 +158,6 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
*/
has_lock = mutex_trylock(&ctx->uring_lock);

- if (has_lock && (ctx->flags & IORING_SETUP_SQPOLL)) {
- struct io_sq_data *sq = ctx->sq_data;
-
- if (mutex_trylock(&sq->lock)) {
- if (sq->thread) {
- sq_pid = task_pid_nr(sq->thread);
- sq_cpu = task_cpu(sq->thread);
- }
- mutex_unlock(&sq->lock);
- }
- }
-
- seq_printf(m, "SqThread:\t%d\n", sq_pid);
- seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
- seq_printf(m, "UserFiles:\t%u\n", ctx->nr_user_files);
for (i = 0; has_lock && i < ctx->nr_user_files; i++) {
struct file *f = io_file_from_index(&ctx->file_table, i);

diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
index bd6c2c7959a5..dc093adc1ce5 100644
--- a/io_uring/sqpoll.c
+++ b/io_uring/sqpoll.c
@@ -224,17 +224,21 @@ static int io_sq_thread(void *data)
struct io_ring_ctx *ctx;
unsigned long timeout = 0;
char buf[TASK_COMM_LEN];
+ unsigned long sq_start, sq_work_begin, sq_work_end;
DEFINE_WAIT(wait);

snprintf(buf, sizeof(buf), "iou-sqp-%d", sqd->task_pid);
set_task_comm(current, buf);

- if (sqd->sq_cpu != -1)
+ if (sqd->sq_cpu != -1) {
set_cpus_allowed_ptr(current, cpumask_of(sqd->sq_cpu));
- else
+ } else {
set_cpus_allowed_ptr(current, cpu_online_mask);
+ sqd->sq_cpu = raw_smp_processor_id();
+ }

mutex_lock(&sqd->lock);
+ sq_start = jiffies;
while (1) {
bool cap_entries, sqt_spin = false;

@@ -245,6 +249,7 @@ static int io_sq_thread(void *data)
}

cap_entries = !list_is_singular(&sqd->ctx_list);
+ sq_work_begin = jiffies;
list_for_each_entry(ctx, &sqd->ctx_list, sqd_list) {
int ret = __io_sq_thread(ctx, cap_entries);

@@ -254,6 +259,11 @@ static int io_sq_thread(void *data)
if (io_run_task_work())
sqt_spin = true;

+ sq_work_end = jiffies;
+ sqd->total_time = sq_work_end - sq_start;
+ if (sqt_spin == true)
+ sqd->work_time += sq_work_end - sq_work_begin;
+
if (sqt_spin || !time_after(jiffies, timeout)) {
if (sqt_spin)
timeout = jiffies + sqd->sq_thread_idle;
@@ -261,6 +271,7 @@ static int io_sq_thread(void *data)
mutex_unlock(&sqd->lock);
cond_resched();
mutex_lock(&sqd->lock);
+ sqd->sq_cpu = raw_smp_processor_id();
}
continue;
}
@@ -294,6 +305,7 @@ static int io_sq_thread(void *data)
mutex_unlock(&sqd->lock);
schedule();
mutex_lock(&sqd->lock);
+ sqd->sq_cpu = raw_smp_processor_id();
}
list_for_each_entry(ctx, &sqd->ctx_list, sqd_list)
atomic_andnot(IORING_SQ_NEED_WAKEUP,
@@ -395,14 +407,14 @@ __cold int io_sq_offload_create(struct io_ring_ctx *ctx,
sqd->sq_cpu = -1;
}

- sqd->task_pid = current->pid;
- sqd->task_tgid = current->tgid;
+ sqd->task_tgid = current->pid;
tsk = create_io_thread(io_sq_thread, sqd, NUMA_NO_NODE);
if (IS_ERR(tsk)) {
ret = PTR_ERR(tsk);
goto err_sqpoll;
}

+ sqd->task_pid = task_pid_nr(tsk);
sqd->thread = tsk;
ret = io_uring_alloc_task_context(tsk, ctx);
wake_up_new_task(tsk);
diff --git a/io_uring/sqpoll.h b/io_uring/sqpoll.h
index 8df37e8c9149..fd6fa9587843 100644
--- a/io_uring/sqpoll.h
+++ b/io_uring/sqpoll.h
@@ -16,6 +16,8 @@ struct io_sq_data {
pid_t task_pid;
pid_t task_tgid;

+ unsigned long work_time;
+ unsigned long total_time;
unsigned long state;
struct completion exited;
};
--
2.34.1

2023-11-15 13:51:41

by Jens Axboe

[permalink] [raw]

Subject: Re: [PATCH v3] io_uring: Statistics of the true utilization of sq threads.

On 11/15/23 5:18 AM, Xiaobing Li wrote:
> v3:
> 1.Since the sq thread has a while(1) structure, during this process,
> there may be a lot of time that is not processing IO but does not
> exceed the timeout period, therefore, the sqpoll thread will keep
> running and will keep occupying the CPU. Obviously, the CPU is wasted at
> this time;Our goal is to count the part of the time that the sqpoll
> thread actually processes IO, so as to reflect the part of the CPU it
> uses to process IO, which can be used to help improve the actual
> utilization of the CPU in the future.
>
> 2."work_time" in the code represents the sum of the jiffies count of the
> sq thread actually processing IO, that is, how many milliseconds it
> actually takes to process IO. "total_time" represents the total time
> that the sq thread has elapsed from the beginning of the loop to the
> current time point, that is, how many milliseconds it has spent in
> total.
> The output "SqBusy" represents the percentage of time utilization that
> the sq thread actually uses to process IO.
>
> 3.The task_pid value in the io_sq_data structure should be assigned
> after the sq thread is created, otherwise the pid of its parent
> process will be recorded.
>
> 4.After many tests, we do not need to obtain ctx->uring_lock in advance
> when obtaining ctx->sq_data. We can avoid null pointer references by
> judging that ctx is not null.

This is mixed in with my patch, please just base it on top of the v4
I'll send out now rather than integrate it. And then you'd need that rcu
free patch as well on top of that, then your changes as a separate
patch.

--
Jens Axboe

2023-11-20 14:26:57

by Dan Carpenter

[permalink] [raw]

Subject: Re: [PATCH v3] io_uring: Statistics of the true utilization of sq threads.

Hi Xiaobing,

kernel test robot
patch link: If you fix the issue the same patch/commit), | Reported-by: kernel | Reported-by: Dan | Closes: noticed the following build warnings:
.com/docs/git-format-patch#_base_tree_information]">https://git-scm.com/docs/git-format-patch#_base_tree_information]
/github.com/intel-lab-lkp/linux/commits/Xiaobing-Li/io_uring-Statistics-of-the-true-utilization-of-sq-threads/20231115-211954">https://github.com/intel-lab-lkp/linux/commits/Xiaobing-Li/io_uring-Statistics-of-the-true-utilization-of-sq-threads/20231115-211954
href="https://lore.kernel.org/r/20231115121839.12556-1-xiaobing.li%40samsung.com">https://lore.kernel.org/r/20231115121839.12556-1-xiaobing.li%40samsung.com
v3] io_uring: Statistics of the true utilization of sq threads.
(https://download.01.org/0day-ci/archive/20231116/[email protected]/config)
(Debian 12.2.0-14) 12.2.0
href="https://download.01.org/0day-ci/archive/20231116/202311160629.h4GrebJh-lkp@intel.com/reproduce)">https://download.01.org/0day-ci/archive/20231116/[email protected]/reproduce)
in a separate patch/commit (i.e. not just a new version of
kindly add following tags
test robot <[email protected]>
Carpenter <[email protected]>
://lore.kernel.org/r/202311160629.h4GrebJh-lkp@intel.com/">https://lore.kernel.org/r/[email protected]/
io_uring_show_fdinfo() warn: variable dereferenced before check 'ctx' (see line 57)
io_uring_show_fdinfo() error: we previously assumed 'sq' could be null (see line 141)
2023-07-10 53 __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
2022-05-25 54 {
2023-07-10 55 struct io_ring_ctx *ctx = f->private_data;
2022-05-25 56 struct io_overflow_cqe *ocqe;
2022-05-25 @57 struct io_rings *r = ctx->rings;
^^^^^^^^^^
dereferences so ctx can't be NULL.
2022-05-25 58 unsigned int sq_mask = ctx->sq_entries - 1, cq_mask = ctx->cq_entries - 1;
2022-05-25 59 unsigned int sq_head = READ_ONCE(r->sq.head);
2022-05-25 60 unsigned int sq_tail = READ_ONCE(r->sq.tail);
2022-05-25 61 unsigned int cq_head = READ_ONCE(r->cq.head);
2022-05-25 62 unsigned int cq_tail = READ_ONCE(r->cq.tail);
2022-05-25 63 unsigned int cq_shift = 0;
2022-09-11 64 unsigned int sq_shift = 0;
2022-05-25 65 unsigned int sq_entries, cq_entries;
2023-10-21 66 int sq_pid = -1, sq_cpu = -1;
2023-11-15 67 int sq_busy = 0;
2022-05-25 68 bool has_lock;
2022-05-25 69 unsigned int i;
2022-05-25 70
2022-09-11 71 if (ctx->flags & IORING_SETUP_CQE32)
2022-05-25 72 cq_shift = 1;
2022-09-11 73 if (ctx->flags & IORING_SETUP_SQE128)
2022-09-11 74 sq_shift = 1;
2022-05-25 75
2022-05-25 76 /*
2022-05-25 77 * we may get imprecise sqe and cqe info if uring is actively running
2022-05-25 78 * since we get cached_sq_head and cached_cq_tail without uring_lock
2022-05-25 79 * and sq_tail and cq_head are changed by userspace. But it's ok since
2022-05-25 80 * we usually use these info when it is stuck.
2022-05-25 81 */
2022-05-25 82 seq_printf(m, "SqMask:\t0x%x\n", sq_mask);
2022-05-25 83 seq_printf(m, "SqHead:\t%u\n", sq_head);
2022-05-25 84 seq_printf(m, "SqTail:\t%u\n", sq_tail);
2022-05-25 85 seq_printf(m, "CachedSqHead:\t%u\n", ctx->cached_sq_head);
2022-05-25 86 seq_printf(m, "CqMask:\t0x%x\n", cq_mask);
2022-05-25 87 seq_printf(m, "CqHead:\t%u\n", cq_head);
2022-05-25 88 seq_printf(m, "CqTail:\t%u\n", cq_tail);
2022-05-25 89 seq_printf(m, "CachedCqTail:\t%u\n", ctx->cached_cq_tail);
2022-09-11 90 seq_printf(m, "SQEs:\t%u\n", sq_tail - sq_head);
2022-05-25 91 sq_entries = min(sq_tail - sq_head, ctx->sq_entries);
2022-05-25 92 for (i = 0; i < sq_entries; i++) {
2022-05-25 93 unsigned int entry = i + sq_head;
2022-05-25 94 struct io_uring_sqe *sqe;
2022-09-11 95 unsigned int sq_idx;
2022-05-25 96
2023-09-01 97 if (ctx->flags & IORING_SETUP_NO_SQARRAY)
2023-09-01 98 break;
2022-09-11 99 sq_idx = READ_ONCE(ctx->sq_array[entry & sq_mask]);
2022-05-25 100 if (sq_idx > sq_mask)
2022-05-25 101 continue;
Begunkov 2022-10-11 102 sqe = &ctx->sq_sqes[sq_idx << sq_shift];
2022-09-11 103 seq_printf(m, "%5u: opcode:%s, fd:%d, flags:%x, off:%llu, "
2022-09-11 104 "addr:0x%llx, rw_flags:0x%x, buf_index:%d "
2022-09-11 105 "user_data:%llu",
2022-09-11 106 sq_idx, io_uring_get_opcode(sqe->opcode), sqe->fd,
2022-09-11 107 sqe->flags, (unsigned long long) sqe->off,
2022-09-11 108 (unsigned long long) sqe->addr, sqe->rw_flags,
2022-09-11 109 sqe->buf_index, sqe->user_data);
2022-09-11 110 if (sq_shift) {
2022-09-11 111 u64 *sqeb = (void *) (sqe + 1);
2022-09-11 112 int size = sizeof(struct io_uring_sqe) / sizeof(u64);
2022-09-11 113 int j;
2022-09-11 114
2022-09-11 115 for (j = 0; j < size; j++) {
2022-09-11 116 seq_printf(m, ", e%d:0x%llx", j,
2022-09-11 117 (unsigned long long) *sqeb);
2022-09-11 118 sqeb++;
2022-09-11 119 }
2022-09-11 120 }
2022-09-11 121 seq_printf(m, "\n");
2022-05-25 122 }
2022-05-25 123 seq_printf(m, "CQEs:\t%u\n", cq_tail - cq_head);
2022-05-25 124 cq_entries = min(cq_tail - cq_head, ctx->cq_entries);
2022-05-25 125 for (i = 0; i < cq_entries; i++) {
2022-05-25 126 unsigned int entry = i + cq_head;
2022-05-25 127 struct io_uring_cqe *cqe = &r->cqes[(entry & cq_mask) << cq_shift];
2022-05-25 128
2022-09-11 129 seq_printf(m, "%5u: user_data:%llu, res:%d, flag:%x",
2022-05-25 130 entry & cq_mask, cqe->user_data, cqe->res,
2022-05-25 131 cqe->flags);
2022-09-11 132 if (cq_shift)
2022-09-11 133 seq_printf(m, ", extra1:%llu, extra2:%llu\n",
2022-09-11 134 cqe->big_cqe[0], cqe->big_cqe[1]);
2022-09-11 135 seq_printf(m, "\n");
2022-05-25 136 }
2022-05-25 137
2023-11-15 @138 if (ctx && (ctx->flags & IORING_SETUP_SQPOLL)) {
^^^
2023-11-15 139 struct io_sq_data *sq = ctx->sq_data;
2023-11-15 140
2023-11-15 @141 if (sq && sq->total_time != 0)
^^
2023-11-15 142 sq_busy = (int)(sq->work_time * 100 / sq->total_time);
2023-11-15 143
2023-11-15 @144 sq_pid = sq->task_pid;
^^^^
com/intel/lkp-tests/wiki">https://github.com/intel/lkp-tests/wiki