[RFC] workqueue: Make show_pwq() use run-length encoding
Commit Message
The show_pwq() function dumps out a pool_workqueue structure's activity,
including the pending work-queue handlers:
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
pwq 0: cpus=0 node=0 flags=0x1 nice=0 active=10/256 refcnt=11
in-flight: 7:test_work_func, 64:test_work_func, 249:test_work_func
pending: test_work_func, test_work_func, test_work_func1, test_work_func1, test_work_func1, test_work_func1, test_work_func1
When large systems are facing certain types of hang conditions, it is not
unusual for this "pending" list to contain runs of hundreds of identical
function names. This "wall of text" is difficult to read, and worse yet,
it can be interleaved with other output such as stack traces.
Therefore, make show_pwq() use run-length encoding so that the above
printout instead looks like this:
Showing busy workqueues and worker pools:
workqueue events: flags=0x0
pwq 0: cpus=0 node=0 flags=0x1 nice=0 active=10/256 refcnt=11
in-flight: 7:test_work_func, 64:test_work_func, 249:test_work_func
pending: 2*test_work_func, 5*test_work_func1
When no comma would be printed, including the WORK_STRUCT_LINKED case,
a new run is started unconditionally.
This output is more readable, places less stress on the hardware,
firmware, and software on the console-log path, and reduces interference
with other output.
Signed-off-by: Paul E. McKenney <paulmck@kernel.org>
Cc: Tejun Heo <tj@kernel.org>
Cc: Lai Jiangshan <jiangshanlai@gmail.com>
Cc: Dave Jones <davej@codemonkey.org.uk>
Cc: Rik van Riel <riel@surriel.com>
Comments
On Fri, Jan 06, 2023 at 04:10:24PM -0800, Paul E. McKenney wrote:
> The show_pwq() function dumps out a pool_workqueue structure's activity,
> including the pending work-queue handlers:
>
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
> pwq 0: cpus=0 node=0 flags=0x1 nice=0 active=10/256 refcnt=11
> in-flight: 7:test_work_func, 64:test_work_func, 249:test_work_func
> pending: test_work_func, test_work_func, test_work_func1, test_work_func1, test_work_func1, test_work_func1, test_work_func1
>
> When large systems are facing certain types of hang conditions, it is not
> unusual for this "pending" list to contain runs of hundreds of identical
> function names. This "wall of text" is difficult to read, and worse yet,
> it can be interleaved with other output such as stack traces.
>
> Therefore, make show_pwq() use run-length encoding so that the above
> printout instead looks like this:
>
> Showing busy workqueues and worker pools:
> workqueue events: flags=0x0
> pwq 0: cpus=0 node=0 flags=0x1 nice=0 active=10/256 refcnt=11
> in-flight: 7:test_work_func, 64:test_work_func, 249:test_work_func
> pending: 2*test_work_func, 5*test_work_func1
>
> When no comma would be printed, including the WORK_STRUCT_LINKED case,
> a new run is started unconditionally.
>
> This output is more readable, places less stress on the hardware,
> firmware, and software on the console-log path, and reduces interference
> with other output.
This is fantastic. Applied to wq/for-6.3.
Thanks.
@@ -4709,22 +4709,53 @@ static void pr_cont_pool_info(struct worker_pool *pool)
pr_cont(" flags=0x%x nice=%d", pool->flags, pool->attrs->nice);
}
-static void pr_cont_work(bool comma, struct work_struct *work)
+struct pr_cont_work_struct {
+ bool comma;
+ work_func_t func;
+ long ctr;
+};
+
+static void pr_cont_work_flush(bool comma, work_func_t func, struct pr_cont_work_struct *pcwsp)
+{
+ if (!pcwsp->ctr)
+ goto out_record;
+ if (func == pcwsp->func) {
+ pcwsp->ctr++;
+ return;
+ }
+ if (pcwsp->ctr == 1)
+ pr_cont("%s %ps", pcwsp->comma ? "," : "", pcwsp->func);
+ else
+ pr_cont("%s %ld*%ps", pcwsp->comma ? "," : "", pcwsp->ctr, pcwsp->func);
+ pcwsp->ctr = 0;
+out_record:
+ if ((long)func == -1L)
+ return;
+ pcwsp->comma = comma;
+ pcwsp->func = func;
+ pcwsp->ctr = 1;
+}
+
+static void pr_cont_work(bool comma, struct work_struct *work, struct pr_cont_work_struct *pcwsp)
{
if (work->func == wq_barrier_func) {
struct wq_barrier *barr;
barr = container_of(work, struct wq_barrier, work);
+ pr_cont_work_flush(comma, (work_func_t)-1, pcwsp);
pr_cont("%s BAR(%d)", comma ? "," : "",
task_pid_nr(barr->task));
} else {
- pr_cont("%s %ps", comma ? "," : "", work->func);
+ if (!comma)
+ pr_cont_work_flush(comma, (work_func_t)-1, pcwsp);
+ pr_cont_work_flush(comma, work->func, pcwsp);
}
}
static void show_pwq(struct pool_workqueue *pwq)
{
+ struct pr_cont_work_struct pcws = { .ctr = 0, };
struct worker_pool *pool = pwq->pool;
struct work_struct *work;
struct worker *worker;
@@ -4757,7 +4788,8 @@ static void show_pwq(struct pool_workqueue *pwq)
worker->rescue_wq ? "(RESCUER)" : "",
worker->current_func);
list_for_each_entry(work, &worker->scheduled, entry)
- pr_cont_work(false, work);
+ pr_cont_work(false, work, &pcws);
+ pr_cont_work_flush(comma, (work_func_t)-1L, &pcws);
comma = true;
}
pr_cont("\n");
@@ -4777,9 +4809,10 @@ static void show_pwq(struct pool_workqueue *pwq)
if (get_work_pwq(work) != pwq)
continue;
- pr_cont_work(comma, work);
+ pr_cont_work(comma, work, &pcws);
comma = !(*work_data_bits(work) & WORK_STRUCT_LINKED);
}
+ pr_cont_work_flush(comma, (work_func_t)-1L, &pcws);
pr_cont("\n");
}
@@ -4788,9 +4821,10 @@ static void show_pwq(struct pool_workqueue *pwq)
pr_info(" inactive:");
list_for_each_entry(work, &pwq->inactive_works, entry) {
- pr_cont_work(comma, work);
+ pr_cont_work(comma, work, &pcws);
comma = !(*work_data_bits(work) & WORK_STRUCT_LINKED);
}
+ pr_cont_work_flush(comma, (work_func_t)-1L, &pcws);
pr_cont("\n");
}
}