Re: [PATCH v2 1/2] ftrace: add tracepoint for timer

[Frederic Weisbecker <fweisbec@gmail.com>]

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
>    <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>


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
> 
>