Skip to contentSkip to conversation

workqueue: Add basic tracepoints to track workqueue execution

PATCH In review Arjan van de Ven 4 participants 7 messages Aug 21, 2010 – Aug 27, 2010

Subsystems (3)
Documentation Tracing Workqueue
lore
Share & tools
lore

Arjan van de Ven

author
#0 lore raw

PATCH 1/1 workqueue: Add basic tracepoints to track workqueue execution

From: Arjan van de Ven <[email protected]>
Date: Sat, 21 Aug 2010 13:07:26 -0700
Subject: [PATCH] workqueue: Add basic tracepoints to track workqueue execution

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

With this pair of tracepoints, the next PowerTOP can correctly report which work item caused the wakeup (and how long it took):

Interrupt (43)            i915      time   3.51ms    wakeups 141
Work      ieee80211_iface_work      time   0.81ms    wakeups  29
Work              do_dbs_timer      time   0.55ms    wakeups  24
Process                   Xorg      time  21.36ms    wakeups   4
Timer    sched_rt_period_timer      time   0.01ms    wakeups   1
Signed-off-by Arjan van de Ven <[email protected]>
---
 include/trace/events/workqueue.h |   63 ++++++++++++++++++++++++++++++++++++++
 kernel/workqueue.c               |    9 +++++
 2 files changed, 72 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/events/workqueue.h
include/trace/events/workqueue.h new file +63 -0
new file mode 100644
index 0000000..4fd2bd1
@@ -0,0 +1,63 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM workqueue
+
+#if !defined(_TRACE_WORKQUEUE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_WORKQUEUE_H
+
+#include <linux/tracepoint.h>
+#include <linux/workqueue.h>
+
+/**
+ * workqueue_execute_start - called immediately before the workqueue callback
+ * @work:	pointer to struct work_struct
+ *
+ * Allows to track workqueue execution.
+ */
+TRACE_EVENT(workqueue_execute_start,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+	),
+
+	TP_printk("work struct %p: function %pf", __entry->work, __entry->function)
+);
+
+/**
+ * workqueue_execute_end - called immediately before the workqueue callback
+ * @work:	pointer to struct work_struct
+ *
+ * Allows to track workqueue execution.
+ */
+TRACE_EVENT(workqueue_execute_end,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+	),
+
+	TP_printk("work struct %p", __entry->work)
+);
+
+
+#endif /*  _TRACE_WORKQUEUE_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
+
kernel/workqueue.c +9 -0
index 2994a0e..8bd600c 100644
@@ -35,6 +35,9 @@
 #include <linux/lockdep.h>
 #include <linux/idr.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/workqueue.h>
+
 #include "workqueue_sched.h"
 
 enum {

@@ -1790,7 +1793,13 @@ static void process_one_work(struct worker *worker, struct work_struct *work)
 	work_clear_pending(work);
 	lock_map_acquire(&cwq->wq->lockdep_map);
 	lock_map_acquire(&lockdep_map);
+	trace_workqueue_execute_start(work);
 	f(work);
+	/*
+	 * While we must be careful to not use "work" after this, the trace
+	 * point will only record its address.
+	 */
+	trace_workqueue_execute_end(work);
 	lock_map_release(&lockdep_map);
 	lock_map_release(&cwq->wq->lockdep_map);
Signature · 8 lines
1.7.1.1



-- 
Arjan van de Ven 	Intel Open Source Technology Centre
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org
Acked-by on v1 1/1
#1 lore raw
Quoted 16 lines · Arjan van de Ven

From: Arjan van de Ven <[email protected]>
Date: Sat, 21 Aug 2010 13:07:26 -0700
Subject: [PATCH] workqueue: Add basic tracepoints to track workqueue execution

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

With this pair of tracepoints, the next PowerTOP can correctly report which work item caused the wakeup (and how long it took):

Quoted 7 lines
Interrupt (43)            i915      time   3.51ms    wakeups 141
Work      ieee80211_iface_work      time   0.81ms    wakeups  29
Work              do_dbs_timer      time   0.55ms    wakeups  24
Process                   Xorg      time  21.36ms    wakeups   4
Timer    sched_rt_period_timer      time   0.01ms    wakeups   1
Signed-off-by Arjan van de Ven <[email protected]>
Acked-by Frederic Weisbecker <[email protected]>

If that broke a userspace tool, should that perhaps go to .36 ? I know it's a big patch, but in fact it's more a semi-revert of the workqueue tracepoints removal.

It's my bad in fact: I suggested Tejun not to bother with workqueue tracepoints yet and to drop the previous ones for now. The previous ones were placed to observe problems specific to the purely serialized design they had. I thought cmwq would need other tracepoints.

In fact I thought no tools were using these tracepoints. Bad assumption...

#2 lore raw
In reply to Arjan van de Ven
Quoted 16 lines · Arjan van de Ven

From: Arjan van de Ven <[email protected]>
Date: Sat, 21 Aug 2010 13:07:26 -0700
Subject: [PATCH] workqueue: Add basic tracepoints to track workqueue execution

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

With this pair of tracepoints, the next PowerTOP can correctly report which work item caused the wakeup (and how long it took):

Quoted 7 lines
Interrupt (43)            i915      time   3.51ms    wakeups 141
Work      ieee80211_iface_work      time   0.81ms    wakeups  29
Work              do_dbs_timer      time   0.55ms    wakeups  24
Process                   Xorg      time  21.36ms    wakeups   4
Timer    sched_rt_period_timer      time   0.01ms    wakeups   1
Signed-off-by Arjan van de Ven <[email protected]>

Ok, Linus applied it. That answers my doubts about the route for this patch :)

maintainer
#3 lore raw

Hello,

Quoted 23 lines · Frederic Weisbecker
Quoted 22 lines · Arjan van de Ven

From: Arjan van de Ven <[email protected]>
Date: Sat, 21 Aug 2010 13:07:26 -0700
Subject: [PATCH] workqueue: Add basic tracepoints to track workqueue execution

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

With this pair of tracepoints, the next PowerTOP can correctly report which work item caused the wakeup (and how long it took):

Interrupt (43)            i915      time   3.51ms    wakeups 141
Work      ieee80211_iface_work      time   0.81ms    wakeups  29
Work              do_dbs_timer      time   0.55ms    wakeups  24
Process                   Xorg      time  21.36ms    wakeups   4
Timer    sched_rt_period_timer      time   0.01ms    wakeups   1
Quoted 4 lines
Quoted 1 line
Signed-off-by Arjan van de Ven <[email protected]>

Ok, Linus applied it. That answers my doubts about the route for this patch :)

I was planning to work on wq tracing in this devel cycle but yeah Arjan's patch seems like a good starting place.

We definitely need more tracing points tho. Also, David was wondering whether it would be possible to have simple file based interface to monitor the current status of workers. That's doable w/ tracing API, right?

Thanks.

Signature · 1 line
tejun
#4 lore raw
Quoted 31 lines · Tejun Heo

Hello,

Quoted 23 lines · Frederic Weisbecker
Quoted 22 lines · Arjan van de Ven

From: Arjan van de Ven <[email protected]>
Date: Sat, 21 Aug 2010 13:07:26 -0700
Subject: [PATCH] workqueue: Add basic tracepoints to track workqueue execution

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

With this pair of tracepoints, the next PowerTOP can correctly report which work item caused the wakeup (and how long it took):

Interrupt (43)            i915      time   3.51ms    wakeups 141
Work      ieee80211_iface_work      time   0.81ms    wakeups  29
Work              do_dbs_timer      time   0.55ms    wakeups  24
Process                   Xorg      time  21.36ms    wakeups   4
Timer    sched_rt_period_timer      time   0.01ms    wakeups   1
Quoted 4 lines
Quoted 1 line
Signed-off-by Arjan van de Ven <[email protected]>

Ok, Linus applied it. That answers my doubts about the route for this patch :)

Quoted 7 lines

I was planning to work on wq tracing in this devel cycle but yeah Arjan's patch seems like a good starting place.

We definitely need more tracing points tho. Also, David was wondering whether it would be possible to have simple file based interface to monitor the current status of workers. That's doable w/ tracing API, right?

Yeah but the ftrace API that handles statistics is a very basic thing. It works well for measuring entities that won't be freed, like for branch and function profiling for example.
But once you deal with entities that can disappear (like workqueue threads), you need to handle all the locking by yourself.

You can have a look at kernel/trace/trace_workqueue.c. It's broken as we have removed some workqueue tracepoints, so I planned to remove it. It's a basic thing but perhaps you can restart from there.

I think there was also a race between reader and writer. A stat node probably need to be read under rcu (and freed after a grace period).

#5 lore raw
In reply to Arjan van de Ven
Quoted 8 lines · Arjan van de Ven

With the introduction of the new unified work queue thread pools, we lost one feature: It's no longer possible to know which worker is causing the CPU to wake out of idle. The result is that PowerTOP now reports a lot of "kworker/a:b" instead of more readable results.

This patch adds a pair of tracepoints to the new workqueue code, similar in style to the timer/hrtimer tracepoints.

Hi,

it might also be nice to add a workqueue chapter to the traceopint docbook. Since you've already included kernel-doc style comments, the below is all that we need.

current book is at: http://www.kernel.org/doc/htmldocs/tracepoint/

thanks,

-Jason

Add a workqueue chapter to the tracepoint docbook

Signed-off-by Jason Baron <[email protected]>
---
 Documentation/DocBook/tracepoint.tmpl |    5 +++++
 1 files changed, 5 insertions(+), 0 deletions(-)
Documentation/DocBook/tracepoint.tmpl +5 -0
index e8473ea..b57a9ed 100644
@@ -104,4 +104,9 @@
    <title>Block IO</title>
 !Iinclude/trace/events/block.h
   </chapter>
+
+  <chapter id="workqueue">
+   <title>Workqueue</title>
+!Iinclude/trace/events/workqueue.h
+  </chapter>
 </book>
Signature · 1 line
1.6.0.6
maintainer
#6 lore raw

PATCH 1/1 workqueue: Add a workqueue chapter to the tracepoint docbook

From: Jason Baron <[email protected]>

Add a workqueue chapter to the traceopint docbook.

Current book is at: http://www.kernel.org/doc/htmldocs/tracepoint/

Signed-off-by Jason Baron <[email protected]>
Signed-off-by Tejun Heo <[email protected]>

---
Applied w/ patch description update. Thanks.

 Documentation/DocBook/tracepoint.tmpl |    5 +++++
 1 files changed, 5 insertions(+), 0 deletions(-)
Documentation/DocBook/tracepoint.tmpl +5 -0
index e8473ea..b57a9ed 100644
@@ -104,4 +104,9 @@
    <title>Block IO</title>
 !Iinclude/trace/events/block.h
   </chapter>
+
+  <chapter id="workqueue">
+   <title>Workqueue</title>
+!Iinclude/trace/events/workqueue.h
+  </chapter>
 </book>
Signature · 1 line
1.7.1