The running time of the sq thread and the actual IO processing time are counted, and the proportion of time actually used to process IO is output as a percentage. Variable description: "work_time" in the code represents the sum of the jiffies 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. The test results are as follows: Every 0.5s: cat /proc/23112/fdinfo/6 | grep Sq SqMask: 0x3 SqHead: 1168417 SqTail: 1168418 CachedSqHead: 1168418 SqThread: 23112 SqThreadCpu: 55 SqBusy: 97% changes： v5： - list the changes in each iteration. v4： - Resubmit the patch based on removing sq->lock - https://lore.kernel.org/io-uring/20231213032513.12591-1-xiaobing.li@xxxxxxxxxxx/T/#u v3： - output actual working time as a percentage of total time - detailed description of the meaning of each variable - added test results - https://lore.kernel.org/io-uring/50ec567f-6b79-42ea-bf2c-2c9b2ecb427d@suswa.mountain/T/#t v2： - output the total statistical time and work time to fdinfo - https://lore.kernel.org/io-uring/9e2b679c-fc1e-3d83-2303-e053f330a21a@xxxxxxxxx/T/#t v1： - initial version - Statistics of total time and work time - https://lore.kernel.org/io-uring/2a1bdb5a-1216-45b0-a78d-5542b36ccd17@xxxxxxxxx/T/#t Signed-off-by: Xiaobing Li <xiaobing.li@xxxxxxxxxxx> --- io_uring/fdinfo.c | 4 ++++ io_uring/sqpoll.c | 8 ++++++++ io_uring/sqpoll.h | 2 ++ 3 files changed, 14 insertions(+) diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c index 976e9500f651..b0f9d296c5aa 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; @@ -147,10 +148,13 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f) sq_pid = sq->task_pid; sq_cpu = sq->sq_cpu; + if (sq->total_time != 0) + sq_busy = (int)(sq->work_time * 100 / sq->total_time); } 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); 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 65b5dbe3c850..9b74e344c52a 100644 --- a/io_uring/sqpoll.c +++ b/io_uring/sqpoll.c @@ -225,6 +225,7 @@ 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); @@ -241,6 +242,7 @@ static int io_sq_thread(void *data) } mutex_lock(&sqd->lock); + sq_start = jiffies; while (1) { bool cap_entries, sqt_spin = false; @@ -251,6 +253,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); @@ -260,6 +263,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; diff --git a/io_uring/sqpoll.h b/io_uring/sqpoll.h index 8df37e8c9149..92b4b07220fa 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
