ftrace: add tracepoint for timer
Subsystems (2)
PATCH v2 1/2 ftrace: add tracepoint for timer
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
--- include/trace/events/timer.h | 82 ++++++++++++++++++++++++++++++++++++++++++ kernel/timer.c | 33 +++++++++++++++-- 2 files changed, 111 insertions(+), 4 deletions(-)
include/trace/events/timer.h +82 -0
@@ -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 */
kernel/timer.c +29 -4
@@ -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;
Signature · 1 line
1.6.1.2
PATCH v2 2/2 ftrace: add tracepoint for hrtimer
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
--- include/trace/events/timer.h | 90 ++++++++++++++++++++++++++++++++++++++++++ kernel/hrtimer.c | 38 +++++++++++++++-- 2 files changed, 123 insertions(+), 5 deletions(-)
include/trace/events/timer.h +90 -0
@@ -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 */
kernel/hrtimer.c +33 -5
@@ -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
Signature · 1 line
1.6.1.2
Quoted 21 lines · 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=2Great 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 timerThus 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_funWe expect the timer expires at 442863, after 50 jiffies, actually the timer expires at 442863, so it is delayed by 0 jiffies.
Quoted 6 lines
Changelog
v1->v2:
1: Add jiffies info into timer
2: Combine debugobjects and trace as Thomas's suggestionSigned-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.
Quoted 181 lines
--- include/trace/events/timer.h | 82 ++++++++++++++++++++++++++++++++++++++++++ kernel/timer.c | 33 +++++++++++++++-- 2 files changed, 111 insertions(+), 4 deletions(-)include/trace/events/timer.h +82
-0@@ -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 */ kernel/timer.c +29
-4@@ -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;Signature · 1 line
1.6.1.2
Quoted 26 lines · Frederic Weisbecker
Quoted 25 lines · 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=2Great 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 timerThus 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_funWe 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
Quoted 8 lines
Quoted 2 lines
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
Quoted 4 lines
Thanks,
Frederic.