From ede1b4290781ae82ccf0f2ecc6dada8d3dd35779 Mon Sep 17 00:00:00 2001 From: Arjan van de Ven Date: Wed, 18 Aug 2010 15:33:13 -0700 Subject: tracing: Fix timer tracing PowerTOP would like to be able to trace timers. Unfortunately, the current timer tracing is not very useful: the actual timer function is not recorded in the trace at the start of timer execution. Although this is recorded for timer "start" time (when it gets armed), this is not useful; most timers get started early, and a tracer like PowerTOP will never see this event, but will only see the actual running of the timer. This patch just adds the function to the timer tracing; I've verified with PowerTOP that now it can get useful information about timers. Signed-off-by: Arjan van de Ven Cc: xiaoguangrong@cn.fujitsu.com Cc: Steven Rostedt Cc: Frederic Weisbecker Cc: Peter Zijlstra Cc: # .35.x, .34.x, .33.x LKML-Reference: <4C6C5FA9.3000405@linux.intel.com> Signed-off-by: Ingo Molnar --- include/trace/events/timer.h | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) (limited to 'include/trace') diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h index c624126a9c8..425bcfe56c6 100644 --- a/include/trace/events/timer.h +++ b/include/trace/events/timer.h @@ -81,14 +81,16 @@ TRACE_EVENT(timer_expire_entry, TP_STRUCT__entry( __field( void *, timer ) __field( unsigned long, now ) + __field( void *, function) ), TP_fast_assign( __entry->timer = timer; __entry->now = jiffies; + __entry->function = timer->function; ), - TP_printk("timer=%p now=%lu", __entry->timer, __entry->now) + TP_printk("timer=%p function=%pf now=%lu", __entry->timer, __entry->function,__entry->now) ); /** @@ -200,14 +202,16 @@ TRACE_EVENT(hrtimer_expire_entry, TP_STRUCT__entry( __field( void *, hrtimer ) __field( s64, now ) + __field( void *, function) ), TP_fast_assign( __entry->hrtimer = hrtimer; __entry->now = now->tv64; + __entry->function = hrtimer->function; ), - TP_printk("hrtimer=%p now=%llu", __entry->hrtimer, + TP_printk("hrtimer=%p function=%pf now=%llu", __entry->hrtimer, __entry->function, (unsigned long long)ktime_to_ns((ktime_t) { .tv64 = __entry->now })) ); -- cgit v1.2.3-70-g09d2 From e36c886a0f9d624377977fa6cae309cfd7f362fa Mon Sep 17 00:00:00 2001 From: Arjan van de Ven Date: Sat, 21 Aug 2010 13:07:26 -0700 Subject: 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 Signed-off-by: Linus Torvalds --- include/trace/events/workqueue.h | 62 ++++++++++++++++++++++++++++++++++++++++ kernel/workqueue.c | 9 ++++++ 2 files changed, 71 insertions(+) create mode 100644 include/trace/events/workqueue.h (limited to 'include/trace') diff --git a/include/trace/events/workqueue.h b/include/trace/events/workqueue.h new file mode 100644 index 00000000000..49682d7e9d6 --- /dev/null +++ b/include/trace/events/workqueue.h @@ -0,0 +1,62 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM workqueue + +#if !defined(_TRACE_WORKQUEUE_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_WORKQUEUE_H + +#include +#include + +/** + * 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 diff --git a/kernel/workqueue.c b/kernel/workqueue.c index 2994a0e3a61..8bd600c020e 100644 --- a/kernel/workqueue.c +++ b/kernel/workqueue.c @@ -35,6 +35,9 @@ #include #include +#define CREATE_TRACE_POINTS +#include + #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); -- cgit v1.2.3-70-g09d2