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 <[email protected]>
Signed-off-by: Xiao Guangrong <[email protected]>
---
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
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-3821 [001] 3192.239314: hrtimer_init: timer=d08a1480 clockid=CLOCK_REALTIME mode=HRTIMER_MODE_ABS
insmod-3821 [001] 3192.239335: hrtimer_start: timer=d08a1480 func=hrtimer_fun expires=1245162841000000000 ns softexpires=1245162841000000000 ns
<idle>-0 [001] 3201.506127: hrtimer_expire: timer=d08a1480 func=hrtimer_fun now=1245162841010241858
<idle>-0 [001] 3201.506129: hrtimer_cancel: timer=d08a1480 func=hrtimer_fun
We expect the hrtimer expires at 1245162841000000000 ns, actually the
hrtimer expires at 1245162841010241858 ns, so it is delayed by
1245162841010241858- 1245162841000000000 = 10241858 ns.
Changelog v1->v2:
1: Remove ktime_to_ns() in TP_fast_assign()
2: Combine debugobjects and trace as Thomas's suggestion
Signed-off-by: Xiao Guangrong <[email protected]>
---
include/trace/events/timer.h | 90 ++++++++++++++++++++++++++++++++++++++++++
kernel/hrtimer.c | 38 +++++++++++++++--
2 files changed, 123 insertions(+), 5 deletions(-)
diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index e9c51ee..8ffb2e2 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -192,6 +192,96 @@ TRACE_EVENT(timer_cancel,
TP_printk("timer=%p func=%pf", __entry->timer, __entry->function)
);
+TRACE_EVENT(hrtimer_init,
+
+ TP_PROTO(struct hrtimer *timer, clockid_t clockid, enum hrtimer_mode mode),
+
+ TP_ARGS(timer, clockid, mode),
+
+ TP_STRUCT__entry(
+ __field( void *, timer )
+ __field( clockid_t, clockid )
+ __field( enum hrtimer_mode, mode )
+ ),
+
+ TP_fast_assign(
+ __entry->timer = timer;
+ __entry->clockid = clockid;
+ __entry->mode = mode;
+ ),
+
+ TP_printk("timer=%p clockid=%s mode=%s", __entry->timer,
+ __entry->clockid == CLOCK_REALTIME ?
+ "CLOCK_REALTIME" : "CLOCK_MONOTONIC",
+ __entry->mode == HRTIMER_MODE_ABS ?
+ "HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL")
+);
+
+TRACE_EVENT(hrtimer_start,
+
+ TP_PROTO(struct hrtimer *timer),
+
+ TP_ARGS(timer),
+
+ TP_STRUCT__entry(
+ __field( void *, timer )
+ __field( void *, function )
+ __field( s64, expires )
+ __field( s64, softexpires )
+ ),
+
+ TP_fast_assign(
+ __entry->timer = timer;
+ __entry->function = timer->function;
+ __entry->expires = hrtimer_get_expires(timer).tv64;
+ __entry->softexpires = hrtimer_get_softexpires(timer).tv64;
+ ),
+
+ TP_printk("timer=%p func=%pf expires=%llu ns softexpires=%llu ns",
+ __entry->timer, __entry->function,
+ (unsigned long long)__entry->expires,
+ (unsigned long long)__entry->softexpires)
+);
+
+TRACE_EVENT(hrtimer_expire,
+
+ TP_PROTO(struct hrtimer *timer, s64 now),
+
+ TP_ARGS(timer, now),
+
+ TP_STRUCT__entry(
+ __field( void *, timer )
+ __field( void *, function )
+ __field( s64, now )
+ ),
+
+ TP_fast_assign(
+ __entry->timer = timer;
+ __entry->function = timer->function;
+ __entry->now = now;
+ ),
+
+ TP_printk("timer=%p func=%pf now=%llu", __entry->timer, __entry->function,
+ (unsigned long long)__entry->now)
+);
+
+TRACE_EVENT(hrtimer_cancel,
+
+ TP_PROTO(struct hrtimer *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/hrtimer.c b/kernel/hrtimer.c
index b42429f..f75ba95 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -491,6 +491,32 @@ 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_expire(struct hrtimer *timer,
+ s64 now)
+{
+ trace_hrtimer_expire(timer, now);
+}
+
+static inline void debug_and_trace_hrtimer_deactivate(struct hrtimer *timer)
+{
+ debug_hrtimer_deactivate(timer);
+ trace_hrtimer_cancel(timer);
+}
+
/* High resolution timer related functions */
#ifdef CONFIG_HIGH_RES_TIMERS
@@ -847,7 +873,7 @@ static int enqueue_hrtimer(struct hrtimer *timer,
struct hrtimer *entry;
int leftmost = 1;
- debug_hrtimer_activate(timer);
+ debug_and_trace_hrtimer_activate(timer);
/*
* Find the right place in the rbtree:
@@ -933,7 +959,7 @@ remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base)
* reprogramming happens in the interrupt handler. This is a
* rare case and less expensive than a smp call.
*/
- debug_hrtimer_deactivate(timer);
+ debug_and_trace_hrtimer_deactivate(timer);
timer_stats_hrtimer_clear_start_info(timer);
reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
__remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,
@@ -1167,7 +1193,7 @@ static void __hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
enum hrtimer_mode mode)
{
- debug_hrtimer_init(timer);
+ debug_and_trace_hrtimer_init(timer, clock_id, mode);
__hrtimer_init(timer, clock_id, mode);
}
EXPORT_SYMBOL_GPL(hrtimer_init);
@@ -1200,7 +1226,7 @@ static void __run_hrtimer(struct hrtimer *timer)
WARN_ON(!irqs_disabled());
- debug_hrtimer_deactivate(timer);
+ debug_and_trace_hrtimer_deactivate(timer);
__remove_hrtimer(timer, base, HRTIMER_STATE_CALLBACK, 0);
timer_stats_account_hrtimer(timer);
fn = timer->function;
@@ -1316,6 +1342,7 @@ void hrtimer_interrupt(struct clock_event_device *dev)
break;
}
+ debug_and_trace_hrtimer_expire(timer, basenow.tv64);
__run_hrtimer(timer);
}
spin_unlock(&cpu_base->lock);
@@ -1434,6 +1461,7 @@ void hrtimer_run_queues(void)
hrtimer_get_expires_tv64(timer))
break;
+ debug_and_trace_hrtimer_expire(timer, base->softirq_time.tv64);
__run_hrtimer(timer);
}
spin_unlock(&cpu_base->lock);
@@ -1610,7 +1638,7 @@ static void migrate_hrtimer_list(struct hrtimer_clock_base *old_base,
while ((node = rb_first(&old_base->active))) {
timer = rb_entry(node, struct hrtimer, node);
BUG_ON(hrtimer_callback_running(timer));
- debug_hrtimer_deactivate(timer);
+ debug_and_trace_hrtimer_deactivate(timer);
/*
* Mark it as STATE_MIGRATE not INACTIVE otherwise the
--
1.6.1.2
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 <[email protected]>
> Signed-off-by: Xiao Guangrong <[email protected]>
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
>
>
Frederic Weisbecker wrote:
> 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 <[email protected]>
>> Signed-off-by: Xiao Guangrong <[email protected]>
>
>
> Thomas, are you fine with these patches?
> If so, I can prepare a pull request to Ingo, unless he prefers to
> apply them himself.
>
Hi Thomas,
What is your opinion on this patch?
Can I get your acked-by if you think this patch is useful for us?
Thanks,
Xiao
> Thanks,
> Frederic.
>
>