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

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

[Xiaobing Li]

Count the running time and actual IO processing time of the sqpoll
thread, and output the statistical data to fdinfo.

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 test tool is fio, and its parameters are as follows:
[global]
ioengine=io_uring
direct=1
group_reporting
bs=128k
norandommap=1
randrepeat=0
refill_buffers
ramp_time=30s
time_based
runtime=1m
clocksource=clock_gettime
overwrite=1
log_avg_msec=1000
numjobs=1

[disk0]
filename=/dev/nvme0n1
rw=read
iodepth=16
hipri
sqthread_poll=1

---
The test results are as follows:
Every 2.0s: cat /proc/9230/fdinfo/6 | grep -E Sq
SqMask: 0x3
SqHead: 3197153
SqTail: 3197153
CachedSqHead:   3197153
SqThread:       9231
SqThreadCpu:    11
SqTotalTime:    18099614
SqWorkTime:     16748316

---
The test results corresponding to different iodepths are as follows:
|-----------|-------|-------|-------|------|-------|
|   iodepth |   1   |   4   |   8   |  16  |  64   |
|-----------|-------|-------|-------|------|-------|
|utilization| 2.9%  | 8.8%  | 10.9% | 92.9%| 84.4% |
|-----------|-------|-------|-------|------|-------|
|    idle   | 97.1% | 91.2% | 89.1% | 7.1% | 15.6% |
|-----------|-------|-------|-------|------|-------|

changes：
v8:
 - Get the work time of the sqpoll thread through getrusage

v7:
 - Get the total time of the sqpoll thread through getrusage
 - The working time of the sqpoll thread is obtained through ktime_get()

v6:
 - Replace the percentages in the fdinfo output with the actual running
time and the time actually processing IO

v5：
 - list the changes in each iteration.

v4：
 - Resubmit the patch based on removing sq->lock

v3：
 - output actual working time as a percentage of total time
 - detailed description of the meaning of each variable
 - added test results

v2：
 - output the total statistical time and work time to fdinfo

v1：
 - initial version
 - Statistics of total time and work time

Signed-off-by: Xiaobing Li <xiaobing.li@samsung.com>
---
 io_uring/fdinfo.c | 8 ++++++++
 io_uring/sqpoll.c | 8 ++++++++
 io_uring/sqpoll.h | 1 +
 3 files changed, 17 insertions(+)

diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c
index 976e9500f651..18c6f4aa4a48 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;
+	u64 sq_total_time = 0, sq_work_time = 0;
 	bool has_lock;
 	unsigned int i;
 
@@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
 
 		sq_pid = sq->task_pid;
 		sq_cpu = sq->sq_cpu;
+		struct rusage r;
+
+		getrusage(sq->thread, RUSAGE_SELF, &r);
+		sq_total_time = r.ru_stime.tv_sec * 1000000 + r.ru_stime.tv_usec;
+		sq_work_time = sq->work_time;
 	}
 
 	seq_printf(m, "SqThread:\t%d\n", sq_pid);
 	seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
+	seq_printf(m, "SqTotalTime:\t%llu\n", sq_total_time);
+	seq_printf(m, "SqWorkTime:\t%llu\n", sq_work_time);
 	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..9155fc0b5eee 100644
--- a/io_uring/sqpoll.c
+++ b/io_uring/sqpoll.c
@@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
 		}
 
 		cap_entries = !list_is_singular(&sqd->ctx_list);
+		struct rusage start, end;
+
+		getrusage(current, RUSAGE_SELF, &start);
 		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;
 
+		getrusage(current, RUSAGE_SELF, &end);
+		if (sqt_spin == true)
+			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
+					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
+
 		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..e99f5423a3c3 100644
--- a/io_uring/sqpoll.h
+++ b/io_uring/sqpoll.h
@@ -16,6 +16,7 @@ struct io_sq_data {
 	pid_t			task_pid;
 	pid_t			task_tgid;
 
+	u64					work_time;
 	unsigned long		state;
 	struct completion	exited;
 };
-- 
2.34.1

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

[Xiaobing Li]

On 2/6/24 10:39 AM, Xiaobing Li wrote:
> io_uring/fdinfo.c | 8 ++++++++
> io_uring/sqpoll.c | 8 ++++++++
> io_uring/sqpoll.h | 1 +
> 3 files changed, 17 insertions(+)
>
>diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c
>index 976e9500f651..18c6f4aa4a48 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;
>+	u64 sq_total_time = 0, sq_work_time = 0;
> 	bool has_lock;
> 	unsigned int i;
> 
>@@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
> 
> 		sq_pid = sq->task_pid;
> 		sq_cpu = sq->sq_cpu;
>+		struct rusage r;
>+
>+		getrusage(sq->thread, RUSAGE_SELF, &r);
>+		sq_total_time = r.ru_stime.tv_sec * 1000000 + r.ru_stime.tv_usec;
>+		sq_work_time = sq->work_time;
> 	}
> 
> 	seq_printf(m, "SqThread:\t%d\n", sq_pid);
> 	seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
>+	seq_printf(m, "SqTotalTime:\t%llu\n", sq_total_time);
>+	seq_printf(m, "SqWorkTime:\t%llu\n", sq_work_time);
> 	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..9155fc0b5eee 100644
>--- a/io_uring/sqpoll.c
>+++ b/io_uring/sqpoll.c
>@@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
> 		}
> 
> 		cap_entries = !list_is_singular(&sqd->ctx_list);
>+		struct rusage start, end;
>+
>+		getrusage(current, RUSAGE_SELF, &start);
> 		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;
> 
>+		getrusage(current, RUSAGE_SELF, &end);
>+		if (sqt_spin == true)
>+			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
>+					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
>+
> 		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..e99f5423a3c3 100644
>--- a/io_uring/sqpoll.h
>+++ b/io_uring/sqpoll.h
>@@ -16,6 +16,7 @@ struct io_sq_data {
> 	pid_t			task_pid;
> 	pid_t			task_tgid;
> 
>+	u64					work_time;
> 	unsigned long		state;
> 	struct completion	exited;
> };
 
Hi, Jens and Pavel
This patch has been modified according to your previous opinions.
Do you have any other comments?

--
Xiaobing Li

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

[Jens Axboe]

On 2/17/24 10:55 PM, Xiaobing Li wrote:
> On 2/6/24 10:39 AM, Xiaobing Li wrote:
>> io_uring/fdinfo.c | 8 ++++++++
>> io_uring/sqpoll.c | 8 ++++++++
>> io_uring/sqpoll.h | 1 +
>> 3 files changed, 17 insertions(+)
>>
>> diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c
>> index 976e9500f651..18c6f4aa4a48 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;
>> +	u64 sq_total_time = 0, sq_work_time = 0;
>> 	bool has_lock;
>> 	unsigned int i;
>>
>> @@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
>>
>> 		sq_pid = sq->task_pid;
>> 		sq_cpu = sq->sq_cpu;
>> +		struct rusage r;
>> +
>> +		getrusage(sq->thread, RUSAGE_SELF, &r);
>> +		sq_total_time = r.ru_stime.tv_sec * 1000000 + r.ru_stime.tv_usec;
>> +		sq_work_time = sq->work_time;
>> 	}
>>
>> 	seq_printf(m, "SqThread:\t%d\n", sq_pid);
>> 	seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
>> +	seq_printf(m, "SqTotalTime:\t%llu\n", sq_total_time);
>> +	seq_printf(m, "SqWorkTime:\t%llu\n", sq_work_time);
>> 	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..9155fc0b5eee 100644
>> --- a/io_uring/sqpoll.c
>> +++ b/io_uring/sqpoll.c
>> @@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
>> 		}
>>
>> 		cap_entries = !list_is_singular(&sqd->ctx_list);
>> +		struct rusage start, end;
>> +
>> +		getrusage(current, RUSAGE_SELF, &start);
>> 		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;
>>
>> +		getrusage(current, RUSAGE_SELF, &end);
>> +		if (sqt_spin == true)
>> +			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
>> +					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
>> +
>> 		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..e99f5423a3c3 100644
>> --- a/io_uring/sqpoll.h
>> +++ b/io_uring/sqpoll.h
>> @@ -16,6 +16,7 @@ struct io_sq_data {
>> 	pid_t			task_pid;
>> 	pid_t			task_tgid;
>>
>> +	u64					work_time;
>> 	unsigned long		state;
>> 	struct completion	exited;
>> };
>  
> Hi, Jens and Pavel
> This patch has been modified according to your previous opinions.
> Do you have any other comments?

I don't have any further complaints on the patch, I think it looks
pretty straight forward now. I'll get it applied, thanks.

-- 
Jens Axboe

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

[Jens Axboe]

On 2/18/24 5:45 AM, Jens Axboe wrote:
> On 2/17/24 10:55 PM, Xiaobing Li wrote:
>> On 2/6/24 10:39 AM, Xiaobing Li wrote:
>>> io_uring/fdinfo.c | 8 ++++++++
>>> io_uring/sqpoll.c | 8 ++++++++
>>> io_uring/sqpoll.h | 1 +
>>> 3 files changed, 17 insertions(+)
>>>
>>> diff --git a/io_uring/fdinfo.c b/io_uring/fdinfo.c
>>> index 976e9500f651..18c6f4aa4a48 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;
>>> +	u64 sq_total_time = 0, sq_work_time = 0;
>>> 	bool has_lock;
>>> 	unsigned int i;
>>>
>>> @@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
>>>
>>> 		sq_pid = sq->task_pid;
>>> 		sq_cpu = sq->sq_cpu;
>>> +		struct rusage r;
>>> +
>>> +		getrusage(sq->thread, RUSAGE_SELF, &r);
>>> +		sq_total_time = r.ru_stime.tv_sec * 1000000 + r.ru_stime.tv_usec;
>>> +		sq_work_time = sq->work_time;
>>> 	}
>>>
>>> 	seq_printf(m, "SqThread:\t%d\n", sq_pid);
>>> 	seq_printf(m, "SqThreadCpu:\t%d\n", sq_cpu);
>>> +	seq_printf(m, "SqTotalTime:\t%llu\n", sq_total_time);
>>> +	seq_printf(m, "SqWorkTime:\t%llu\n", sq_work_time);
>>> 	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..9155fc0b5eee 100644
>>> --- a/io_uring/sqpoll.c
>>> +++ b/io_uring/sqpoll.c
>>> @@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
>>> 		}
>>>
>>> 		cap_entries = !list_is_singular(&sqd->ctx_list);
>>> +		struct rusage start, end;
>>> +
>>> +		getrusage(current, RUSAGE_SELF, &start);
>>> 		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;
>>>
>>> +		getrusage(current, RUSAGE_SELF, &end);
>>> +		if (sqt_spin == true)
>>> +			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
>>> +					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
>>> +
>>> 		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..e99f5423a3c3 100644
>>> --- a/io_uring/sqpoll.h
>>> +++ b/io_uring/sqpoll.h
>>> @@ -16,6 +16,7 @@ struct io_sq_data {
>>> 	pid_t			task_pid;
>>> 	pid_t			task_tgid;
>>>
>>> +	u64					work_time;
>>> 	unsigned long		state;
>>> 	struct completion	exited;
>>> };
>>  
>> Hi, Jens and Pavel
>> This patch has been modified according to your previous opinions.
>> Do you have any other comments?
> 
> I don't have any further complaints on the patch, I think it looks
> pretty straight forward now. I'll get it applied, thanks.

I take that back, I'll reply to the patch...

-- 
Jens Axboe

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

[Jens Axboe]

On 2/5/24 7:39 PM, Xiaobing Li wrote:
> Count the running time and actual IO processing time of the sqpoll
> thread, and output the statistical data to fdinfo.
> 
> 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 test tool is fio, and its parameters are as follows:
> [global]
> ioengine=io_uring
> direct=1
> group_reporting
> bs=128k
> norandommap=1
> randrepeat=0
> refill_buffers
> ramp_time=30s
> time_based
> runtime=1m
> clocksource=clock_gettime
> overwrite=1
> log_avg_msec=1000
> numjobs=1
> 
> [disk0]
> filename=/dev/nvme0n1
> rw=read
> iodepth=16
> hipri
> sqthread_poll=1
> 
> ---

If you put --- in here, then the rest of the commit message disappears.
The way you format commit messages it to put things you don't want in
the git log below it... This one should not be here.

> 
> ---
> The test results corresponding to different iodepths are as follows:

Same with this one...

> |-----------|-------|-------|-------|------|-------|
> |   iodepth |   1   |   4   |   8   |  16  |  64   |
> |-----------|-------|-------|-------|------|-------|
> |utilization| 2.9%  | 8.8%  | 10.9% | 92.9%| 84.4% |
> |-----------|-------|-------|-------|------|-------|
> |    idle   | 97.1% | 91.2% | 89.1% | 7.1% | 15.6% |
> |-----------|-------|-------|-------|------|-------|
> 
> changes?
> v8:

Here you need it, the changelog should be below the one and only --- you
put in the commit message.

>  - Get the work time of the sqpoll thread through getrusage
> 
> v7:
>  - Get the total time of the sqpoll thread through getrusage
>  - The working time of the sqpoll thread is obtained through ktime_get()
> 
> v6:
>  - Replace the percentages in the fdinfo output with the actual running
> time and the time actually processing IO
> 
> v5?
>  - list the changes in each iteration.
> 
> v4?
>  - Resubmit the patch based on removing sq->lock
> 
> v3?
>  - output actual working time as a percentage of total time
>  - detailed description of the meaning of each variable
>  - added test results
> 
> v2?
>  - output the total statistical time and work time to fdinfo
> 
> v1?
>  - initial version
>  - Statistics of total time and work time
> 
> Signed-off-by: Xiaobing Li <xiaobing.li@samsung.com>

And since your Signed-off-by is here, it also does not go into the
commit message, which it must.

> index 976e9500f651..18c6f4aa4a48 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;
> +	u64 sq_total_time = 0, sq_work_time = 0;
>  	bool has_lock;
>  	unsigned int i;
>  
> @@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
>  
>  		sq_pid = sq->task_pid;
>  		sq_cpu = sq->sq_cpu;
> +		struct rusage r;

Here, and in one other spot, you're mixing variable declarations and
code. Don't do that, they need to be top of that scope and before any
code.

> diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
> index 65b5dbe3c850..9155fc0b5eee 100644
> --- a/io_uring/sqpoll.c
> +++ b/io_uring/sqpoll.c
> @@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
>  		}
>  
>  		cap_entries = !list_is_singular(&sqd->ctx_list);
> +		struct rusage start, end;
> +
> +		getrusage(current, RUSAGE_SELF, &start);

Ditto, move the variables to the top of the scope.

>  		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;
>  
> +		getrusage(current, RUSAGE_SELF, &end);
> +		if (sqt_spin == true)
> +			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
> +					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
> +

and this should go in a helper instead. It's trivial code, but the way
too long lines makes it hard to read. Compare the above to eg:

static void io_sq_update_worktime(struct io_sq_data *sqd, struct rusage *start)
{
       struct rusage end;

       getrusage(current, RUSAGE_SELF, &end);
       end.ru_stime.tv_sec -= start->ru_stime.tv_sec;
       end_ru_stime.tv_usec -= start->ru_stime.tv_usec;

       sqd->work_time += end.ru_stime.tv_usec + end.ru_stime.tv_sec * 1000000;
}

which is so much nicer to look at.

We're already doing an sqt_spin == true check right below, here:

>  		if (sqt_spin || !time_after(jiffies, timeout)) {
>  			if (sqt_spin)
>  				timeout = jiffies + sqd->sq_thread_idle;

why not just put io_sq_update_worktime(sqd, &start); inside this check?

> diff --git a/io_uring/sqpoll.h b/io_uring/sqpoll.h
> index 8df37e8c9149..e99f5423a3c3 100644
> --- a/io_uring/sqpoll.h
> +++ b/io_uring/sqpoll.h
> @@ -16,6 +16,7 @@ struct io_sq_data {
>  	pid_t			task_pid;
>  	pid_t			task_tgid;
>  
> +	u64					work_time;
>  	unsigned long		state;
>  	struct completion	exited;
>  };

Not sure why this addition is indented differently than everything else
in there?

-- 
Jens Axboe

Re: Re: [PATCH] liburing: add script for statistics sqpoll running time.

[Xiaobing Li]

On 2/18/24 06:00 AM, Jens Axboe wrote:
>And since your Signed-off-by is here, it also does not go into the
>commit message, which it must.
>
>> index 976e9500f651..18c6f4aa4a48 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;
>> +	u64 sq_total_time = 0, sq_work_time = 0;
>>  	bool has_lock;
>>  	unsigned int i;
>>  
>> @@ -147,10 +148,17 @@ __cold void io_uring_show_fdinfo(struct seq_file *m, struct file *f)
>>  
>>  		sq_pid = sq->task_pid;
>>  		sq_cpu = sq->sq_cpu;
>> +		struct rusage r;
>
>Here, and in one other spot, you're mixing variable declarations and
>code. Don't do that, they need to be top of that scope and before any
>code.
>
>> diff --git a/io_uring/sqpoll.c b/io_uring/sqpoll.c
>> index 65b5dbe3c850..9155fc0b5eee 100644
>> --- a/io_uring/sqpoll.c
>> +++ b/io_uring/sqpoll.c
>> @@ -251,6 +251,9 @@ static int io_sq_thread(void *data)
>>  		}
>>  
>>  		cap_entries = !list_is_singular(&sqd->ctx_list);
>> +		struct rusage start, end;
>> +
>> +		getrusage(current, RUSAGE_SELF, &start);
>
>Ditto, move the variables to the top of the scope.
>
>>  		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;
>>  
>> +		getrusage(current, RUSAGE_SELF, &end);
>> +		if (sqt_spin == true)
>> +			sqd->work_time += (end.ru_stime.tv_sec - start.ru_stime.tv_sec) *
>> +					1000000 + (end.ru_stime.tv_usec - start.ru_stime.tv_usec);
>> +
>
>and this should go in a helper instead. It's trivial code, but the way
>too long lines makes it hard to read. Compare the above to eg:
>
>static void io_sq_update_worktime(struct io_sq_data *sqd, struct rusage *start)
>{
>       struct rusage end;
>
>       getrusage(current, RUSAGE_SELF, &end);
>       end.ru_stime.tv_sec -= start->ru_stime.tv_sec;
>       end_ru_stime.tv_usec -= start->ru_stime.tv_usec;
>
>       sqd->work_time += end.ru_stime.tv_usec + end.ru_stime.tv_sec * 1000000;
>}
>
>which is so much nicer to look at.
>
>We're already doing an sqt_spin == true check right below, here:
>
>>  		if (sqt_spin || !time_after(jiffies, timeout)) {
>>  			if (sqt_spin)
>>  				timeout = jiffies + sqd->sq_thread_idle;
>
>why not just put io_sq_update_worktime(sqd, &start); inside this check?
>
 
ok, I got it, I will send out a v9.

--
Xiaobing Li