[PATCH 0/5] tracing/workqueue updates

[PATCH 0/5] tracing/workqueue updates

[Frederic Weisbecker]

Hi Ingo,

The following patches are fixes and cleanup for the workqueue tracer.

One of them makes the worklet search patch faster.
Some of them fix and sanitize the histogram output and the others clean and
standardize the code.

Thanks.

The following changes since commit c5f0530c4bb2ec77a805cfcf23db09b3e5ab09d4:
  Ingo Molnar (1):
        Merge branch 'tracing/core' into tracing/workqueues

are available in the git repository at:

  git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/workqueue

Anton Blanchard (2):
      tracing/events: use %pf in workqueue trace events
      tracing/events: rename worklet_execute to worklet_entry and worklet_complete to worklet_exit

Zhaolei (3):
      tracing/workqueue: get rid of searching last executed worklet in probe_worklet_complete()
      tracing/workqueue: fix list header and function name format
      tracing/workqueue: cleanup for trace_workqueue.c

 Documentation/trace/workqueue.txt |   12 ++--
 include/trace/events/workqueue.h  |    8 +-
 kernel/trace/trace_workqueue.c    |  124 +++++++++++++++++-------------------
 3 files changed, 69 insertions(+), 75 deletions(-)

[PATCH 1/5] tracing/workqueue: get rid of searching last executed worklet in probe_worklet_complete()

[Frederic Weisbecker]

From: Zhaolei <zhaolei@cn.fujitsu.com>

We don't need to search the worklet which was latest executed
inside the workqueue's worklet list.

Instead, we can use a pointer in cpu_workqueue_stats to remember
which worklet was last executed.

Thanks Oleg for pointing it out.

Changelog:
v1->v2: Oleg pointed out that if searching executed workfunc_stats failed
in probe_worklet_execute(), for example, workfunc_stats's memory allocation
failed previously, cpu_workqueue_stats->last_workfunc is not set to correct
value, and it will cause wrong accessing in probe_worklet_complete().
This problem is fixed in v2.

[ Impact: make worklet tracing faster ]

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
Reported-by: Oleg Nesterov <oleg@redhat.com>
Acked-by: Oleg Nesterov <oleg@redhat.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/trace_workqueue.c |   39 ++++++++++++++++-----------------------
 1 files changed, 16 insertions(+), 23 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index c67be60..740de3b 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -25,13 +25,6 @@ struct workfunc_stats {
 	unsigned int			inserted;
 	unsigned int			executed;
 
-	/*
-	 * save latest work_struct's pointer to use as identifier in
-	 * probe_worklet_complete, because we can't use work_struct->...
-	 * after worklet got executed
-	 */
-	void				*work;
-
 	/* save execution time temporarily for calculate executed time */
 	u64				start_time;
 	u64				max_executed_time;
@@ -46,10 +39,17 @@ struct cpu_workqueue_stats {
 	/* Protected by cpu workqueue lock */
 	unsigned int		inserted;
 	unsigned int		executed;
+
 	/* list of struct workfunc_stats in this workqueue */
 	struct list_head	workfunclist;
 
 	/*
+	 * pointer to last executed worklet's workfunc_stats in this workqueue,
+	 * used by probe_worklet_complete()
+	 */
+	struct workfunc_stats *last_workfunc;
+
+	/*
 	 * the task maybe destroyed when we read stat file
 	 * we define it to void * because we only use it as a identifier
 	 */
@@ -163,9 +163,10 @@ found_wq:
 		if (wfnode->func == work->func) {
 			wfnode->executed++;
 			wfnode->start_time = trace_clock_global();
-			wfnode->work = work;
+			node->last_workfunc = wfnode;
 			goto found_wf;
 		}
+	node->last_workfunc = NULL;
 	pr_debug("trace_workqueue: worklet not found\n");
 	goto end;
 
@@ -180,7 +181,7 @@ probe_worklet_complete(struct task_struct *wq_thread, void *work)
 {
 	int cpu = cpumask_first(&wq_thread->cpus_allowed);
 	struct cpu_workqueue_stats *node;
-	struct workfunc_stats *wfnode;
+	u64 executed_time;
 	unsigned long flags;
 
 	spin_lock_irqsave(&workqueue_cpu_stat(cpu)->lock, flags);
@@ -192,22 +193,14 @@ probe_worklet_complete(struct task_struct *wq_thread, void *work)
 	goto end;
 
 found_wq:
-	list_for_each_entry(wfnode, &node->workfunclist, list) {
-		u64 executed_time;
+	if (!node->last_workfunc)
+		goto end;
 
-		if (wfnode->work != work)
-			continue;
+	executed_time = trace_clock_global() - node->last_workfunc->start_time;
+	node->last_workfunc->total_time += executed_time;
+	if (executed_time > node->last_workfunc->max_executed_time)
+		node->last_workfunc->max_executed_time = executed_time;
 
-		executed_time = trace_clock_global() - wfnode->start_time;
-		wfnode->total_time += executed_time;
-		if (executed_time > wfnode->max_executed_time)
-			wfnode->max_executed_time = executed_time;
-		goto found_wf;
-	}
-	pr_debug("trace_workqueue: worklet not found\n");
-	goto end;
-
-found_wf:
 end:
 	spin_unlock_irqrestore(&workqueue_cpu_stat(cpu)->lock, flags);
 }
-- 
1.6.2.3

[PATCH 2/5] tracing/events: use %pf in workqueue trace events

[Frederic Weisbecker]

From: Anton Blanchard <anton@samba.org>

Using %pf instead of %pF supresses printing of the function offset
which will always be 0.

[ Impact: cleanup workqueue events traces output ]

Signed-off-by: Anton Blanchard <anton@samba.org>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 Documentation/trace/workqueue.txt |    6 +++---
 include/trace/events/workqueue.h  |    8 ++++----
 2 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/Documentation/trace/workqueue.txt b/Documentation/trace/workqueue.txt
index 4019a8a..c446b28 100644
--- a/Documentation/trace/workqueue.txt
+++ b/Documentation/trace/workqueue.txt
@@ -107,8 +107,8 @@ worklet_cancel  worklet_enqueue   worklet_execute          workqueue_destruction
  # TASK-PID    CPU#    TIMESTAMP  FUNCTION
  #   | |       |          |         |
 
-<...>-5627  [000]  4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task+0x0/0x280 cpu=0
-<...>-508   [000]  4597.858660: worklet_execute: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
+<...>-5627  [000]  4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task cpu=0
+<...>-508   [000]  4597.858660: worklet_execute: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task
 <...>-508   [000]  4597.858684: worklet_complete: thread=ata/0:508 work=ffff88007e9e67b8
-<...>-2437  [000]  4597.861259: worklet_cancel: func=ata_pio_task+0x0/0x280
+<...>-2437  [000]  4597.861259: worklet_cancel: func=ata_pio_task
 [...]
diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h
index 49608c7..6cb7833 100644
--- a/include/trace/events/workqueue.h
+++ b/include/trace/events/workqueue.h
@@ -32,7 +32,7 @@ TRACE_EVENT(worklet_enqueue,
 		__entry->cpu		= cpu;
 	),
 
-	TP_printk("thread=%s:%d func=%pF cpu=%d", __entry->thread_comm,
+	TP_printk("thread=%s:%d func=%pf cpu=%d", __entry->thread_comm,
 		__entry->thread_pid, __entry->func, __entry->cpu)
 );
 
@@ -63,7 +63,7 @@ TRACE_EVENT(worklet_enqueue_delayed,
 		__entry->delay		= delay;
 	),
 
-	TP_printk("thread=%s:%d func=%pF cpu=%d delay=%lu",
+	TP_printk("thread=%s:%d func=%pf cpu=%d delay=%lu",
 		__entry->thread_comm, __entry->thread_pid, __entry->func,
 		__entry->cpu, __entry->delay)
 );
@@ -88,7 +88,7 @@ TRACE_EVENT(worklet_execute,
 		__entry->func		= work->func;
 	),
 
-	TP_printk("thread=%s:%d work=%p func=%pF", __entry->thread_comm,
+	TP_printk("thread=%s:%d work=%p func=%pf", __entry->thread_comm,
 		__entry->thread_pid, __entry->work, __entry->func)
 );
 
@@ -128,7 +128,7 @@ TRACE_EVENT(worklet_cancel,
 		__entry->func	= work->func;
 	),
 
-	TP_printk("func=%pF", __entry->func)
+	TP_printk("func=%pf", __entry->func)
 );
 
 /* Trace the creation of one workqueue thread on a cpu */
-- 
1.6.2.3

[PATCH 3/5] tracing/events: rename worklet_execute to worklet_entry and worklet_complete to worklet_exit

[Frederic Weisbecker]

From: Anton Blanchard <anton@samba.org>

Keep a common naming convention for tracing the latency of events such as
softirq_entry/softirq_exit.

[ Impact: standardize workqueue tracepoint names ]

Signed-off-by: Anton Blanchard <anton@samba.org>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 Documentation/trace/workqueue.txt |    8 ++++----
 kernel/trace/trace_workqueue.c    |   20 ++++++++++----------
 2 files changed, 14 insertions(+), 14 deletions(-)

diff --git a/Documentation/trace/workqueue.txt b/Documentation/trace/workqueue.txt
index c446b28..b380a76 100644
--- a/Documentation/trace/workqueue.txt
+++ b/Documentation/trace/workqueue.txt
@@ -98,8 +98,8 @@ For a simple capture of all workqueues events:
 # mount -t debugfs debug /sys/kernel/debug/
 # cd /sys/kernel/debug/tracing/events/workqueue
 # ls
-filter          worklet_complete  worklet_enqueue_delayed  workqueue_creation     workqueue_flush
-worklet_cancel  worklet_enqueue   worklet_execute          workqueue_destruction
+filter          worklet_exit  worklet_enqueue_delayed  workqueue_creation     workqueue_flush
+worklet_cancel  worklet_enqueue   worklet_entry          workqueue_destruction
 # for e in $(ls); do echo 1 > $e/enable; done
 # cat /sys/kernel/debug/tracing/trace
 
@@ -108,7 +108,7 @@ worklet_cancel  worklet_enqueue   worklet_execute          workqueue_destruction
  #   | |       |          |         |
 
 <...>-5627  [000]  4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task cpu=0
-<...>-508   [000]  4597.858660: worklet_execute: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task
-<...>-508   [000]  4597.858684: worklet_complete: thread=ata/0:508 work=ffff88007e9e67b8
+<...>-508   [000]  4597.858660: worklet_entry: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task
+<...>-508   [000]  4597.858684: worklet_exit: thread=ata/0:508 work=ffff88007e9e67b8
 <...>-2437  [000]  4597.861259: worklet_cancel: func=ata_pio_task
 [...]
diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index 740de3b..fa70ea2 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -141,7 +141,7 @@ probe_worklet_enqueue_delayed(struct task_struct *wq_thread,
 
 /* Execution of a work */
 static void
-probe_worklet_execute(struct task_struct *wq_thread, struct work_struct *work)
+probe_worklet_entry(struct task_struct *wq_thread, struct work_struct *work)
 {
 	int cpu = cpumask_first(&wq_thread->cpus_allowed);
 	struct cpu_workqueue_stats *node;
@@ -177,7 +177,7 @@ end:
 
 /* Complete of a work */
 static void
-probe_worklet_complete(struct task_struct *wq_thread, void *work)
+probe_worklet_exit(struct task_struct *wq_thread, void *work)
 {
 	int cpu = cpumask_first(&wq_thread->cpus_allowed);
 	struct cpu_workqueue_stats *node;
@@ -497,17 +497,17 @@ int __init trace_workqueue_early_init(void)
 	if (ret)
 		goto out_worklet_enqueue;
 
-	ret = register_trace_worklet_execute(probe_worklet_execute);
+	ret = register_trace_worklet_entry(probe_worklet_entry);
 	if (ret)
 		goto out_worklet_enqueue_delayed;
 
-	ret = register_trace_worklet_complete(probe_worklet_complete);
+	ret = register_trace_worklet_exit(probe_worklet_exit);
 	if (ret)
-		goto out_worklet_execute;
+		goto out_worklet_entry;
 
 	ret = register_trace_workqueue_creation(probe_workqueue_creation);
 	if (ret)
-		goto out_worklet_complete;
+		goto out_worklet_exit;
 
 	ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
 	if (ret)
@@ -522,10 +522,10 @@ int __init trace_workqueue_early_init(void)
 
 out_workqueue_creation:
 	unregister_trace_workqueue_creation(probe_workqueue_creation);
-out_worklet_complete:
-	unregister_trace_worklet_complete(probe_worklet_complete);
-out_worklet_execute:
-	unregister_trace_worklet_execute(probe_worklet_execute);
+out_worklet_exit:
+	unregister_trace_worklet_exit(probe_worklet_exit);
+out_worklet_entry:
+	unregister_trace_worklet_entry(probe_worklet_entry);
 out_worklet_enqueue_delayed:
 	unregister_trace_worklet_enqueue_delayed(probe_worklet_enqueue_delayed);
 out_worklet_enqueue:
-- 
1.6.2.3

[PATCH 4/5] tracing/workqueue: fix list header and function name format

[Frederic Weisbecker]

From: Zhaolei <zhaolei@cn.fujitsu.com>

Fix list header of workqueue trace,
and use %pf to print the function name only(ignore the offsets).

Before patch:
 # CPU INSERTED EXECUTED    MAX us   AVG us   TASKNAME:PID
 #  |     |        |           |      ` |     -WORKFUNC
 #  |     |        |           |        |          |
     0        1        1     1053     1053   `-flush_async_commits+0x0/0x90
 ...

After patch:
 # CPU INSERTED EXECUTED   MAX us   AVG us   TASKNAME:PID
 #  |     |        |         |        |      `-WORKFUNC
 #  |     |        |         |        |           |
     0        1        1     1155     1155   `-flush_async_commits
 ...

[ Impact: fix and clarify workqueue stats output ]

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/trace_workqueue.c |   14 ++++++++------
 1 files changed, 8 insertions(+), 6 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index fa70ea2..cb6429e 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -402,7 +402,7 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
 			avg_time = 0;
 		}
 
-		seq_printf(s, "  %3d   %6d   %6u   %6llu   %6llu   %c-%pF\n",
+		seq_printf(s, "  %3d   %6d   %6u   %6llu   %6llu   %c-%pf\n",
 			cws->cpu,
 			wfstat->inserted,
 			wfstat->executed,
@@ -450,11 +450,13 @@ static void workqueue_stat_file_open(void)
 		/**/
 static int workqueue_stat_headers(struct seq_file *s)
 {
-	seq_printf(s, "# CPU INSERTED EXECUTED    MAX us   AVG us"
-			"   TASKNAME:PID\n");
-	seq_printf(s, "#  |     |        |           |      ` |"
-			"     -WORKFUNC\n");
-	seq_printf(s, "#  |     |        |           |        |          |\n");
+	seq_printf(s,
+		"# CPU INSERTED EXECUTED   MAX us   AVG us   TASKNAME:PID\n");
+	seq_printf(s,
+		"#  |     |        |         |        |      `-WORKFUNC\n");
+	seq_printf(s,
+		"#  |     |        |         |        |           |\n");
+
 	return 0;
 }
 
-- 
1.6.2.3

[PATCH 5/5] tracing/workqueue: cleanup for trace_workqueue.c

[Frederic Weisbecker]

From: Zhaolei <zhaolei@cn.fujitsu.com>

1: Make function's order in source same with definition in struct tracer_stat
2: Remove ";" after workqueue_stat_file_release()
3: Remove redundant blank in struct tracer_stat workqueue_stats
4: add "static" prefix for some function and struct

[ Impact: reorganize code, cleanup ]

Signed-off-by: Zhao Lei <zhaolei@cn.fujitsu.com>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
 kernel/trace/trace_workqueue.c |   65 +++++++++++++++++++--------------------
 1 files changed, 32 insertions(+), 33 deletions(-)

diff --git a/kernel/trace/trace_workqueue.c b/kernel/trace/trace_workqueue.c
index cb6429e..ae98be4 100644
--- a/kernel/trace/trace_workqueue.c
+++ b/kernel/trace/trace_workqueue.c
@@ -81,7 +81,7 @@ static int wq_file_ref;
  * Update record when insert a work into workqueue
  * Caller need to hold cpu_workqueue_stats spin_lock
  */
-int do_worklet_enqueue(struct cpu_workqueue_stats *cws,
+static int do_worklet_enqueue(struct cpu_workqueue_stats *cws,
 			 struct work_struct *work)
 {
 	struct workfunc_stats *wfstat;
@@ -415,6 +415,27 @@ static int workqueue_stat_show(struct seq_file *s, void *p)
 	return 0;
 }
 
+static int workqueue_stat_headers(struct seq_file *s)
+{
+	seq_printf(s,
+		"# CPU INSERTED EXECUTED   MAX us   AVG us   TASKNAME:PID\n");
+	seq_printf(s,
+		"#  |     |        |         |        |      `-WORKFUNC\n");
+	seq_printf(s,
+		"#  |     |        |         |        |           |\n");
+
+	return 0;
+}
+
+static void workqueue_stat_file_open(void)
+{
+	unsigned long flags;
+
+	spin_lock_irqsave(&free_wq_lock, flags);
+	wq_file_ref++;
+	spin_unlock_irqrestore(&free_wq_lock, flags);
+}
+
 /*
  * Here we are sure that we have no more readers on our stat file
  * and that further readers will block until we return from this function.
@@ -436,42 +457,20 @@ static void workqueue_stat_file_release(void)
 	}
 
 	spin_unlock_irqrestore(&free_wq_lock, flags);
-};
-
-static void workqueue_stat_file_open(void)
-{
-	unsigned long flags;
-
-	spin_lock_irqsave(&free_wq_lock, flags);
-	wq_file_ref++;
-	spin_unlock_irqrestore(&free_wq_lock, flags);
-}
-
-		/**/
-static int workqueue_stat_headers(struct seq_file *s)
-{
-	seq_printf(s,
-		"# CPU INSERTED EXECUTED   MAX us   AVG us   TASKNAME:PID\n");
-	seq_printf(s,
-		"#  |     |        |         |        |      `-WORKFUNC\n");
-	seq_printf(s,
-		"#  |     |        |         |        |           |\n");
-
-	return 0;
 }
 
-struct tracer_stat workqueue_stats __read_mostly = {
-	.name		 = "workqueues",
-	.stat_start	 = workqueue_stat_start,
-	.stat_next	 = workqueue_stat_next,
-	.stat_show	 = workqueue_stat_show,
-	.stat_headers	 = workqueue_stat_headers,
-	.file_open	 = workqueue_stat_file_open,
-	.file_open	 = workqueue_stat_file_release,
+static struct tracer_stat workqueue_stats __read_mostly = {
+	.name		= "workqueues",
+	.stat_start	= workqueue_stat_start,
+	.stat_next	= workqueue_stat_next,
+	.stat_show	= workqueue_stat_show,
+	.stat_headers	= workqueue_stat_headers,
+	.file_open	= workqueue_stat_file_open,
+	.file_open	= workqueue_stat_file_release,
 };
 
 
-int __init stat_workqueue_init(void)
+static int __init stat_workqueue_init(void)
 {
 	if (register_stat_tracer(&workqueue_stats)) {
 		pr_warning("Unable to register workqueue stat tracer\n");
@@ -486,7 +485,7 @@ fs_initcall(stat_workqueue_init);
  * Workqueues are created very early, just after pre-smp initcalls.
  * So we must register our tracepoints at this stage.
  */
-int __init trace_workqueue_early_init(void)
+static int __init trace_workqueue_early_init(void)
 {
 	int ret, cpu;
 
-- 
1.6.2.3

Re: [PATCH 0/5] tracing/workqueue updates

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> Hi Ingo,
> 
> The following patches are fixes and cleanup for the workqueue tracer.
> 
> One of them makes the worklet search patch faster.
> Some of them fix and sanitize the histogram output and the others clean and
> standardize the code.
> 
> Thanks.
> 
> The following changes since commit c5f0530c4bb2ec77a805cfcf23db09b3e5ab09d4:
>   Ingo Molnar (1):
>         Merge branch 'tracing/core' into tracing/workqueues
> 
> are available in the git repository at:
> 
>   git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/workqueue
> 
> Anton Blanchard (2):
>       tracing/events: use %pf in workqueue trace events
>       tracing/events: rename worklet_execute to worklet_entry and worklet_complete to worklet_exit
> 
> Zhaolei (3):
>       tracing/workqueue: get rid of searching last executed worklet in probe_worklet_complete()
>       tracing/workqueue: fix list header and function name format
>       tracing/workqueue: cleanup for trace_workqueue.c
> 
>  Documentation/trace/workqueue.txt |   12 ++--
>  include/trace/events/workqueue.h  |    8 +-
>  kernel/trace/trace_workqueue.c    |  124 +++++++++++++++++-------------------
>  3 files changed, 69 insertions(+), 75 deletions(-)

Pulled, thanks Frederic!

	Ingo