[PATCH 1/3] ftrace: add tracepoint for timer

[PATCH 1/3] ftrace: add tracepoint for timer

[Xiao Guangrong]

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

This patch can trace timer's whole lifecycle as init/start/expire/cancel

Example ftrace output:
           <...>-2998  [000] 63501.542376: timer_init: timer=e0b374e0
           <...>-2998  [000] 63501.542424: timer_start: timer=e0b374e0 func=test_timerfuc expires=4294941565 cpu=0
	  <idle>-0     [000] 63514.508219: timer_expire: timer=e0b374e0 func=test_timerfuc
          <idle>-0     [000] 63514.508222: timer_cancel: timer=e0b374e0 func=test_timerfuc

We already have debugobject in timer to init/activate/deactivate/free,
but it can't be covered function of there tracepoints, because:
1: We can't get timer's lifecycle information in userspace by debugobject,
   it is necessary for system engineer to investigate system trouble caused
   by using timer.
2: We can't get information of whole lifecycle of timer by debugobject, 
   for example, deactivation of a timer.
3: There are many different tracing code in many kernel subsystem as blktrace,
   debugobject, and tracepoint is designed as generic way to unify these
   tracing way.

Changelog:
1: modify the tracepoint name
2: move tracepoing to suitable position
3: use TRACE_EVENT instead of DEFINE_TRACE/DECLARE_TRACE

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 include/trace/events/timer.h |   94 ++++++++++++++++++++++++++++++++++++++++++
 kernel/timer.c               |    9 ++++-
 2 files changed, 102 insertions(+), 1 deletions(-)
 create mode 100644 include/trace/events/timer.h

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
new file mode 100644
index 0000000..f2f60d8
--- /dev/null
+++ b/include/trace/events/timer.h
@@ -0,0 +1,94 @@
+#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+#include <linux/timer.h>
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM timer
+
+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, int cpu),
+
+	TP_ARGS(timer, cpu),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer		)
+		__field( void *,	function	)
+		__field( unsigned long,	expires		)
+		__field( int,		cpu		)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->function	= timer->function;
+		__entry->expires	= timer->expires;
+		__entry->cpu		= cpu;
+	),
+
+	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
+		  __entry->function, __entry->expires, __entry->cpu)
+);
+
+TRACE_EVENT(timer_expire,
+
+	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)
+);
+
+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 */
+#include <trace/define_trace.h>
+
+
diff --git a/kernel/timer.c b/kernel/timer.c
index 4149033..6cb40ba 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -45,6 +45,9 @@
 #include <asm/timex.h>
 #include <asm/io.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/timer.h>
+
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
 EXPORT_SYMBOL(jiffies_64);
@@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
 {
 	debug_timer_init(timer);
 	__init_timer(timer, name, key);
+	trace_timer_init(timer);
 }
 EXPORT_SYMBOL(init_timer_key);
 
@@ -565,6 +569,7 @@ static inline void detach_timer(struct timer_list *timer,
 	struct list_head *entry = &timer->entry;
 
 	debug_timer_deactivate(timer);
+	trace_timer_cancel(timer);
 
 	__list_del(entry->prev, entry->next);
 	if (clear_pending)
@@ -650,7 +655,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires, bool pending_only)
 
 	timer->expires = expires;
 	internal_add_timer(base, timer);
-
+	trace_timer_start(timer, smp_processor_id());
 out_unlock:
 	spin_unlock_irqrestore(&base->lock, flags);
 
@@ -746,6 +751,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	timer_set_base(timer, base);
 	debug_timer_activate(timer);
 	internal_add_timer(base, timer);
+	trace_timer_start(timer, cpu);
 	/*
 	 * Check whether the other CPU is idle and needs to be
 	 * triggered to reevaluate the timer wheel when nohz is
@@ -914,6 +920,7 @@ static inline void __run_timers(struct tvec_base *base)
 			unsigned long data;
 
 			timer = list_first_entry(head, struct timer_list,entry);
+			trace_timer_expire(timer);
 			fn = timer->function;
 			data = timer->data;
 
-- 
1.6.1.2

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

[Thomas Gleixner]

On Fri, 22 May 2009, 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

  I have a hard time to connect this patch to the original one.
 
> +TRACE_EVENT(timer_start,
> +
> +	TP_PROTO(struct timer_list *timer, int cpu),
> +
> +	TP_ARGS(timer, cpu),
> +
> +	TP_STRUCT__entry(
> +		__field( void *,	timer		)
> +		__field( void *,	function	)
> +		__field( unsigned long,	expires		)
> +		__field( int,		cpu		)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->timer		= timer;
> +		__entry->function	= timer->function;
> +		__entry->expires	= timer->expires;
> +		__entry->cpu		= cpu;
> +	),
> +
> +	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
> +		  __entry->function, __entry->expires, __entry->cpu)
> +);

  How do we connect the trace to the jiffies value when the timer
  was started ?

> +
> +TRACE_EVENT(timer_expire,
> +
> +	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)
> +);

  Ditto.

> +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)
> +);

  Same here.

> @@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
>  {
>  	debug_timer_init(timer);
>  	__init_timer(timer, name, key);
> +	trace_timer_init(timer);

  Can we please avoid to have two debug calls in one 2 line function ?

>  }
>  EXPORT_SYMBOL(init_timer_key);
>  
> @@ -565,6 +569,7 @@ static inline void detach_timer(struct timer_list *timer,
>  	struct list_head *entry = &timer->entry;
>  
>  	debug_timer_deactivate(timer);
> +	trace_timer_cancel(timer);

  Ditto. Please create one debug entity which covers both.

  ....

Thanks,

	tglx

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

[Xiao Guangrong]

Thomas Gleixner wrote:
> On Fri, 22 May 2009, 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
> 
>   I have a hard time to connect this patch to the original one.
>  

There are some timer hook in Mathieu's patch, I just modify the tracepoint name and
add the tracepoint in other suitable place.

>> +TRACE_EVENT(timer_start,
>> +
>> +	TP_PROTO(struct timer_list *timer, int cpu),
>> +
>> +	TP_ARGS(timer, cpu),
>> +
>> +	TP_STRUCT__entry(
>> +		__field( void *,	timer		)
>> +		__field( void *,	function	)
>> +		__field( unsigned long,	expires		)
>> +		__field( int,		cpu		)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__entry->timer		= timer;
>> +		__entry->function	= timer->function;
>> +		__entry->expires	= timer->expires;
>> +		__entry->cpu		= cpu;
>> +	),
>> +
>> +	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
>> +		  __entry->function, __entry->expires, __entry->cpu)
>> +);
> 
>   How do we connect the trace to the jiffies value when the timer
>   was started ?
> 

ftrace already have time information in trace event's output, we can use it instead

>> +
>> +TRACE_EVENT(timer_expire,
>> +
>> +	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)
>> +);
> 
>   Ditto.
> 

Yes, you are right, I'll remove __entry->function in v2 patch

>> +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)
>> +);
> 
>   Same here.
> 
>> @@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
>>  {
>>  	debug_timer_init(timer);
>>  	__init_timer(timer, name, key);
>> +	trace_timer_init(timer);
> 
>   Can we please avoid to have two debug calls in one 2 line function ?
> 

debug_timer_init() must call before object's init, but tracepoint have to call
after object's init beacuse if we move the tracepoint to before object init, the
object has no data yet.

>>  }
>>  EXPORT_SYMBOL(init_timer_key);
>>  
>> @@ -565,6 +569,7 @@ static inline void detach_timer(struct timer_list *timer,
>>  	struct list_head *entry = &timer->entry;
>>  
>>  	debug_timer_deactivate(timer);
>> +	trace_timer_cancel(timer);
> 
>   Ditto. Please create one debug entity which covers both.
>

IMHO, we can't create one entity for init event, so we do better detach other event.

for example:  

in init event:
void init_timer_key(...)
{
	debug_timer_init(timer); 
	__init_timer(timer, name, key);
	trace_timer_init(timer); 
}
 
but in detach event ():
void detach_timer(...)
{
	......
	trace_timer_deactivate()
}

void trace_timer_deactivate()
{
	debug_timer_deactivate(timer);
	trace_timer_cancel(timer);
}
 
it's  disunity for us.

Thanks,
Xiao Guangrong
 
>   ....
> 
> Thanks,
> 
> 	tglx
> 
> 

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

[Thomas Gleixner]

On Wed, 27 May 2009, Xiao Guangrong wrote:
> >> +	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
> >> +		  __entry->function, __entry->expires, __entry->cpu)
> >> +);
> > 
> >   How do we connect the trace to the jiffies value when the timer
> >   was started ?
> > 
> 
> ftrace already have time information in trace event's output, we can use it instead

  Hmm, I'm not sure whether we can see the jiffies value there, but ok. 
 
> >> @@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
> >>  {
> >>  	debug_timer_init(timer);
> >>  	__init_timer(timer, name, key);
> >> +	trace_timer_init(timer);
> > 
> >   Can we please avoid to have two debug calls in one 2 line function ?
> > 
> 
> debug_timer_init() must call before object's init, but tracepoint have to call
> after object's init beacuse if we move the tracepoint to before object init, the
> object has no data yet.

  Err.

> >> + 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)
> >> +);

  Is timer different before and after the __init_timer call ?
 
> >>  }
> >>  EXPORT_SYMBOL(init_timer_key);
> >>  
> >> @@ -565,6 +569,7 @@ static inline void detach_timer(struct timer_list *timer,
> >>  	struct list_head *entry = &timer->entry;
> >>  
> >>  	debug_timer_deactivate(timer);
> >> +	trace_timer_cancel(timer);
> > 
> >   Ditto. Please create one debug entity which covers both.
> >
> 
> IMHO, we can't create one entity for init event, so we do better detach other event.

  See above.
 
Thanks,

	tglx

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

[Zhaolei]

Thomas Gleixner wrote:
> On Wed, 27 May 2009, Xiao Guangrong wrote:
>>>> +	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
>>>> +		  __entry->function, __entry->expires, __entry->cpu)
>>>> +);
>>>   How do we connect the trace to the jiffies value when the timer
>>>   was started ?
>>>
>> ftrace already have time information in trace event's output, we can use it instead
> 
>   Hmm, I'm not sure whether we can see the jiffies value there, but ok. 
>  
>>>> @@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
>>>>  {
>>>>  	debug_timer_init(timer);
>>>>  	__init_timer(timer, name, key);
>>>> +	trace_timer_init(timer);
>>>   Can we please avoid to have two debug calls in one 2 line function ?
>>>
>> debug_timer_init() must call before object's init, but tracepoint have to call
>> after object's init beacuse if we move the tracepoint to before object init, the
>> object has no data yet.
> 
>   Err.
> 
>>>> + 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)
>>>> +);
> 
>   Is timer different before and after the __init_timer call ?

Hello, Thomas

Yes, timer's pointer is same before and after __init_timer().
We don't need to put debug_timer_init() and trace_timer_init() into different
place.

But, for trace_timer_start() in __mod_timer(), we need to put it after
timer->* changed.
Nevertheless, it don't means we need separate trace_timer_start() and
debug_timer_activate(), because we can put move debug_timer_activate() below,
as:
-	debug_timer_activate(timer);
	...
 	timer->expires = expires;
 	internal_add_timer(base, timer);
+	debug_timer_activate(timer);
+	trace_timer_start(timer, smp_processor_id());

Then we can also combine debug_timer_activate() and trace_timer_start() into
one function.

So we'll do what you suggested.

Thanks
Zhaolei

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

[Thomas Gleixner]

On Fri, 29 May 2009, Zhaolei wrote:
> But, for trace_timer_start() in __mod_timer(), we need to put it after
> timer->* changed.

Why ?

>> +	TP_fast_assign(
>> +		__entry->timer		= timer;
>> +		__entry->function	= timer->function;
>> +		__entry->expires	= timer->expires;
>> +		__entry->cpu		= cpu;

Again, neither timer nor function nor expires will change when the
timer is added, right ?

The only unknown at this point is cpu. See below.

> Nevertheless, it don't means we need separate trace_timer_start() and
> debug_timer_activate(), because we can put move debug_timer_activate() below,
> as:
> -	debug_timer_activate(timer);
> 	...
>  	timer->expires = expires;
>  	internal_add_timer(base, timer);
> +	debug_timer_activate(timer);

No, you can not call it with the base->lock held.

> +	trace_timer_start(timer, smp_processor_id());

Also using smp_processor_id() here is wrong. We do not necessarily add
the timer to the current CPUs timer wheel. See the code which selects
the timer base. So this information is rather useless, because the
tracer knows anyway  on which CPU we are running.

Unfortunately we do not have an easy way to figure out to which CPU
the base belongs (except if it's the base of the current CPU). There
is not much we can do about that. But OTOH, this is not a problem
because we see when the timer expires on which CPU it was enqueued. So
scrapping the cpu entry in the trace completely is not a big loss.

The same applies to hrtimers as well.

Thanks,

	tglx

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

[Zhaolei]

Thomas Gleixner wrote:
> On Fri, 29 May 2009, Zhaolei wrote:
>> But, for trace_timer_start() in __mod_timer(), we need to put it after
>> timer->* changed.
> 
> Why ?

Hello, Thomas

Thanks for your review.

Please see my explain below.

> 
>>> +	TP_fast_assign(
>>> +		__entry->timer		= timer;
>>> +		__entry->function	= timer->function;
>>> +		__entry->expires	= timer->expires;
>>> +		__entry->cpu		= cpu;
> 
> Again, neither timer nor function nor expires will change when the
> timer is added, right ?
> 

Sorry for my poor English.
I don't means that internal_add_timer() will change timer->*.
My meaning is:
	timer->expires = expires; *
	internal_add_timer(base, timer);

*: timer->expires is changed here, so trace_timer_start() need to called below
   this line. If we call debug_timer_activate() and trace_timer_start() together,
   we need to move debug_timer_activate() to place below this line too.

> The only unknown at this point is cpu. See below.
> 
>> Nevertheless, it don't means we need separate trace_timer_start() and
>> debug_timer_activate(), because we can put move debug_timer_activate() below,
>> as:
>> -	debug_timer_activate(timer);
>> 	...
>>  	timer->expires = expires;
>>  	internal_add_timer(base, timer);
>> +	debug_timer_activate(timer);
> 
> No, you can not call it with the base->lock held.
> 
>> +	trace_timer_start(timer, smp_processor_id());
> 
> Also using smp_processor_id() here is wrong. We do not necessarily add
> the timer to the current CPUs timer wheel. See the code which selects
> the timer base. So this information is rather useless, because the
> tracer knows anyway  on which CPU we are running.
> 
> Unfortunately we do not have an easy way to figure out to which CPU
> the base belongs (except if it's the base of the current CPU). There
> is not much we can do about that. But OTOH, this is not a problem
> because we see when the timer expires on which CPU it was enqueued. So
> scrapping the cpu entry in the trace completely is not a big loss.

Indeed.
We can remove smp_processor_id() from trace_timer_start()'s argument.

Xiao Guangrong, author of this patch is in vacation these days, and will come
back recently.
Maybe we want to hear his opinion about this fix.

Thanks
Zhaolei

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

[Xiao Guangrong]

Thomas Gleixner wrote:
> On Wed, 27 May 2009, Xiao Guangrong wrote:
>>>> +	TP_printk("timer=%p func=%pf expires=%lu cpu=%d", __entry->timer,
>>>> +		  __entry->function, __entry->expires, __entry->cpu)
>>>> +);
>>>   How do we connect the trace to the jiffies value when the timer
>>>   was started ?
>>>
>> ftrace already have time information in trace event's output, we can use it instead
> 
>   Hmm, I'm not sure whether we can see the jiffies value there, but ok. 
>  
>>>> @@ -547,6 +550,7 @@ void init_timer_key(struct timer_list *timer,
>>>>  {
>>>>  	debug_timer_init(timer);
>>>>  	__init_timer(timer, name, key);
>>>> +	trace_timer_init(timer);
>>>   Can we please avoid to have two debug calls in one 2 line function ?
>>>
>> debug_timer_init() must call before object's init, but tracepoint have to call
>> after object's init beacuse if we move the tracepoint to before object init, the
>> object has no data yet.
> 
>   Err.
> 
>>>> + 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)
>>>> +);
> 
>   Is timer different before and after the __init_timer call ?
>  

Hi tglx:

I have different view about this.

In ftrace, we only use the timer's pointer, It's same value before or after
__init_timer(). 
But TRACE_EVENT not only be used in ftrace but also be used in other probe
module. Maybe detailed information of timer is requisite in other probe funtion.
In this case, we must put trace_timer_init() after  __init_timer().

Thanks,
Xiao Guangrong

>>>>  }
>>>>  EXPORT_SYMBOL(init_timer_key);
>>>>  
>>>> @@ -565,6 +569,7 @@ static inline void detach_timer(struct timer_list *timer,
>>>>  	struct list_head *entry = &timer->entry;
>>>>  
>>>>  	debug_timer_deactivate(timer);
>>>> +	trace_timer_cancel(timer);
>>>   Ditto. Please create one debug entity which covers both.
>>>
>> IMHO, we can't create one entity for init event, so we do better detach other event.
> 
>   See above.
>  
> Thanks,
> 
> 	tglx
> 
> 

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

[Xiao Guangrong]

Thomas Gleixner wrote:
> On Fri, 29 May 2009, Zhaolei wrote:
>> But, for trace_timer_start() in __mod_timer(), we need to put it after
>> timer->* changed.
> 
> Why ?
> 
>>> +	TP_fast_assign(
>>> +		__entry->timer		= timer;
>>> +		__entry->function	= timer->function;
>>> +		__entry->expires	= timer->expires;
>>> +		__entry->cpu		= cpu;
> 
> Again, neither timer nor function nor expires will change when the
> timer is added, right ?
> 
> The only unknown at this point is cpu. See below.
> 
>> Nevertheless, it don't means we need separate trace_timer_start() and
>> debug_timer_activate(), because we can put move debug_timer_activate() below,
>> as:
>> -	debug_timer_activate(timer);
>> 	...
>>  	timer->expires = expires;
>>  	internal_add_timer(base, timer);
>> +	debug_timer_activate(timer);
> 
> No, you can not call it with the base->lock held.
> 
>> +	trace_timer_start(timer, smp_processor_id());
> 
> Also using smp_processor_id() here is wrong. We do not necessarily add
> the timer to the current CPUs timer wheel. See the code which selects
> the timer base. So this information is rather useless, because the
> tracer knows anyway  on which CPU we are running.
> 
> Unfortunately we do not have an easy way to figure out to which CPU
> the base belongs (except if it's the base of the current CPU). There
> is not much we can do about that. But OTOH, this is not a problem
> because we see when the timer expires on which CPU it was enqueued. So
> scrapping the cpu entry in the trace completely is not a big loss.
> 
> The same applies to hrtimers as well.
> 

Hi tglx:

I also have different view here.  :-) 

As you say, "We do not necessarily add the timer to the current CPUs timer
wheel", but the timer is added to current CPU in __mod_timer(), selects the
timer base as below code:
	new_base = __get_cpu_var(tvec_bases);
In this case, we can use smp_processor_id() to get the CPU which timer is
added.

We can not add the timer to the current CPUs by using add_timer_on(), selects
the timer base in this function as below code:
	struct tvec_base *base = per_cpu(tvec_bases, cpu);
In this case, We can know the timer is added to 'cpu'.

So, I add trace_timer_start() in __mod_timer() and add_timer_on()in my patch.

In hrtimer, all timer is added to the current CPU which can be getted by using
smp_processor_id() in probe function, so it not has 'cpu' argument in my patch.

In addition, we do better not put trace_timer_start() and debug_timer_activate
in one function, have two reasons:
1: for trace_timer_start()'s logic, the timer start event is completed in 
   internal_add_timer(), in other words: the timer is not start before
   internal_add_timer().
	
2: as Zhaolei says in the last mail, the timer's data may changed after
   debug_timer_activate().

Thanks,
Xiao Guangrong

> 
> 	tglx
> 
> 

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

[Thomas Gleixner]

On Wed, 3 Jun 2009, Xiao Guangrong wrote:
> Thomas Gleixner wrote:
> > On Fri, 29 May 2009, Zhaolei wrote:
> >> But, for trace_timer_start() in __mod_timer(), we need to put it after
> >> timer->* changed.
> > 
> > Why ?
> > 
> >>> +	TP_fast_assign(
> >>> +		__entry->timer		= timer;
> >>> +		__entry->function	= timer->function;
> >>> +		__entry->expires	= timer->expires;
> >>> +		__entry->cpu		= cpu;
> > 
> > Again, neither timer nor function nor expires will change when the
> > timer is added, right ?
> > 
> > The only unknown at this point is cpu. See below.
> > 
> >> Nevertheless, it don't means we need separate trace_timer_start() and
> >> debug_timer_activate(), because we can put move debug_timer_activate() below,
> >> as:
> >> -	debug_timer_activate(timer);
> >> 	...
> >>  	timer->expires = expires;
> >>  	internal_add_timer(base, timer);
> >> +	debug_timer_activate(timer);
> > 
> > No, you can not call it with the base->lock held.
> > 
> >> +	trace_timer_start(timer, smp_processor_id());
> > 
> > Also using smp_processor_id() here is wrong. We do not necessarily add
> > the timer to the current CPUs timer wheel. See the code which selects
> > the timer base. So this information is rather useless, because the
> > tracer knows anyway  on which CPU we are running.
> > 
> > Unfortunately we do not have an easy way to figure out to which CPU
> > the base belongs (except if it's the base of the current CPU). There
> > is not much we can do about that. But OTOH, this is not a problem
> > because we see when the timer expires on which CPU it was enqueued. So
> > scrapping the cpu entry in the trace completely is not a big loss.
> > 
> > The same applies to hrtimers as well.
> > 
> 
> Hi tglx:
> 
> I also have different view here.  :-) 
>
> As you say, "We do not necessarily add the timer to the current CPUs timer
> wheel", but the timer is added to current CPU in __mod_timer(), selects the
> timer base as below code:
> 	new_base = __get_cpu_var(tvec_bases);
> In this case, we can use smp_processor_id() to get the CPU which timer is
> added.

No, this is _wrong_. You need to look at the full source. I added some
extra comments

	new_base = __get_cpu_var(tvec_bases);

	if (base != new_base) {

+ 	   	 /* current timer base is on a different CPU */

		/*
		 * We are trying to schedule the timer on the local CPU.
		 * However we can't change timer's base while it is running,
		 * otherwise del_timer_sync() can't detect that the timer's
		 * handler yet has not finished. This also guarantees that
		 * the timer is serialized wrt itself.
		 */
		if (likely(base->running_timer != timer)) {
			/* See the comment in lock_timer_base() */
			timer_set_base(timer, NULL);
			spin_unlock(&base->lock);
			base = new_base;
			spin_lock(&base->lock);
			timer_set_base(timer, base);
-		}
+		} else
+		  /*
+		   * we know that that
+		   * the callback is running on a different CPU and we need
+		   * to keep base unchanged, so smp_processor_id() is
+		   * telling you the wrong information.
+		   */
+	}

> We can not add the timer to the current CPUs by using add_timer_on(), selects

  We can add the timer to the current CPU by using add_timer_on() as well.

> the timer base in this function as below code:
> 	struct tvec_base *base = per_cpu(tvec_bases, cpu);
> In this case, We can know the timer is added to 'cpu'.
>
> So, I add trace_timer_start() in __mod_timer() and add_timer_on()in my patch.

  Still in the __mod_timer() case the tracing info can be wrong and
  tracing wrong information is worse than tracing no information.

  Your patch could result in a trace which confuses the hell out of
  people looking at it:

  ....... 0..... activate_timer on cpu 0
  
  some time later

  ....... 2..... expire timer on cpu 2

  And the guy who needs to analyse that trace would rip his hairs out
  to find out how the timer moved from cpu 0 to cpu 2
 
> In hrtimer, all timer is added to the current CPU which can be getted by using
> smp_processor_id() in probe function, so it not has 'cpu' argument in my patch.

  Wrong again. Read the code in switch_hrtimer_base(). It does the
  same thing as the timer base selection logic in __mod_timer()
 
> In addition, we do better not put trace_timer_start() and debug_timer_activate
> in one function, have two reasons:
> 1: for trace_timer_start()'s logic, the timer start event is completed in 
>    internal_add_timer(), in other words: the timer is not start before
>    internal_add_timer().

 Oh well. So where is the difference of tracing it before or after the
 list add happened ? That's complete irrelevant.
 
> 2: as Zhaolei says in the last mail, the timer's data may changed after
>    debug_timer_activate().

 Really ? What is going to change ? Nothing in the normal case, in the
 case the timer is active then it is removed first. Also it depends on
 how you do this:

void debug_and_trace_timer_activate(....)
{
	debug_timer_activate(...);
	trace_timer_activate(...);
}

in the timer code:

-      debug_timer_activate(...);
+      debug_and_trace_timer_activate(...);

So this does not change the order of functions at all, but it avoids
sprinkling the real code with tons of extra crap.

Thanks,

	tglx

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

[Xiao Guangrong]

Thomas Gleixner wrote:

> No, this is _wrong_. You need to look at the full source. I added some
> extra comments
> 
> 	new_base = __get_cpu_var(tvec_bases);
> 
> 	if (base != new_base) {
> 
> + 	   	 /* current timer base is on a different CPU */
> 
> 		/*
> 		 * We are trying to schedule the timer on the local CPU.
> 		 * However we can't change timer's base while it is running,
> 		 * otherwise del_timer_sync() can't detect that the timer's
> 		 * handler yet has not finished. This also guarantees that
> 		 * the timer is serialized wrt itself.
> 		 */
> 		if (likely(base->running_timer != timer)) {
> 			/* See the comment in lock_timer_base() */
> 			timer_set_base(timer, NULL);
> 			spin_unlock(&base->lock);
> 			base = new_base;
> 			spin_lock(&base->lock);
> 			timer_set_base(timer, base);
> -		}
> +		} else
> +		  /*
> +		   * we know that that
> +		   * the callback is running on a different CPU and we need
> +		   * to keep base unchanged, so smp_processor_id() is
> +		   * telling you the wrong information.
> +		   */
> +	}
> 
>> We can not add the timer to the current CPUs by using add_timer_on(), selects
> 
>   We can add the timer to the current CPU by using add_timer_on() as well.
> 
>> the timer base in this function as below code:
>> 	struct tvec_base *base = per_cpu(tvec_bases, cpu);
>> In this case, We can know the timer is added to 'cpu'.
>>
>> So, I add trace_timer_start() in __mod_timer() and add_timer_on()in my patch.
> 
>   Still in the __mod_timer() case the tracing info can be wrong and
>   tracing wrong information is worse than tracing no information.
> 
>   Your patch could result in a trace which confuses the hell out of
>   people looking at it:
> 
>   ....... 0..... activate_timer on cpu 0
>   
>   some time later
> 
>   ....... 2..... expire timer on cpu 2
> 
>   And the guy who needs to analyse that trace would rip his hairs out
>   to find out how the timer moved from cpu 0 to cpu 2
>  
>> In hrtimer, all timer is added to the current CPU which can be getted by using
>> smp_processor_id() in probe function, so it not has 'cpu' argument in my patch.
> 
>   Wrong again. Read the code in switch_hrtimer_base(). It does the
>   same thing as the timer base selection logic in __mod_timer()
>  

Hi tglx: 

Thanks for you correct my mistake again.  :-) 

It's hard to detect which cpu the timer add, we can remove the 'cpu' parameter
in trace_timer_start() as your suggestion, like this:

TRACE_EVENT(timer_start,

	TP_PROTO(struct timer_list *timer),

	TP_ARGS(timer),

	TP_STRUCT__entry(
		__field( void *,	timer		)
		__field( void *,	function	)
		__field( unsigned long,	expires		)
	),
	......
}

>> In addition, we do better not put trace_timer_start() and debug_timer_activate
>> in one function, have two reasons:
>> 1: for trace_timer_start()'s logic, the timer start event is completed in 
>>    internal_add_timer(), in other words: the timer is not start before
>>    internal_add_timer().
> 
>  Oh well. So where is the difference of tracing it before or after the
>  list add happened ? That's complete irrelevant.
>  

Yes, maybe it's not important.

>> 2: as Zhaolei says in the last mail, the timer's data may changed after
>>    debug_timer_activate().
> 
>  Really ? What is going to change ? Nothing in the normal case, in the
>  case the timer is active then it is removed first. Also it depends on
>  how you do this:
> 
> void debug_and_trace_timer_activate(....)
> {
> 	debug_timer_activate(...);
> 	trace_timer_activate(...);
> }
> 
> in the timer code:
> 
> -      debug_timer_activate(...);
> +      debug_and_trace_timer_activate(...);
> 
> So this does not change the order of functions at all, but it avoids
> sprinkling the real code with tons of extra crap.
> 

See below code:

static inline int
__mod_timer(......)
{
	......
	......
	
	debug_timer_activate(timer);

	new_base = __get_cpu_var(tvec_bases);
	......
	......
	
	timer->expires = expires;	*
	internal_add_timer(base, timer);
	trace_timer_start(...)
	......
}
( this example is in Zhaolei's reply)

timer->expires can be changed at *, if we put trace_timer_start() and
debug_timer_activate() together, we can't get the right value of timer->expires.

In addition, do you agree my humble opinion about not put __init_timer() and
debug_timer_init() together? (can be found at:
http://marc.info/?l=linux-kernel&m=124399744614127&w=2)
If you agree with it, we do better to detach other event.

Thanks,
Xiao Guangrong

> Thanks,
> 
> 	tglx
> 
> 

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

[Thomas Gleixner]

On Thu, 4 Jun 2009, Xiao Guangrong wrote:
> > void debug_and_trace_timer_activate(....)
> > {
> > 	debug_timer_activate(...);
> > 	trace_timer_activate(...);
> > }
> > 
> > in the timer code:
> > 
> > -      debug_timer_activate(...);
> > +      debug_and_trace_timer_activate(...);
> > 
> > So this does not change the order of functions at all, but it avoids
> > sprinkling the real code with tons of extra crap.
> > 
> 
> See below code:
> 
> static inline int
> __mod_timer(......)
> {
> 	......
> 	......
>
 	
- 	debug_timer_activate(timer);
+	debug_and_trace_timer_activate(timer, expires);

  Does the trick nicely

> In addition, do you agree my humble opinion about not put __init_timer() and
> debug_timer_init() together? (can be found at:

No, I do not agree at all. I still see no value in those extra trace
points. As I showed you above you can hide all in extra arguments to a
combined debug_trace_xxx() function.

> http://marc.info/?l=linux-kernel&m=124399744614127&w=2)

>> But TRACE_EVENT not only be used in ftrace but also be used in
>> other probe module. Maybe detailed information of timer is
>> requisite in other probe funtion.  In this case, we must put
>> trace_timer_init() after __init_timer().

Please stop this handwaving about potential use cases. I still have
not seen a single technical argument which explains the benefit of
those extra trace points. If we follow your "maybe its needed" logic
then we have to add yet another dozen of tracepoints into the same
functions to gather all possible states which might be there.

Tracing is important but it needs to be done unintrusive to the code
and you have to apply common sense which information is really
valuable and necessary. Gathering random crap just because it might be
necessary at some point is useless.

Get your gear together, sit down and think hard about which
information a tracer or a probe needs to have to give us a useful
insight into a particular object or function.

As long as there is no technical convincing argument that the gathered
information is really useful I'm not going to apply any of those
patches to the code I maintain.

Thanks,

	tglx

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

[Xiao Guangrong]

Hi Thomas:

Sorry for the delayed reply.

> Please stop this handwaving about potential use cases. I still have
> not seen a single technical argument which explains the benefit of
> those extra trace points. If we follow your "maybe its needed" logic
> then we have to add yet another dozen of tracepoints into the same
> functions to gather all possible states which might be there.
> 
> Tracing is important but it needs to be done unintrusive to the code
> and you have to apply common sense which information is really
> valuable and necessary. Gathering random crap just because it might be
> necessary at some point is useless.
> 

I see your point, and I agree with you on this.

> Get your gear together, sit down and think hard about which
> information a tracer or a probe needs to have to give us a useful
> insight into a particular object or function.
> 
> As long as there is no technical convincing argument that the gathered
> information is really useful I'm not going to apply any of those
> patches to the code I maintain.
> 

Those tracepoints are wanted and useful:

1) We can detect a timer's delay if jiffies info is added, like this:

	XXX: timer_start: timer=e0b374e0 func=test_timerfuc expires=4294941565
	XXX: timer_expire: timer=e0b374e0 func=test_timerfuc jiffies=4294941567
 
   We expect the timer expires at 4294941565, actually the timer expires at
   4294941567, so it is delayed by 2 jiffies.

2) We can monitor the lifecycle and behaviors of a timer, for example, when
   monitoring dirty writeback timer, I found reading /proc/sys/vm/dirty_writeback_centisecs
   will reset the timer:

         pdflush-244   [000]  0.554131: timer_start: timer=c077ef20 func=wb_timer_fn expires=2757949
          <idle>-0     [000]  5.544769: timer_expire: timer=c077ef20 func=wb_timer_fn
          <idle>-0     [000]  5.544770: timer_cancel: timer=c077ef20 func=wb_timer_fn
         pdflush-244   [000]  5.544807: timer_start: timer=c077ef20 func=wb_timer_fn expires=2762949
             cat-2326  [000]  5.618852: timer_cancel: timer=c077ef20 func=wb_timer_fn
             cat-2326  [000]  6.618858: timer_start: timer=c077ef20 func=wb_timer_fn expires=2764025

3) We are developing "flight-record" using crash. It can read out the ring
   buffer from the dump file, and let us know what was happening before
   kernel panic, so we may find the cause of the panic. This requires
   well-defined tracepoints in different kernel subsystems, especially some
   core subsystems, timer is surely one of them.

I'll revise those patches according to your suggestions.

Thanks,
Xiao Guangrong

> Thanks,
> 
> 	tglx
> 
> 

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

[Thomas Gleixner]

Xiao,

On Wed, 10 Jun 2009, Xiao Guangrong wrote:
> Those tracepoints are wanted and useful:
> 1) We can detect a timer's delay if jiffies info is added, like this:
> 
> 	XXX: timer_start: timer=e0b374e0 func=test_timerfuc expires=4294941565
> 	XXX: timer_expire: timer=e0b374e0 func=test_timerfuc jiffies=4294941567
>    We expect the timer expires at 4294941565, actually the timer expires at
>    4294941567, so it is delayed by 2 jiffies.

You can achive the same thing by storing (expires - jiffies) when you
trace the timer start. Then you can calc the delta from the trace
timestamps, but I have no strong opinion about that.

> 2) We can monitor the lifecycle and behaviors of a timer, for
>    example, when monitoring dirty writeback timer, I found reading
>    /proc/sys/vm/dirty_writeback_centisecs will reset the timer:

 
> 3) We are developing "flight-record" using crash. It can read out the ring
>    buffer from the dump file, and let us know what was happening before
>    kernel panic, so we may find the cause of the panic. This requires
>    well-defined tracepoints in different kernel subsystems, especially some
>    core subsystems, timer is surely one of them.

I'm not arguing that tracepoints are not useful, but you can achieve
all the things above by combining them in an unintrusive way to the
existing debug points.

This results in the minimum noise of debug/trace insertions into the
code, which keeps it readable and maintainable. That's all I want.

Thanks,

	tglx