Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
From: Frédéric Weisbecker
Date: Wed May 20 2009 - 20:01:33 EST
2009/5/20 Anton Blanchard <anton@xxxxxxxxx>:
>
> Add tracepoints for timer and high res timer execution. We add entry and
> exit tracepoints so we can calculate timer latency.
>
> Example ftrace output:
>
> <idle>-0 [000] 264.040506: hrtimer_entry: func=.tick_sched_timer+0x0/0xf0
> <idle>-0 [000] 264.040508: hrtimer_exit: func=.tick_sched_timer+0x0/0xf0 restart=HRTIMER_RESTART
> <idle>-0 [000] 264.040530: timer_entry: func=.e1000_watchdog+0x0/0x8fc
> <idle>-0 [000] 264.040728: timer_exit: func=.e1000_watchdog+0x0/0x8fc
>
> Here we can see e1000_watchdog is taking 0.2ms - it might make sense to
> move this into a workqueue or kernel thread.
>
> Signed-off-by: Anton Blanchard <anton@xxxxxxxxx>
> ---
>
> Index: linux-2.6-tracing/kernel/hrtimer.c
> ===================================================================
> --- linux-2.6-tracing.orig/kernel/hrtimer.c 2009-05-20 17:11:50.000000000 +1000
> +++ linux-2.6-tracing/kernel/hrtimer.c 2009-05-20 17:11:52.000000000 +1000
> @@ -46,6 +46,8 @@
>
> #include <asm/uaccess.h>
>
> +#include <trace/events/timer.h>
> +
> /**
> * ktime_get - get the monotonic time in ktime_t format
> *
> @@ -1161,7 +1163,9 @@
> * the timer base.
> */
> spin_unlock(&cpu_base->lock);
> + trace_hrtimer_entry(timer);
> restart = fn(timer);
> + trace_hrtimer_exit(timer, restart);
> spin_lock(&cpu_base->lock);
>
> /*
> Index: linux-2.6-tracing/kernel/timer.c
> ===================================================================
> --- linux-2.6-tracing.orig/kernel/timer.c 2009-05-20 17:11:50.000000000 +1000
> +++ linux-2.6-tracing/kernel/timer.c 2009-05-20 17:11:52.000000000 +1000
> @@ -44,6 +44,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);
> @@ -946,7 +949,9 @@
> */
> lock_map_acquire(&lockdep_map);
>
> + trace_timer_entry(timer);
> fn(data);
> + trace_timer_exit(timer);
>
> lock_map_release(&lockdep_map);
>
> Index: linux-2.6-tracing/include/trace/events/timer.h
> ===================================================================
> --- /dev/null 1970-01-01 00:00:00.000000000 +0000
> +++ linux-2.6-tracing/include/trace/events/timer.h 2009-05-20 17:15:41.000000000 +1000
> @@ -0,0 +1,116 @@
> +#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ)
> +#define _TRACE_TIMER_H
> +
> +#include <linux/tracepoint.h>
> +#include <linux/timer.h>
> +#include <linux/hrtimer.h>
> +
> +#undef TRACE_SYSTEM
> +#define TRACE_SYSTEM timer
> +
> +/**
> + * timer_entry - called immediately before the timer
> + * @timer: pointer to struct timer_list
> + *
> + * When used in combination with the timer_exit tracepoint we can
> + * determine the timer latency.
> + */
> +TRACE_EVENT(timer_entry,
> +
> + TP_PROTO(struct timer_list *timer),
> +
> + TP_ARGS(timer),
> +
> + TP_STRUCT__entry(
> + __field(void *, function)
void * won't make the filtering easier.
It would require the raw address whereas it would be nice to filter
by function name.
But saving the address instead of the resolved name is faster.
I guess we should add a filter feature to resolve a function name to
its address.
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + ),
> +
> + TP_printk("func=%pF", __entry->function)
Please use %pf which only prints the function name and ignore the
offsets and so... These overload
the trace in such case.
Thanks,
Frederic.
> +);
> +
> +/**
> + * timer_exit - called immediately after the timer returns
> + * @timer: pointer to struct timer_list
> + *
> + * When used in combination with the timer_entry tracepoint we can
> + * determine the timer latency.
> + */
> +TRACE_EVENT(timer_exit,
> +
> + TP_PROTO(struct timer_list *timer),
> +
> + TP_ARGS(timer),
> +
> + TP_STRUCT__entry(
> + __field(void *, function)
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + ),
> +
> + TP_printk("func=%pF", __entry->function)
> +);
> +
> +/**
> + * hrtimer_entry - called immediately before the high res timer
> + * @timer: pointer to struct hrtimer
> + *
> + * When used in combination with the hrtimer_exit tracepoint we can
> + * determine the high res timer latency.
> + */
> +TRACE_EVENT(hrtimer_entry,
> +
> + TP_PROTO(struct hrtimer *timer),
> +
> + TP_ARGS(timer),
> +
> + TP_STRUCT__entry(
> + __field(void *, function)
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + ),
> +
> + TP_printk("func=%pF", __entry->function)
> +);
> +
> +/**
> + * hrtimer_exit - called immediately after the high res timer returns
> + * @timer: pointer to struct hrtimer
> + * @restart: high res timer return value
> + *
> + * High res timer will restart if @restart is set to HRTIMER_RESTART.
> + * When used in combination with the hrtimer_entry tracepoint we can
> + * determine the high res timer latency.
> + */
> +TRACE_EVENT(hrtimer_exit,
> +
> + TP_PROTO(struct hrtimer *timer, int restart),
> +
> + TP_ARGS(timer, restart),
> +
> + TP_STRUCT__entry(
> + __field(void *, function)
> + __field(int, restart)
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + __entry->restart = restart;
> + ),
> +
> + TP_printk("func=%pF restart=%s", __entry->function,
> + (__entry->restart == HRTIMER_RESTART) ?
> + "HRTIMER_RESTART" : "HRTIMER_NORESTART")
> +);
> +
> +#endif /* _TRACE_TIMER_H */
> +
> +/* This part must be outside protection */
> +#include <trace/define_trace.h>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/