[PATCH] workqueue: Add a trace event for works enqueuing

[PATCH] workqueue: Add a trace event for works enqueuing

[Frederic Weisbecker]

Tracing worklet queuing provides useful informations to understand
their lifecycles. Combined with timers trace events, we can also
extend the informations about this lifecycle from delayed queueing.

Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Ingo Molnar <mingo@elte.hu>
---
 include/trace/events/workqueue.h |   32 ++++++++++++++++++++++++++++++++
 kernel/workqueue.c               |    2 ++
 2 files changed, 34 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h
index 49682d7..4c2ec52 100644
--- a/include/trace/events/workqueue.h
+++ b/include/trace/events/workqueue.h
@@ -7,6 +7,38 @@
 #include <linux/tracepoint.h>
 #include <linux/workqueue.h>
 
+
+/**
+ * workqueue_queue_work - called when a work gets queued
+ * @work:	pointer to struct work_struct
+ * @wq:		workqueue structure
+ *
+ * Allows to track workqueue execution. This event occurs when
+ * a work is queued immediately or once a delayed work is actually
+ * queued on a workqueue (ie: once the delay has been reached).
+ */
+TRACE_EVENT(workqueue_queue_work,
+
+	TP_PROTO(struct work_struct *work, struct workqueue_struct *wq),
+
+	TP_ARGS(work, wq),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+		__field( void *,	workqueue)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+		__entry->workqueue	= wq;
+	),
+
+	TP_printk("work struct=%p function=%pf workqueue=%p",
+			__entry->work, __entry->function, __entry->workqueue)
+);
+
 /**
  * workqueue_execute_start - called immediately before the workqueue callback
  * @work:	pointer to struct work_struct
diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index f77afd9..5ed9f89 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -959,6 +959,8 @@ static void __queue_work(unsigned int cpu, struct workqueue_struct *wq,
 	if (WARN_ON_ONCE(wq->flags & WQ_DYING))
 		return;
 
+	trace_workqueue_queue_work(work, wq);
+
 	/* determine gcwq to use */
 	if (!(wq->flags & WQ_UNBOUND)) {
 		struct global_cwq *last_gcwq;
-- 
1.6.2.3

Re: [PATCH] workqueue: Add a trace event for works enqueuing

[Tejun Heo]

Sorry about the delay.  I was off last week.

How about something like this?  It probably needs to be split into two
patches.  It provides more information on which CPU was requested and
eventually chosen and separates queueing and activation which can be
useful for analyzing latency or freezer issues.

Thanks.

diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h
index 49682d7..7d49729 100644
--- a/include/trace/events/workqueue.h
+++ b/include/trace/events/workqueue.h
@@ -7,38 +7,83 @@
 #include <linux/tracepoint.h>
 #include <linux/workqueue.h>

+DECLARE_EVENT_CLASS(workqueue_work,
+
+	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)
+);
+
 /**
- * workqueue_execute_start - called immediately before the workqueue callback
+ * workqueue_queue_work - called when a work gets queued
+ * @req_cpu:	the requested cpu
+ * @cwq:	pointer to struct cpu_workqueue_struct
  * @work:	pointer to struct work_struct
  *
- * Allows to track workqueue execution.
+ * This event occurs when a work is queued immediately or once a
+ * delayed work is actually queued on a workqueue (ie: once the delay
+ * has been reached).
  */
-TRACE_EVENT(workqueue_execute_start,
+TRACE_EVENT(workqueue_queue_work,

-	TP_PROTO(struct work_struct *work),
+	TP_PROTO(unsigned int req_cpu, struct cpu_workqueue_struct *cwq,
+		 struct work_struct *work),

-	TP_ARGS(work),
+	TP_ARGS(req_cpu, cwq, work),

 	TP_STRUCT__entry(
 		__field( void *,	work	)
 		__field( void *,	function)
+		__field( void *,	workqueue)
+		__field( unsigned int,	req_cpu	)
+		__field( unsigned int,	cpu	)
 	),

 	TP_fast_assign(
 		__entry->work		= work;
 		__entry->function	= work->func;
+		__entry->workqueue	= cwq->wq;
+		__entry->req_cpu	= req_cpu;
+		__entry->cpu		= cwq->gcwq->cpu;
 	),

-	TP_printk("work struct %p: function %pf", __entry->work, __entry->function)
+	TP_printk("work struct=%p function=%pf workqueue=%p req_cpu=%u cpu=%u",
+		  __entry->work, __entry->function, __entry->workqueue,
+		  __entry->req_cpu, __entry->cpu)
 );

 /**
- * workqueue_execute_end - called immediately before the workqueue callback
+ * workqueue_activate_work - called when a work gets activated
+ * @work:	pointer to struct work_struct
+ *
+ * This event occurs when a queued work is put on the active queue,
+ * which happens immediately after queueing unless @max_active limit
+ * is reached.
+ */
+DEFINE_EVENT(workqueue_work, workqueue_activate_work,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work)
+);
+
+/**
+ * workqueue_execute_start - called immediately before the workqueue callback
  * @work:	pointer to struct work_struct
  *
  * Allows to track workqueue execution.
  */
-TRACE_EVENT(workqueue_execute_end,
+TRACE_EVENT(workqueue_execute_start,

 	TP_PROTO(struct work_struct *work),

@@ -46,15 +91,29 @@ TRACE_EVENT(workqueue_execute_end,

 	TP_STRUCT__entry(
 		__field( void *,	work	)
+		__field( void *,	function)
 	),

 	TP_fast_assign(
 		__entry->work		= work;
+		__entry->function	= work->func;
 	),

-	TP_printk("work struct %p", __entry->work)
+	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.
+ */
+DEFINE_EVENT(workqueue_work, workqueue_execute_end,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work)
+);

 #endif /*  _TRACE_WORKQUEUE_H */

diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 19e4bc1..cb2ccfb 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -42,9 +42,6 @@
 #include <linux/lockdep.h>
 #include <linux/idr.h>

-#define CREATE_TRACE_POINTS
-#include <trace/events/workqueue.h>
-
 #include "workqueue_sched.h"

 enum {
@@ -257,6 +254,9 @@ EXPORT_SYMBOL_GPL(system_long_wq);
 EXPORT_SYMBOL_GPL(system_nrt_wq);
 EXPORT_SYMBOL_GPL(system_unbound_wq);

+#define CREATE_TRACE_POINTS
+#include <trace/events/workqueue.h>
+
 #define for_each_busy_worker(worker, i, pos, gcwq)			\
 	for (i = 0; i < BUSY_WORKER_HASH_SIZE; i++)			\
 		hlist_for_each_entry(worker, pos, &gcwq->busy_hash[i], hentry)
@@ -997,6 +997,7 @@ static void __queue_work(unsigned int cpu, struct workqueue_struct *wq,

 	/* gcwq determined, get cwq and queue */
 	cwq = get_cwq(gcwq->cpu, wq);
+	trace_workqueue_queue_work(cpu, cwq, work);

 	BUG_ON(!list_empty(&work->entry));

@@ -1004,6 +1005,7 @@ static void __queue_work(unsigned int cpu, struct workqueue_struct *wq,
 	work_flags = work_color_to_flags(cwq->work_color);

 	if (likely(cwq->nr_active < cwq->max_active)) {
+		trace_workqueue_activate_work(work);
 		cwq->nr_active++;
 		worklist = gcwq_determine_ins_pos(gcwq, cwq);
 	} else {
@@ -1679,6 +1681,7 @@ static void cwq_activate_first_delayed(struct cpu_workqueue_struct *cwq)
 						    struct work_struct, entry);
 	struct list_head *pos = gcwq_determine_ins_pos(cwq->gcwq, cwq);

+	trace_workqueue_activate_work(work);
 	move_linked_works(work, pos, NULL);
 	__clear_bit(WORK_STRUCT_DELAYED_BIT, work_data_bits(work));
 	cwq->nr_active++;

Re: [PATCH] workqueue: Add a trace event for works enqueuing

[Frederic Weisbecker]

On Mon, Oct 04, 2010 at 04:46:56PM +0200, Tejun Heo wrote:
> Sorry about the delay.  I was off last week.
> 
> How about something like this?  It probably needs to be split into two
> patches.  It provides more information on which CPU was requested and
> eventually chosen and separates queueing and activation which can be
> useful for analyzing latency or freezer issues.
> 
> Thanks.



Yep looks good. I hadn't thought about frozen works.

Thanks.

(I think this should go through your tree rather than the tracing tree).

[PATCH wq#for-next 1/2] workqueue: prepare for more tracepoints

[Tejun Heo]

Define workqueue_work event class and use it for workqueue_execute_end
trace point.  Also, move trace/events/workqueue.h include downwards
such that all struct definitions are visible to it.  This is to
prepare for more tracepoints and doesn't cause any functional change.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
---
I'll route these two through wq tree.  Thank you.

 include/trace/events/workqueue.h |   32 +++++++++++++++++++-------------
 kernel/workqueue.c               |    6 +++---
 2 files changed, 22 insertions(+), 16 deletions(-)

diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h
index 49682d7..ec9d724 100644
--- a/include/trace/events/workqueue.h
+++ b/include/trace/events/workqueue.h
@@ -7,13 +7,7 @@
 #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,
+DECLARE_EVENT_CLASS(workqueue_work,

 	TP_PROTO(struct work_struct *work),

@@ -21,24 +15,22 @@ TRACE_EVENT(workqueue_execute_start,

 	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)
+	TP_printk("work struct %p", __entry->work)
 );

 /**
- * workqueue_execute_end - called immediately before the workqueue callback
+ * workqueue_execute_start - called immediately before the workqueue callback
  * @work:	pointer to struct work_struct
  *
  * Allows to track workqueue execution.
  */
-TRACE_EVENT(workqueue_execute_end,
+TRACE_EVENT(workqueue_execute_start,

 	TP_PROTO(struct work_struct *work),

@@ -46,15 +38,29 @@ TRACE_EVENT(workqueue_execute_end,

 	TP_STRUCT__entry(
 		__field( void *,	work	)
+		__field( void *,	function)
 	),

 	TP_fast_assign(
 		__entry->work		= work;
+		__entry->function	= work->func;
 	),

-	TP_printk("work struct %p", __entry->work)
+	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.
+ */
+DEFINE_EVENT(workqueue_work, workqueue_execute_end,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work)
+);

 #endif /*  _TRACE_WORKQUEUE_H */

diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 19e4bc1..026f778 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -42,9 +42,6 @@
 #include <linux/lockdep.h>
 #include <linux/idr.h>

-#define CREATE_TRACE_POINTS
-#include <trace/events/workqueue.h>
-
 #include "workqueue_sched.h"

 enum {
@@ -257,6 +254,9 @@ EXPORT_SYMBOL_GPL(system_long_wq);
 EXPORT_SYMBOL_GPL(system_nrt_wq);
 EXPORT_SYMBOL_GPL(system_unbound_wq);

+#define CREATE_TRACE_POINTS
+#include <trace/events/workqueue.h>
+
 #define for_each_busy_worker(worker, i, pos, gcwq)			\
 	for (i = 0; i < BUSY_WORKER_HASH_SIZE; i++)			\
 		hlist_for_each_entry(worker, pos, &gcwq->busy_hash[i], hentry)
-- 
1.7.1

[PATCH wq#for-next 2/2] workqueue: add queue_work and activate_work trace points

[Tejun Heo]

These two tracepoints allow tracking when and how a work is queued and
activated.  This patch is based on Frederic's patch to add queue_work
trace point.

Signed-off-by: Tejun Heo <tj@kernel.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
---
 include/trace/events/workqueue.h |   53 ++++++++++++++++++++++++++++++++++++++
 kernel/workqueue.c               |    3 ++
 2 files changed, 56 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h
index ec9d724..7d49729 100644
--- a/include/trace/events/workqueue.h
+++ b/include/trace/events/workqueue.h
@@ -25,6 +25,59 @@ DECLARE_EVENT_CLASS(workqueue_work,
 );

 /**
+ * workqueue_queue_work - called when a work gets queued
+ * @req_cpu:	the requested cpu
+ * @cwq:	pointer to struct cpu_workqueue_struct
+ * @work:	pointer to struct work_struct
+ *
+ * This event occurs when a work is queued immediately or once a
+ * delayed work is actually queued on a workqueue (ie: once the delay
+ * has been reached).
+ */
+TRACE_EVENT(workqueue_queue_work,
+
+	TP_PROTO(unsigned int req_cpu, struct cpu_workqueue_struct *cwq,
+		 struct work_struct *work),
+
+	TP_ARGS(req_cpu, cwq, work),
+
+	TP_STRUCT__entry(
+		__field( void *,	work	)
+		__field( void *,	function)
+		__field( void *,	workqueue)
+		__field( unsigned int,	req_cpu	)
+		__field( unsigned int,	cpu	)
+	),
+
+	TP_fast_assign(
+		__entry->work		= work;
+		__entry->function	= work->func;
+		__entry->workqueue	= cwq->wq;
+		__entry->req_cpu	= req_cpu;
+		__entry->cpu		= cwq->gcwq->cpu;
+	),
+
+	TP_printk("work struct=%p function=%pf workqueue=%p req_cpu=%u cpu=%u",
+		  __entry->work, __entry->function, __entry->workqueue,
+		  __entry->req_cpu, __entry->cpu)
+);
+
+/**
+ * workqueue_activate_work - called when a work gets activated
+ * @work:	pointer to struct work_struct
+ *
+ * This event occurs when a queued work is put on the active queue,
+ * which happens immediately after queueing unless @max_active limit
+ * is reached.
+ */
+DEFINE_EVENT(workqueue_work, workqueue_activate_work,
+
+	TP_PROTO(struct work_struct *work),
+
+	TP_ARGS(work)
+);
+
+/**
  * workqueue_execute_start - called immediately before the workqueue callback
  * @work:	pointer to struct work_struct
  *
diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 026f778..cb2ccfb 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -997,6 +997,7 @@ static void __queue_work(unsigned int cpu, struct workqueue_struct *wq,

 	/* gcwq determined, get cwq and queue */
 	cwq = get_cwq(gcwq->cpu, wq);
+	trace_workqueue_queue_work(cpu, cwq, work);

 	BUG_ON(!list_empty(&work->entry));

@@ -1004,6 +1005,7 @@ static void __queue_work(unsigned int cpu, struct workqueue_struct *wq,
 	work_flags = work_color_to_flags(cwq->work_color);

 	if (likely(cwq->nr_active < cwq->max_active)) {
+		trace_workqueue_activate_work(work);
 		cwq->nr_active++;
 		worklist = gcwq_determine_ins_pos(gcwq, cwq);
 	} else {
@@ -1679,6 +1681,7 @@ static void cwq_activate_first_delayed(struct cpu_workqueue_struct *cwq)
 						    struct work_struct, entry);
 	struct list_head *pos = gcwq_determine_ins_pos(cwq->gcwq, cwq);

+	trace_workqueue_activate_work(work);
 	move_linked_works(work, pos, NULL);
 	__clear_bit(WORK_STRUCT_DELAYED_BIT, work_data_bits(work));
 	cwq->nr_active++;
-- 
1.7.1