Messages in this thread Patch in this message | | | Date | Mon, 06 Jul 2009 17:39:31 +0800 | From | Xiao Guangrong <> | Subject | [PATCH v2 1/3] ftrace: add tracepoint for timer |
| |
This patch is modify from Mathieu's patch base on Ingo's suggestion, the original patch can be found here: http://marc.info/?l=linux-kernel&m=123791201816247&w=2
Great thanks to Thomas for giving me so many valuable advices.
Those tracepoints are wanted and useful: 1: We can detect a timer's delay 2: We can monitor the lifecycle and behaviors of a timer
Thus they help in analysing and debuging.
Example ftrace output: insmod-3743 [001] 217105.738770: timer_init: timer=e0b3e4c8 insmod-3743 [001] 217105.738868: timer_start: timer=e0b3e4c8 func=timer_fun expires=442863 timeout=50 <idle>-0 [001] 217105.935436: timer_expire: timer=e0b3e4c8 func=timer_fun jiffies=442863 <idle>-0 [001] 217105.935440: timer_cancel: timer=e0b3e4c8 func=timer_fun
We expect the timer expires at 442863, after 50 jiffies, actually the timer expires at 442863, so it is delayed by 0 jiffies.
Changelog v1->v2: 1: Add jiffies info into timer 2: Combine debugobjects and trace as Thomas's suggestion
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca> Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com> --- include/trace/events/timer.h | 82 ++++++++++++++++++++++++++++++++++++++++++ kernel/timer.c | 33 +++++++++++++++-- 2 files changed, 111 insertions(+), 4 deletions(-)
diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h index 6e7beb5..e9c51ee 100644 --- a/include/trace/events/timer.h +++ b/include/trace/events/timer.h @@ -110,6 +110,88 @@ TRACE_EVENT(hrtimer_exit, "HRTIMER_RESTART" : "HRTIMER_NORESTART") ); +TRACE_EVENT(timer_init, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + ), + + TP_fast_assign( + __entry->timer = timer; + ), + + TP_printk("timer=%p", __entry->timer) +); + +TRACE_EVENT(timer_start, + + TP_PROTO(struct timer_list *timer, unsigned long expires), + + TP_ARGS(timer, expires), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( void *, function ) + __field( unsigned long, expires ) + __field( int, timeout ) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->function = timer->function; + __entry->expires = expires; + __entry->timeout = timer->expires - jiffies; + ), + + TP_printk("timer=%p func=%pf expires=%lu timeout=%d", __entry->timer, + __entry->function, __entry->expires, __entry->timeout) +); + +TRACE_EVENT(timer_expire, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( void *, function ) + __field( unsigned long, jiffies ) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->function = timer->function; + __entry->jiffies = jiffies; + ), + + TP_printk("timer=%p func=%pf jiffies=%lu", __entry->timer, + __entry->function, __entry->jiffies) +); + +TRACE_EVENT(timer_cancel, + + TP_PROTO(struct timer_list *timer), + + TP_ARGS(timer), + + TP_STRUCT__entry( + __field( void *, timer ) + __field( void *, function ) + ), + + TP_fast_assign( + __entry->timer = timer; + __entry->function = timer->function; + ), + + TP_printk("timer=%p func=%pf", __entry->timer, __entry->function) +); + #endif /* _TRACE_TIMER_H */ /* This part must be outside protection */ diff --git a/kernel/timer.c b/kernel/timer.c index 9385ad5..13f943b 100644 --- a/kernel/timer.c +++ b/kernel/timer.c @@ -523,6 +523,30 @@ static inline void debug_timer_activate(struct timer_list *timer) { } static inline void debug_timer_deactivate(struct timer_list *timer) { } #endif +static inline void debug_and_trace_timer_init(struct timer_list *timer) +{ + debug_timer_init(timer); + trace_timer_init(timer); +} + +static inline void +debug_and_trace_timer_activate(struct timer_list *timer, unsigned long expires) +{ + debug_timer_activate(timer); + trace_timer_start(timer, expires); +} + +static inline void debug_and_trace_timer_expire(struct timer_list *timer) +{ + trace_timer_expire(timer); +} + +static inline void debug_and_trace_timer_deactivate(struct timer_list *timer) +{ + debug_timer_deactivate(timer); + trace_timer_cancel(timer); +} + static void __init_timer(struct timer_list *timer, const char *name, struct lock_class_key *key) @@ -551,7 +575,7 @@ void init_timer_key(struct timer_list *timer, const char *name, struct lock_class_key *key) { - debug_timer_init(timer); + debug_and_trace_timer_init(timer); __init_timer(timer, name, key); } EXPORT_SYMBOL(init_timer_key); @@ -570,7 +594,7 @@ static inline void detach_timer(struct timer_list *timer, { struct list_head *entry = &timer->entry; - debug_timer_deactivate(timer); + debug_and_trace_timer_deactivate(timer); __list_del(entry->prev, entry->next); if (clear_pending) @@ -631,7 +655,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires, goto out_unlock; } - debug_timer_activate(timer); + debug_and_trace_timer_activate(timer, expires); new_base = __get_cpu_var(tvec_bases); @@ -783,7 +807,7 @@ void add_timer_on(struct timer_list *timer, int cpu) BUG_ON(timer_pending(timer) || !timer->function); spin_lock_irqsave(&base->lock, flags); timer_set_base(timer, base); - debug_timer_activate(timer); + debug_and_trace_timer_activate(timer, timer->expires); internal_add_timer(base, timer); /* * Check whether the other CPU is idle and needs to be @@ -954,6 +978,7 @@ static inline void __run_timers(struct tvec_base *base) unsigned long data; timer = list_first_entry(head, struct timer_list,entry); + debug_and_trace_timer_expire(timer); fn = timer->function; data = timer->data; -- 1.6.1.2
| |