lkml.org 
[lkml]   [2009]   [Jul]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH v3 3/4] ftrace: add tracepoint for hrtimer
From
Date
On Fri, 2009-07-17 at 18:18 +0800, Xiao Guangrong wrote:
> Those tracepoints are wanted and useful:
> 1: We can detect a hrtimer's delay
> 2: We can monitor the lifecycle and behaviors of a hrtimer
>
> Thus they help in analysing and debuging.
>
> Great thanks to Thomas for giving me so many valuable advices.
>
> Example ftrace output:
> insmod-5280 [000] 10798.356372: hrtimer_init: timer=d0b044c0 clockid=CLOCK_REALTIME mode=HRTIMER_MODE_ABS
> insmod-5280 [000] 10798.356385: hrtimer_start: timer=d0b044c0 func=hrtimer_fun expires=1246242896000000000 ns softexpires=1246242896000000000 ns
> <idle>-0 [000] 10807.982987: hrtimer_expire: timer=d0b044c0 now=1246242896000906503 ns
> <idle>-0 [000] 10807.982989: hrtimer_cancel: timer=d0b044c0
> <idle>-0 [000] 10807.983562: hrtimer_callback_done: timer=d0b044c0
>
> We expect the hrtimer expires at 1246242896000000000 ns, actually the
> hrtimer expires at 1246242896000906503 ns, so it is delayed by
> 1246242896000906503-1246242896000000000 = 906503 ns.
> We also realize the hrtimer's callback started at 10807.982987, and it
> finished at 10807.983562, so it's taking 10807.983562-10807.982987=0.6ms.
>
> Changelog:
> v1->v2:
> 1: Remove ktime_to_ns() in TP_fast_assign()
> 2: Combine debugobjects and trace as Thomas's suggestion
> v2->v3:
> 1: Remove function address from hrtimer_expire and hrtimer_cancel
> as Thomas's suggestion
> 2: Remove debug_and_trace_hrtimer_expire() as Thomas's suggestion
> 3: Rename trace_hrtimer_entry() and trace_hrtimer_exit() to match this patch
>
> Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
> ---



> diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
> index 33317e4..bd21c9b 100644
> --- a/kernel/hrtimer.c
> +++ b/kernel/hrtimer.c
> @@ -442,6 +442,26 @@ static inline void debug_hrtimer_activate(struct hrtimer *timer) { }
> static inline void debug_hrtimer_deactivate(struct hrtimer *timer) { }
> #endif
>
> +static inline void
> +debug_and_trace_hrtimer_init(struct hrtimer *timer, clockid_t clockid,
> + enum hrtimer_mode mode)
> +{
> + debug_hrtimer_init(timer);
> + trace_hrtimer_init(timer, clockid, mode);
> +}
> +
> +static inline void debug_and_trace_hrtimer_activate(struct hrtimer *timer)
> +{
> + debug_hrtimer_activate(timer);
> + trace_hrtimer_start(timer);
> +}
> +
> +static inline void debug_and_trace_hrtimer_deactivate(struct hrtimer *timer)
> +{
> + debug_hrtimer_deactivate(timer);
> + trace_hrtimer_cancel(timer);
> +}

I would argue that tracing is a form of debugging and you shouldn't need
to mangle these names like that, simply leave them debug_*().


> @@ -1162,9 +1182,8 @@ static void __run_hrtimer(struct hrtimer *timer)
> * the timer base.
> */
> spin_unlock(&cpu_base->lock);
> - trace_hrtimer_entry(timer);
> restart = fn(timer);
> - trace_hrtimer_exit(timer, restart);
> + trace_hrtimer_callback_done(timer);
> spin_lock(&cpu_base->lock);
>
> /*

Why bother introducing these tracepoints if you're going to remove them
in the same patch-set?

Also, the below:

> @@ -1275,6 +1294,7 @@ void hrtimer_interrupt(struct clock_event_device *dev)
> break;
> }
>
> + trace_hrtimer_expire(timer, basenow.tv64);
> __run_hrtimer(timer);
> }
> base++;
> @@ -1397,6 +1417,7 @@ void hrtimer_run_queues(void)
> hrtimer_get_expires_tv64(timer))
> break;
>
> + trace_hrtimer_expire(timer, base->softirq_time.tv64);
> __run_hrtimer(timer);
> }
> spin_unlock(&cpu_base->lock);

indicates you placed that tracepoint in the wrong place.

Furthermore, I don't get why you want it there and not on the old
_entry() site, because this adds all kinds of extra overhead and you
loose the exact callback timings.




\
 
 \ /
  Last update: 2009-07-17 12:53    [W:0.870 / U:0.028 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site