Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751736AbZFYFJV (ORCPT ); Thu, 25 Jun 2009 01:09:21 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1750863AbZFYFJM (ORCPT ); Thu, 25 Jun 2009 01:09:12 -0400 Received: from fg-out-1718.google.com ([72.14.220.158]:38058 "EHLO fg-out-1718.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750788AbZFYFJL (ORCPT ); Thu, 25 Jun 2009 01:09:11 -0400 DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=date:from:to:cc:subject:message-id:references:mime-version :content-type:content-disposition:in-reply-to:user-agent; b=CB8gO1f25ViACZurMf6gqBRtodz5PC2E8jj8zpf9tAyBNwXdkncQUIto/cM/6ZI5MK 5XoKlLP5xK2IQXyHJeXmWtQOjWygvuNv8VegGyoNu7rwlLIbk+Q9uTPewd0VeNaszU44 +pi8+YkAL4iMeLroUNAcX6OpN6KLy5vuE9usA= Date: Thu, 25 Jun 2009 07:09:10 +0200 From: Frederic Weisbecker To: Xiao Guangrong , Thomas Gleixner Cc: Ingo , Mathieu Desnoyers , Steven Rostedt , Zhaolei , kosaki.motohiro@jp.fujitsu.com, LKML Subject: Re: [PATCH v2 1/2] ftrace: add tracepoint for timer Message-ID: <20090625050908.GB6071@nowhere> References: <4A38B9C7.3080802@cn.fujitsu.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <4A38B9C7.3080802@cn.fujitsu.com> User-Agent: Mutt/1.5.18 (2008-05-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6548 Lines: 226 On Wed, Jun 17, 2009 at 05:39:19PM +0800, Xiao Guangrong wrote: > 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 > -0 [001] 217105.935436: timer_expire: timer=e0b3e4c8 func=timer_fun jiffies=442863 > -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 > Signed-off-by: Xiao Guangrong Thomas, are you fine with these patches? If so, I can prepare a pull request to Ingo, unless he prefers to apply them himself. Thanks, Frederic. > --- > 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 d07c900..11660c7 100644 > --- a/kernel/timer.c > +++ b/kernel/timer.c > @@ -521,6 +521,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) > @@ -549,7 +573,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); > @@ -568,7 +592,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) > @@ -629,7 +653,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); > > @@ -781,7 +805,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 > @@ -952,6 +976,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 > > -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/