[PATCH v2 5/4] ftrace, workqueuetrace: display work name
From: KOSAKI Motohiro
Date: Tue Apr 14 2009 - 00:03:51 EST
Frederic, What do you think this patch?
===============
Currently, event-tracer only display function name. it is enough useful.
but some driver share work-function between multiple work_struct.
then, work name displaying is better.
example output
------------------------------
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
<idle>-0 [003] 1540.844960: workqueue_insertion: thread=events/3:30 func=e1000_watchdog_task+0x0/0x6ae [e1000e] work=&adapter->watchdog_task
<idle>-0 [003] 1540.844964: workqueue_insertion: thread=events/3:30 func=vmstat_update+0x0/0x3f work=vmstat_work
<...>-30 [003] 1540.844969: workqueue_handler_entry: thread=events/3:30 latency=0ms func=e1000_watchdog_task+0x0/0x6ae [e1000e] work=&adapter-
>watchdog_task
<...>-30 [003] 1540.845003: workqueue_handler_exit: thread=events/3:30 func=e1000_watchdog_task+0x0/0x6ae [e1000e] work=&adapter->watchdog_tas
k
<...>-30 [003] 1540.845004: workqueue_handler_entry: thread=events/3:30 latency=0ms func=vmstat_update+0x0/0x3f work=vmstat_work
<...>-30 [003] 1540.845007: workqueue_handler_exit: thread=events/3:30 func=vmstat_update+0x0/0x3f work=vmstat_work
This patch increase kernel-size for work name string table.
But actually, lockdep already have work name string table. then if you already use lockdep,
you don't get kernel-size increasing by this patch.
Signed-off-by: KOSAKI Motohiro <kosaki.motohiro@xxxxxxxxxxxxxx>
Cc: Zhaolei <zhaolei@xxxxxxxxxxxxxx>
Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
Cc: Frederic Weisbecker <fweisbec@xxxxxxxxx>
Cc: Tom Zanussi <tzanussi@xxxxxxxxx>
Cc: Ingo Molnar <mingo@xxxxxxx>
---
include/linux/workqueue.h | 34 +++++++++++++++++++++++++++++++++-
include/trace/workqueue_event_types.h | 23 ++++++++++++++++-------
kernel/workqueue.c | 2 +-
3 files changed, 50 insertions(+), 9 deletions(-)
Index: b/include/linux/workqueue.h
===================================================================
--- a/include/linux/workqueue.h 2009-04-14 11:57:05.000000000 +0900
+++ b/include/linux/workqueue.h 2009-04-14 12:53:57.000000000 +0900
@@ -22,6 +22,11 @@ typedef void (*work_func_t)(struct work_
*/
#define work_data_bits(work) ((unsigned long *)(&(work)->data))
+#if defined(CONFIG_WORKQUEUE_TRACER) || defined(CONFIG_EVENT_TRACING)
+#define HAVE_WORK_TRACE 1
+#endif
+
+
struct work_struct {
atomic_long_t data;
#define WORK_STRUCT_PENDING 0 /* T if work item pending execution */
@@ -32,8 +37,9 @@ struct work_struct {
#ifdef CONFIG_LOCKDEP
struct lockdep_map lockdep_map;
#endif
-#ifdef CONFIG_WORKQUEUE_TRACER
+#ifdef HAVE_WORK_TRACE
unsigned long expected_time;
+ char *name;
#endif
};
@@ -65,11 +71,19 @@ struct execute_work {
#define __WORK_INIT_LOCKDEP_MAP(n, k)
#endif
+#ifdef HAVE_WORK_TRACE
+#define __WORK_INIT_NAME(_work, _name) \
+ .name = _name,
+#else
+#define __WORK_INIT_NAME(_work, _name)
+#endif
+
#define __WORK_INITIALIZER(n, f) { \
.data = WORK_DATA_INIT(), \
.entry = { &(n).entry, &(n).entry }, \
.func = (f), \
__WORK_INIT_LOCKDEP_MAP(#n, &(n)) \
+ __WORK_INIT_NAME(&n, #n) \
}
#define __DELAYED_WORK_INITIALIZER(n, f) { \
@@ -94,6 +108,18 @@ struct execute_work {
#define PREPARE_DELAYED_WORK(_work, _func) \
PREPARE_WORK(&(_work)->work, (_func))
+#ifdef HAVE_WORK_TRACE
+#define SET_WORK_NAME(_work, _name) \
+ do { \
+ (_work)->name = (_name); \
+ } while (0)
+
+#else /*!HAVE_WORK_TRACE*/
+#define SET_WORK_NAME(_work, name)
+#endif /*!HAVE_WORK_TRACE*/
+
+
+
/*
* initialize all of a work item in one go
*
@@ -110,6 +136,7 @@ struct execute_work {
lockdep_init_map(&(_work)->lockdep_map, #_work, &__key, 0);\
INIT_LIST_HEAD(&(_work)->entry); \
PREPARE_WORK((_work), (_func)); \
+ SET_WORK_NAME((_work), #_work); \
} while (0)
#else
#define INIT_WORK(_work, _func) \
@@ -117,6 +144,7 @@ struct execute_work {
(_work)->data = (atomic_long_t) WORK_DATA_INIT(); \
INIT_LIST_HEAD(&(_work)->entry); \
PREPARE_WORK((_work), (_func)); \
+ SET_WORK_NAME((_work), #_work); \
} while (0)
#endif
@@ -124,24 +152,28 @@ struct execute_work {
do { \
INIT_WORK(&(_work)->work, (_func)); \
init_timer(&(_work)->timer); \
+ SET_WORK_NAME(&(_work)->work, #_work); \
} while (0)
#define INIT_DELAYED_WORK_ON_STACK(_work, _func) \
do { \
INIT_WORK(&(_work)->work, (_func)); \
init_timer_on_stack(&(_work)->timer); \
+ SET_WORK_NAME(&(_work)->work, #_work); \
} while (0)
#define INIT_DELAYED_WORK_DEFERRABLE(_work, _func) \
do { \
INIT_WORK(&(_work)->work, (_func)); \
init_timer_deferrable(&(_work)->timer); \
+ SET_WORK_NAME(&(_work)->work, #_work); \
} while (0)
#define INIT_DELAYED_WORK_ON_STACK(_work, _func) \
do { \
INIT_WORK(&(_work)->work, (_func)); \
init_timer_on_stack(&(_work)->timer); \
+ SET_WORK_NAME(&(_work)->work, #_work); \
} while (0)
/**
Index: b/include/trace/workqueue_event_types.h
===================================================================
--- a/include/trace/workqueue_event_types.h 2009-04-14 11:57:05.000000000 +0900
+++ b/include/trace/workqueue_event_types.h 2009-04-14 12:15:26.000000000 +0900
@@ -19,6 +19,7 @@ TRACE_EVENT(workqueue_insertion,
__field(pid_t, thread_pid)
__field(struct work_struct *, work)
__field(work_func_t, func)
+ __field(char*, workname)
),
TP_fast_assign(
@@ -26,10 +27,12 @@ TRACE_EVENT(workqueue_insertion,
__entry->thread_pid = wq_thread->pid;
__entry->work = work;
__entry->func = work->func;
+ __entry->workname = work->name;
),
- TP_printk("thread=%s:%d func=%pF", __entry->thread_comm,
- __entry->thread_pid, __entry->func)
+ TP_printk("thread=%s:%d func=%pF work=%s",
+ __entry->thread_comm, __entry->thread_pid,
+ __entry->func, __entry->workname)
);
TRACE_EVENT(workqueue_handler_entry,
@@ -45,6 +48,7 @@ TRACE_EVENT(workqueue_handler_entry,
__field(work_func_t, func)
__field(unsigned long, expected_time)
__field(unsigned long, actual_time)
+ __field(char*, workname)
),
TP_fast_assign(
@@ -54,12 +58,14 @@ TRACE_EVENT(workqueue_handler_entry,
__entry->func = work->func;
__entry->expected_time = work->expected_time;
__entry->actual_time = jiffies;
+ __entry->workname = work->name;
),
- TP_printk("thread=%s:%d latency=%lums func=%pF", __entry->thread_comm,
- __entry->thread_pid,
+ TP_printk("thread=%s:%d latency=%lums func=%pF work=%s",
+ __entry->thread_comm, __entry->thread_pid,
jiffies_to_msecs(__entry->actual_time-__entry->expected_time),
- __entry->func)
+ __entry->func,
+ __entry->workname)
);
TRACE_EVENT(workqueue_handler_exit,
@@ -72,6 +78,7 @@ TRACE_EVENT(workqueue_handler_exit,
__field(pid_t, thread_pid)
__field(struct work_struct *, work)
__field(work_func_t, func)
+ __field(char*, workname)
),
TP_fast_assign(
@@ -79,10 +86,12 @@ TRACE_EVENT(workqueue_handler_exit,
__entry->thread_pid = wq_thread->pid;
__entry->work = work;
__entry->func = work->func;
+ __entry->workname = work->name;
),
- TP_printk("thread=%s:%d func=%pF", __entry->thread_comm,
- __entry->thread_pid, __entry->func)
+ TP_printk("thread=%s:%d func=%pF work=%s",
+ __entry->thread_comm, __entry->thread_pid,
+ __entry->func, __entry->workname)
);
/* Trace the creation of one workqueue thread on a cpu */
Index: b/kernel/workqueue.c
===================================================================
--- a/kernel/workqueue.c 2009-04-14 11:57:05.000000000 +0900
+++ b/kernel/workqueue.c 2009-04-14 11:59:52.000000000 +0900
@@ -82,7 +82,7 @@ static const struct cpumask *cpu_singlet
*/
static cpumask_var_t cpu_populated_map __read_mostly;
-#ifdef CONFIG_WORKQUEUE_TRACER
+#if HAVE_WORK_TRACE
static void set_expected_time(struct work_struct *work,
unsigned long expected_jiffies)
{
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/