* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-20 10:13 [PATCH] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
@ 2009-05-20 10:25 ` KOSAKI Motohiro
2009-05-20 10:31 ` Thomas Gleixner
` (2 subsequent siblings)
3 siblings, 0 replies; 19+ messages in thread
From: KOSAKI Motohiro @ 2009-05-20 10:25 UTC (permalink / raw)
To: Anton Blanchard
Cc: kosaki.motohiro, rostedt, mingo, tzanussi, jbaron, tglx, linux-kernel
>
> 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@samba.org>
This patch don't cover all timer life-cycle. but I think it's good start.
At least, you prove this patch can find one issue :)
- kosaki
> ---
>
> 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)
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + ),
> +
> + TP_printk("func=%pF", __entry->function)
> +);
> +
> +/**
> + * 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@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-20 10:13 [PATCH] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
2009-05-20 10:25 ` KOSAKI Motohiro
@ 2009-05-20 10:31 ` Thomas Gleixner
2009-05-21 0:01 ` Frédéric Weisbecker
2009-05-26 4:26 ` Anton Blanchard
3 siblings, 0 replies; 19+ messages in thread
From: Thomas Gleixner @ 2009-05-20 10:31 UTC (permalink / raw)
To: Anton Blanchard; +Cc: rostedt, mingo, tzanussi, jbaron, linux-kernel
On Wed, 20 May 2009, Anton Blanchard wrote:
>
> 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.
Cute. That should help us to pinpoint more such timer abusers :)
> Signed-off-by: Anton Blanchard <anton@samba.org>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-20 10:13 [PATCH] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
2009-05-20 10:25 ` KOSAKI Motohiro
2009-05-20 10:31 ` Thomas Gleixner
@ 2009-05-21 0:01 ` Frédéric Weisbecker
2009-05-21 0:13 ` Steven Rostedt
2009-05-21 12:38 ` Anton Blanchard
2009-05-26 4:26 ` Anton Blanchard
3 siblings, 2 replies; 19+ messages in thread
From: Frédéric Weisbecker @ 2009-05-21 0:01 UTC (permalink / raw)
To: Anton Blanchard; +Cc: rostedt, mingo, tzanussi, jbaron, tglx, linux-kernel
2009/5/20 Anton Blanchard <anton@samba.org>:
>
> 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@samba.org>
> ---
>
> 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@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-21 0:01 ` Frédéric Weisbecker
@ 2009-05-21 0:13 ` Steven Rostedt
2009-05-21 12:38 ` Anton Blanchard
1 sibling, 0 replies; 19+ messages in thread
From: Steven Rostedt @ 2009-05-21 0:13 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: Anton Blanchard, mingo, tzanussi, jbaron, tglx, linux-kernel
[-- Attachment #1: Type: TEXT/PLAIN, Size: 1114 bytes --]
On Thu, 21 May 2009, Frédéric Weisbecker wrote:
> 2009/5/20 Anton Blanchard <anton@samba.org>:
> > +/**
> > + * 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.
Yeah, I think that would be the better approach. This should be easy since
the function pointers being saved are the actual address of the function
and not an offset into the function. A simple filter on kallsyms should be
enough.
-- Steve
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-21 0:01 ` Frédéric Weisbecker
2009-05-21 0:13 ` Steven Rostedt
@ 2009-05-21 12:38 ` Anton Blanchard
2009-05-25 20:00 ` Frederic Weisbecker
1 sibling, 1 reply; 19+ messages in thread
From: Anton Blanchard @ 2009-05-21 12:38 UTC (permalink / raw)
To: Frédéric Weisbecker
Cc: rostedt, mingo, tzanussi, jbaron, tglx, linux-kernel
Hi Frédéric,
> > + ),
> > +
> > + 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 for the suggestion. It doesn't look like %pf has made Ingo's tree
yet, do you know if there is a plan to merge it soon?
Anton
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-21 12:38 ` Anton Blanchard
@ 2009-05-25 20:00 ` Frederic Weisbecker
0 siblings, 0 replies; 19+ messages in thread
From: Frederic Weisbecker @ 2009-05-25 20:00 UTC (permalink / raw)
To: Anton Blanchard; +Cc: rostedt, mingo, tzanussi, jbaron, tglx, linux-kernel
On Thu, May 21, 2009 at 10:38:10PM +1000, Anton Blanchard wrote:
>
> Hi Frédéric,
>
> > > + ),
> > > +
> > > + 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 for the suggestion. It doesn't look like %pf has made Ingo's tree
> yet, do you know if there is a plan to merge it soon?
>
> Anton
It's available on tip:master, may be you are working on another tree, or..?
^ permalink raw reply [flat|nested] 19+ messages in thread
* [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-20 10:13 [PATCH] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
` (2 preceding siblings ...)
2009-05-21 0:01 ` Frédéric Weisbecker
@ 2009-05-26 4:26 ` Anton Blanchard
2009-05-26 4:31 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Anton Blanchard
` (2 more replies)
3 siblings, 3 replies; 19+ messages in thread
From: Anton Blanchard @ 2009-05-26 4:26 UTC (permalink / raw)
To: rostedt, mingo, tzanussi, jbaron, tglx, fweisbec, kosaki.motohiro
Cc: linux-kernel
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
<idle>-0 [000] 264.040508: hrtimer_exit: func=.tick_sched_timer restart=HRTIMER_RESTART
<idle>-0 [000] 264.040530: timer_entry: func=.e1000_watchdog
<idle>-0 [000] 264.040728: timer_exit: func=.e1000_watchdog
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@samba.org>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
---
v2: Changed %pF to %pf to remove always 0 function offset.
Index: linux-2.6-master/kernel/hrtimer.c
===================================================================
--- linux-2.6-master.orig/kernel/hrtimer.c 2009-05-26 12:55:35.000000000 +1000
+++ linux-2.6-master/kernel/hrtimer.c 2009-05-26 13:09:55.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-master/kernel/timer.c
===================================================================
--- linux-2.6-master.orig/kernel/timer.c 2009-05-26 12:55:35.000000000 +1000
+++ linux-2.6-master/kernel/timer.c 2009-05-26 13:09:55.000000000 +1000
@@ -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);
@@ -947,7 +950,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-master/include/trace/events/timer.h
===================================================================
--- /dev/null 1970-01-01 00:00:00.000000000 +0000
+++ linux-2.6-master/include/trace/events/timer.h 2009-05-26 13:57:42.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)
+ ),
+
+ TP_fast_assign(
+ __entry->function = timer->function;
+ ),
+
+ TP_printk("func=%pf", __entry->function)
+);
+
+/**
+ * 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>
^ permalink raw reply [flat|nested] 19+ messages in thread
* [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit
2009-05-26 4:26 ` Anton Blanchard
@ 2009-05-26 4:31 ` Anton Blanchard
2009-05-26 4:32 ` [PATCH] tracing/events: Use %pf in workqueue trace events Anton Blanchard
2009-05-29 13:16 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Frédéric Weisbecker
2009-05-26 4:55 ` [PATCH v3] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
2009-05-26 18:06 ` [PATCH] " Frederic Weisbecker
2 siblings, 2 replies; 19+ messages in thread
From: Anton Blanchard @ 2009-05-26 4:31 UTC (permalink / raw)
To: rostedt, mingo, tzanussi, jbaron, tglx, fweisbec, kosaki.motohiro
Cc: linux-kernel
Keep a common naming convention for tracing the latency of events such as
softirq_entry/softirq_exit.
Signed-off-by: Anton Blanchard <anton@samba.org>
---
What do people think? It seems like a good idea to have a naming convention
when tracing event latency for softirqs, timers, worklets, etc.
Index: linux-2.6-master/include/trace/events/workqueue.h
===================================================================
--- linux-2.6-master.orig/include/trace/events/workqueue.h 2009-05-26 12:40:01.000000000 +1000
+++ linux-2.6-master/include/trace/events/workqueue.h 2009-05-26 12:40:16.000000000 +1000
@@ -68,7 +68,7 @@
__entry->cpu, __entry->delay)
);
-TRACE_EVENT(worklet_execute,
+TRACE_EVENT(worklet_entry,
TP_PROTO(struct task_struct *wq_thread, struct work_struct *work),
@@ -93,7 +93,7 @@
);
/* Declare work as void *, because we can't use work->... in after f(work) */
-TRACE_EVENT(worklet_complete,
+TRACE_EVENT(worklet_exit,
TP_PROTO(struct task_struct *wq_thread, void *work),
TP_ARGS(wq_thread, work),
Index: linux-2.6-master/kernel/trace/trace_workqueue.c
===================================================================
--- linux-2.6-master.orig/kernel/trace/trace_workqueue.c 2009-05-26 12:43:27.000000000 +1000
+++ linux-2.6-master/kernel/trace/trace_workqueue.c 2009-05-26 12:43:36.000000000 +1000
@@ -27,7 +27,7 @@
/*
* save latest work_struct's pointer to use as identifier in
- * probe_worklet_complete, because we can't use work_struct->...
+ * probe_worklet_exit, because we can't use work_struct->...
* after worklet got executed
*/
void *work;
@@ -141,7 +141,7 @@
/* Execution of a work */
static void
-probe_worklet_execute(struct task_struct *wq_thread, struct work_struct *work)
+probe_worklet_entry(struct task_struct *wq_thread, struct work_struct *work)
{
int cpu = cpumask_first(&wq_thread->cpus_allowed);
struct cpu_workqueue_stats *node;
@@ -176,7 +176,7 @@
/* Complete of a work */
static void
-probe_worklet_complete(struct task_struct *wq_thread, void *work)
+probe_worklet_exit(struct task_struct *wq_thread, void *work)
{
int cpu = cpumask_first(&wq_thread->cpus_allowed);
struct cpu_workqueue_stats *node;
@@ -504,17 +504,17 @@
if (ret)
goto out_worklet_enqueue;
- ret = register_trace_worklet_execute(probe_worklet_execute);
+ ret = register_trace_worklet_entry(probe_worklet_entry);
if (ret)
goto out_worklet_enqueue_delayed;
- ret = register_trace_worklet_complete(probe_worklet_complete);
+ ret = register_trace_worklet_exit(probe_worklet_exit);
if (ret)
- goto out_worklet_execute;
+ goto out_worklet_entry;
ret = register_trace_workqueue_creation(probe_workqueue_creation);
if (ret)
- goto out_worklet_complete;
+ goto out_worklet_exit;
ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
if (ret)
@@ -529,10 +529,10 @@
out_workqueue_creation:
unregister_trace_workqueue_creation(probe_workqueue_creation);
-out_worklet_complete:
- unregister_trace_worklet_complete(probe_worklet_complete);
-out_worklet_execute:
- unregister_trace_worklet_execute(probe_worklet_execute);
+out_worklet_exit:
+ unregister_trace_worklet_exit(probe_worklet_exit);
+out_worklet_entry:
+ unregister_trace_worklet_entry(probe_worklet_entry);
out_worklet_enqueue_delayed:
unregister_trace_worklet_enqueue_delayed(probe_worklet_enqueue_delayed);
out_worklet_enqueue:
Index: linux-2.6-master/kernel/workqueue.c
===================================================================
--- linux-2.6-master.orig/kernel/workqueue.c 2009-05-26 12:43:59.000000000 +1000
+++ linux-2.6-master/kernel/workqueue.c 2009-05-26 12:44:01.000000000 +1000
@@ -296,9 +296,9 @@
work_clear_pending(work);
lock_map_acquire(&cwq->wq->lockdep_map);
lock_map_acquire(&lockdep_map);
- trace_worklet_execute(cwq->thread, work);
+ trace_worklet_entry(cwq->thread, work);
f(work);
- trace_worklet_complete(cwq->thread, work);
+ trace_worklet_exit(cwq->thread, work);
lock_map_release(&lockdep_map);
lock_map_release(&cwq->wq->lockdep_map);
Index: linux-2.6-master/Documentation/trace/workqueue.txt
===================================================================
--- linux-2.6-master.orig/Documentation/trace/workqueue.txt 2009-05-26 12:44:44.000000000 +1000
+++ linux-2.6-master/Documentation/trace/workqueue.txt 2009-05-26 12:45:05.000000000 +1000
@@ -98,8 +98,8 @@
# mount -t debugfs debug /sys/kernel/debug/
# cd /sys/kernel/debug/tracing/events/workqueue
# ls
-filter worklet_complete worklet_enqueue_delayed workqueue_creation workqueue_flush
-worklet_cancel worklet_enqueue worklet_execute workqueue_destruction
+filter worklet_exit worklet_enqueue_delayed workqueue_creation workqueue_flush
+worklet_cancel worklet_enqueue worklet_entry workqueue_destruction
# for e in $(ls); do echo 1 > $e/enable; done
# cat /sys/kernel/debug/tracing/trace
@@ -108,7 +108,7 @@
# | | | | |
<...>-5627 [000] 4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task+0x0/0x280 cpu=0
-<...>-508 [000] 4597.858660: worklet_execute: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
-<...>-508 [000] 4597.858684: worklet_complete: thread=ata/0:508 work=ffff88007e9e67b8
+<...>-508 [000] 4597.858660: worklet_entry: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
+<...>-508 [000] 4597.858684: worklet_exit: thread=ata/0:508 work=ffff88007e9e67b8
<...>-2437 [000] 4597.861259: worklet_cancel: func=ata_pio_task+0x0/0x280
[...]
^ permalink raw reply [flat|nested] 19+ messages in thread
* [PATCH] tracing/events: Use %pf in workqueue trace events
2009-05-26 4:31 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Anton Blanchard
@ 2009-05-26 4:32 ` Anton Blanchard
2009-05-26 4:36 ` tracing/events: Add tasklet tracepoints Anton Blanchard
2009-05-29 13:16 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Frédéric Weisbecker
1 sibling, 1 reply; 19+ messages in thread
From: Anton Blanchard @ 2009-05-26 4:32 UTC (permalink / raw)
To: rostedt, mingo, tzanussi, jbaron, tglx, fweisbec, kosaki.motohiro
Cc: linux-kernel
Using %pf instead of %pF supresses printing of the function offset
which will always be 0.
Signed-off-by: Anton Blanchard <anton@samba.org>
---
Index: linux-2.6-master/include/trace/events/workqueue.h
===================================================================
--- linux-2.6-master.orig/include/trace/events/workqueue.h 2009-05-26 12:55:37.000000000 +1000
+++ linux-2.6-master/include/trace/events/workqueue.h 2009-05-26 12:55:44.000000000 +1000
@@ -32,7 +32,7 @@
__entry->cpu = cpu;
),
- TP_printk("thread=%s:%d func=%pF cpu=%d", __entry->thread_comm,
+ TP_printk("thread=%s:%d func=%pf cpu=%d", __entry->thread_comm,
__entry->thread_pid, __entry->func, __entry->cpu)
);
@@ -63,7 +63,7 @@
__entry->delay = delay;
),
- TP_printk("thread=%s:%d func=%pF cpu=%d delay=%lu",
+ TP_printk("thread=%s:%d func=%pf cpu=%d delay=%lu",
__entry->thread_comm, __entry->thread_pid, __entry->func,
__entry->cpu, __entry->delay)
);
@@ -88,7 +88,7 @@
__entry->func = work->func;
),
- TP_printk("thread=%s:%d work=%p func=%pF", __entry->thread_comm,
+ TP_printk("thread=%s:%d work=%p func=%pf", __entry->thread_comm,
__entry->thread_pid, __entry->work, __entry->func)
);
@@ -128,7 +128,7 @@
__entry->func = work->func;
),
- TP_printk("func=%pF", __entry->func)
+ TP_printk("func=%pf", __entry->func)
);
/* Trace the creation of one workqueue thread on a cpu */
Index: linux-2.6-master/Documentation/trace/workqueue.txt
===================================================================
--- linux-2.6-master.orig/Documentation/trace/workqueue.txt 2009-05-26 12:55:52.000000000 +1000
+++ linux-2.6-master/Documentation/trace/workqueue.txt 2009-05-26 12:56:14.000000000 +1000
@@ -107,8 +107,8 @@
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
-<...>-5627 [000] 4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task+0x0/0x280 cpu=0
-<...>-508 [000] 4597.858660: worklet_entry: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
+<...>-5627 [000] 4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task cpu=0
+<...>-508 [000] 4597.858660: worklet_entry: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task
<...>-508 [000] 4597.858684: worklet_exit: thread=ata/0:508 work=ffff88007e9e67b8
-<...>-2437 [000] 4597.861259: worklet_cancel: func=ata_pio_task+0x0/0x280
+<...>-2437 [000] 4597.861259: worklet_cancel: func=ata_pio_task
[...]
^ permalink raw reply [flat|nested] 19+ messages in thread
* tracing/events: Add tasklet tracepoints
2009-05-26 4:32 ` [PATCH] tracing/events: Use %pf in workqueue trace events Anton Blanchard
@ 2009-05-26 4:36 ` Anton Blanchard
0 siblings, 0 replies; 19+ messages in thread
From: Anton Blanchard @ 2009-05-26 4:36 UTC (permalink / raw)
To: rostedt, mingo, tzanussi, jbaron, tglx, fweisbec, kosaki.motohiro
Cc: linux-kernel
Add tracepoints for tasklets. We add entry and exit tracepoints so we can
calculate tasklet latency.
Example ftrace output:
<idle>-0 [000] 327.349213: tasklet_entry: func=.rpavscsi_task
<idle>-0 [000] 327.349217: tasklet_exit: func=.rpavscsi_task
Signed-off-by: Anton Blanchard <anton@samba.org>
---
Index: linux-2.6-master/kernel/softirq.c
===================================================================
--- linux-2.6-master.orig/kernel/softirq.c 2009-05-26 13:56:58.000000000 +1000
+++ linux-2.6-master/kernel/softirq.c 2009-05-26 13:57:46.000000000 +1000
@@ -412,7 +412,9 @@
if (!atomic_read(&t->count)) {
if (!test_and_clear_bit(TASKLET_STATE_SCHED, &t->state))
BUG();
+ trace_tasklet_entry(t);
t->func(t->data);
+ trace_tasklet_exit(t);
tasklet_unlock(t);
continue;
}
@@ -447,7 +449,9 @@
if (!atomic_read(&t->count)) {
if (!test_and_clear_bit(TASKLET_STATE_SCHED, &t->state))
BUG();
+ trace_tasklet_entry(t);
t->func(t->data);
+ trace_tasklet_exit(t);
tasklet_unlock(t);
continue;
}
Index: linux-2.6-master/include/trace/events/irq.h
===================================================================
--- linux-2.6-master.orig/include/trace/events/irq.h 2009-05-26 13:56:58.000000000 +1000
+++ linux-2.6-master/include/trace/events/irq.h 2009-05-26 14:35:09.000000000 +1000
@@ -128,6 +128,54 @@
TP_printk("softirq=%d action=%s", __entry->vec, __get_str(name))
);
+/**
+ * tasklet_entry - called immediately before the tasklet handler
+ * @t: pointer to struct tasklet_struct
+ *
+ * When used in combination with the tasklet_exit tracepoint we can
+ * determine the tasklet latency.
+ */
+TRACE_EVENT(tasklet_entry,
+
+ TP_PROTO(struct tasklet_struct *t),
+
+ TP_ARGS(t),
+
+ TP_STRUCT__entry(
+ __field(void *, func)
+ ),
+
+ TP_fast_assign(
+ __entry->func = t->func;
+ ),
+
+ TP_printk("func=%pf", __entry->func)
+);
+
+/**
+ * tasklet_exit - called immediately after the tasklet handler returns
+ * @t: pointer to struct tasklet_struct
+ *
+ * When used in combination with the tasklet_entry tracepoint we can
+ * determine the tasklet latency.
+ */
+TRACE_EVENT(tasklet_exit,
+
+ TP_PROTO(struct tasklet_struct *t),
+
+ TP_ARGS(t),
+
+ TP_STRUCT__entry(
+ __field(void *, func)
+ ),
+
+ TP_fast_assign(
+ __entry->func = t->func;
+ ),
+
+ TP_printk("func=%pf", __entry->func)
+);
+
#endif /* _TRACE_IRQ_H */
/* This part must be outside protection */
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit
2009-05-26 4:31 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Anton Blanchard
2009-05-26 4:32 ` [PATCH] tracing/events: Use %pf in workqueue trace events Anton Blanchard
@ 2009-05-29 13:16 ` Frédéric Weisbecker
1 sibling, 0 replies; 19+ messages in thread
From: Frédéric Weisbecker @ 2009-05-29 13:16 UTC (permalink / raw)
To: Anton Blanchard, Zhaolei
Cc: rostedt, mingo, tzanussi, jbaron, tglx, kosaki.motohiro, linux-kernel
Hi Anton, Zhaolei,
You tracing/workqueues patches look good and I've tested them succesfully.
I will apply them soon, thanks!
2009/5/26 Anton Blanchard <anton@samba.org>:
>
> Keep a common naming convention for tracing the latency of events such as
> softirq_entry/softirq_exit.
>
> Signed-off-by: Anton Blanchard <anton@samba.org>
> ---
>
> What do people think? It seems like a good idea to have a naming convention
> when tracing event latency for softirqs, timers, worklets, etc.
>
> Index: linux-2.6-master/include/trace/events/workqueue.h
> ===================================================================
> --- linux-2.6-master.orig/include/trace/events/workqueue.h 2009-05-26 12:40:01.000000000 +1000
> +++ linux-2.6-master/include/trace/events/workqueue.h 2009-05-26 12:40:16.000000000 +1000
> @@ -68,7 +68,7 @@
> __entry->cpu, __entry->delay)
> );
>
> -TRACE_EVENT(worklet_execute,
> +TRACE_EVENT(worklet_entry,
>
> TP_PROTO(struct task_struct *wq_thread, struct work_struct *work),
>
> @@ -93,7 +93,7 @@
> );
>
> /* Declare work as void *, because we can't use work->... in after f(work) */
> -TRACE_EVENT(worklet_complete,
> +TRACE_EVENT(worklet_exit,
> TP_PROTO(struct task_struct *wq_thread, void *work),
>
> TP_ARGS(wq_thread, work),
> Index: linux-2.6-master/kernel/trace/trace_workqueue.c
> ===================================================================
> --- linux-2.6-master.orig/kernel/trace/trace_workqueue.c 2009-05-26 12:43:27.000000000 +1000
> +++ linux-2.6-master/kernel/trace/trace_workqueue.c 2009-05-26 12:43:36.000000000 +1000
> @@ -27,7 +27,7 @@
>
> /*
> * save latest work_struct's pointer to use as identifier in
> - * probe_worklet_complete, because we can't use work_struct->...
> + * probe_worklet_exit, because we can't use work_struct->...
> * after worklet got executed
> */
> void *work;
> @@ -141,7 +141,7 @@
>
> /* Execution of a work */
> static void
> -probe_worklet_execute(struct task_struct *wq_thread, struct work_struct *work)
> +probe_worklet_entry(struct task_struct *wq_thread, struct work_struct *work)
> {
> int cpu = cpumask_first(&wq_thread->cpus_allowed);
> struct cpu_workqueue_stats *node;
> @@ -176,7 +176,7 @@
>
> /* Complete of a work */
> static void
> -probe_worklet_complete(struct task_struct *wq_thread, void *work)
> +probe_worklet_exit(struct task_struct *wq_thread, void *work)
> {
> int cpu = cpumask_first(&wq_thread->cpus_allowed);
> struct cpu_workqueue_stats *node;
> @@ -504,17 +504,17 @@
> if (ret)
> goto out_worklet_enqueue;
>
> - ret = register_trace_worklet_execute(probe_worklet_execute);
> + ret = register_trace_worklet_entry(probe_worklet_entry);
> if (ret)
> goto out_worklet_enqueue_delayed;
>
> - ret = register_trace_worklet_complete(probe_worklet_complete);
> + ret = register_trace_worklet_exit(probe_worklet_exit);
> if (ret)
> - goto out_worklet_execute;
> + goto out_worklet_entry;
>
> ret = register_trace_workqueue_creation(probe_workqueue_creation);
> if (ret)
> - goto out_worklet_complete;
> + goto out_worklet_exit;
>
> ret = register_trace_workqueue_destruction(probe_workqueue_destruction);
> if (ret)
> @@ -529,10 +529,10 @@
>
> out_workqueue_creation:
> unregister_trace_workqueue_creation(probe_workqueue_creation);
> -out_worklet_complete:
> - unregister_trace_worklet_complete(probe_worklet_complete);
> -out_worklet_execute:
> - unregister_trace_worklet_execute(probe_worklet_execute);
> +out_worklet_exit:
> + unregister_trace_worklet_exit(probe_worklet_exit);
> +out_worklet_entry:
> + unregister_trace_worklet_entry(probe_worklet_entry);
> out_worklet_enqueue_delayed:
> unregister_trace_worklet_enqueue_delayed(probe_worklet_enqueue_delayed);
> out_worklet_enqueue:
> Index: linux-2.6-master/kernel/workqueue.c
> ===================================================================
> --- linux-2.6-master.orig/kernel/workqueue.c 2009-05-26 12:43:59.000000000 +1000
> +++ linux-2.6-master/kernel/workqueue.c 2009-05-26 12:44:01.000000000 +1000
> @@ -296,9 +296,9 @@
> work_clear_pending(work);
> lock_map_acquire(&cwq->wq->lockdep_map);
> lock_map_acquire(&lockdep_map);
> - trace_worklet_execute(cwq->thread, work);
> + trace_worklet_entry(cwq->thread, work);
> f(work);
> - trace_worklet_complete(cwq->thread, work);
> + trace_worklet_exit(cwq->thread, work);
> lock_map_release(&lockdep_map);
> lock_map_release(&cwq->wq->lockdep_map);
>
> Index: linux-2.6-master/Documentation/trace/workqueue.txt
> ===================================================================
> --- linux-2.6-master.orig/Documentation/trace/workqueue.txt 2009-05-26 12:44:44.000000000 +1000
> +++ linux-2.6-master/Documentation/trace/workqueue.txt 2009-05-26 12:45:05.000000000 +1000
> @@ -98,8 +98,8 @@
> # mount -t debugfs debug /sys/kernel/debug/
> # cd /sys/kernel/debug/tracing/events/workqueue
> # ls
> -filter worklet_complete worklet_enqueue_delayed workqueue_creation workqueue_flush
> -worklet_cancel worklet_enqueue worklet_execute workqueue_destruction
> +filter worklet_exit worklet_enqueue_delayed workqueue_creation workqueue_flush
> +worklet_cancel worklet_enqueue worklet_entry workqueue_destruction
> # for e in $(ls); do echo 1 > $e/enable; done
> # cat /sys/kernel/debug/tracing/trace
>
> @@ -108,7 +108,7 @@
> # | | | | |
>
> <...>-5627 [000] 4597.858645: worklet_enqueue: thread=ata/0:508 func=ata_pio_task+0x0/0x280 cpu=0
> -<...>-508 [000] 4597.858660: worklet_execute: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
> -<...>-508 [000] 4597.858684: worklet_complete: thread=ata/0:508 work=ffff88007e9e67b8
> +<...>-508 [000] 4597.858660: worklet_entry: thread=ata/0:508 work=ffff88007e9e67b8 func=ata_pio_task+0x0/0x280
> +<...>-508 [000] 4597.858684: worklet_exit: thread=ata/0:508 work=ffff88007e9e67b8
> <...>-2437 [000] 4597.861259: worklet_cancel: func=ata_pio_task+0x0/0x280
> [...]
>
^ permalink raw reply [flat|nested] 19+ messages in thread
* [PATCH v3] tracing/events: Add timer and high res timer tracepoints
2009-05-26 4:26 ` Anton Blanchard
2009-05-26 4:31 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Anton Blanchard
@ 2009-05-26 4:55 ` Anton Blanchard
2009-05-26 18:06 ` [PATCH] " Frederic Weisbecker
2 siblings, 0 replies; 19+ messages in thread
From: Anton Blanchard @ 2009-05-26 4:55 UTC (permalink / raw)
To: rostedt, mingo, tzanussi, jbaron, tglx, fweisbec, kosaki.motohiro
Cc: linux-kernel
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
<idle>-0 [000] 264.040508: hrtimer_exit: func=.tick_sched_timer restart=HRTIMER_RESTART
<idle>-0 [000] 264.040530: timer_entry: func=.e1000_watchdog
<idle>-0 [000] 264.040728: timer_exit: func=.e1000_watchdog
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@samba.org>
Acked-by: Thomas Gleixner <tglx@linutronix.de>
---
v2: Changed %pF to %pf to remove always 0 function offset.
v3: Patch was corrupted, must be vi and my fat fingers.
Index: linux-2.6-master/kernel/hrtimer.c
===================================================================
--- linux-2.6-master.orig/kernel/hrtimer.c 2009-05-26 12:55:35.000000000 +1000
+++ linux-2.6-master/kernel/hrtimer.c 2009-05-26 13:09:55.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-master/kernel/timer.c
===================================================================
--- linux-2.6-master.orig/kernel/timer.c 2009-05-26 12:55:35.000000000 +1000
+++ linux-2.6-master/kernel/timer.c 2009-05-26 13:09:55.000000000 +1000
@@ -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);
@@ -947,7 +950,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-master/include/trace/events/timer.h
===================================================================
--- /dev/null 1970-01-01 00:00:00.000000000 +0000
+++ linux-2.6-master/include/trace/events/timer.h 2009-05-26 13:57:42.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)
+ ),
+
+ TP_fast_assign(
+ __entry->function = timer->function;
+ ),
+
+ TP_printk("func=%pf", __entry->function)
+);
+
+/**
+ * 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>
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-26 4:26 ` Anton Blanchard
2009-05-26 4:31 ` [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit Anton Blanchard
2009-05-26 4:55 ` [PATCH v3] tracing/events: Add timer and high res timer tracepoints Anton Blanchard
@ 2009-05-26 18:06 ` Frederic Weisbecker
2009-05-27 9:28 ` Xiao Guangrong
2009-05-27 13:46 ` [PATCH] tracing/events: Add timer and high res timer tracepoints Thomas Gleixner
2 siblings, 2 replies; 19+ messages in thread
From: Frederic Weisbecker @ 2009-05-26 18:06 UTC (permalink / raw)
To: Anton Blanchard
Cc: rostedt, mingo, tzanussi, jbaron, tglx, kosaki.motohiro, linux-kernel
On Tue, May 26, 2009 at 02:26:43PM +1000, Anton Blanchard wrote:
>
> Add tracepoints for timer and high res timer execution. We add entry and
> exit tracepoints so we can calculate timer latency.
Your work looks very similar to Xiao Guangrong's patches.
See:
ftrace: add tracepoint for timer
ftrace: add tracepoint for itimer
ftrace: add tracepoint for hrimer
I'm not sure which one should be picked between
his patches and yours.
Frederic.
> Example ftrace output:
>
> <idle>-0 [000] 264.040506: hrtimer_entry: func=.tick_sched_timer
> <idle>-0 [000] 264.040508: hrtimer_exit: func=.tick_sched_timer restart=HRTIMER_RESTART
> <idle>-0 [000] 264.040530: timer_entry: func=.e1000_watchdog
> <idle>-0 [000] 264.040728: timer_exit: func=.e1000_watchdog
>
> 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@samba.org>
> Acked-by: Thomas Gleixner <tglx@linutronix.de>
> ---
>
> v2: Changed %pF to %pf to remove always 0 function offset.
>
> Index: linux-2.6-master/kernel/hrtimer.c
> ===================================================================
> --- linux-2.6-master.orig/kernel/hrtimer.c 2009-05-26 12:55:35.000000000 +1000
> +++ linux-2.6-master/kernel/hrtimer.c 2009-05-26 13:09:55.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-master/kernel/timer.c
> ===================================================================
> --- linux-2.6-master.orig/kernel/timer.c 2009-05-26 12:55:35.000000000 +1000
> +++ linux-2.6-master/kernel/timer.c 2009-05-26 13:09:55.000000000 +1000
> @@ -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);
> @@ -947,7 +950,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-master/include/trace/events/timer.h
> ===================================================================
> --- /dev/null 1970-01-01 00:00:00.000000000 +0000
> +++ linux-2.6-master/include/trace/events/timer.h 2009-05-26 13:57:42.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)
> + ),
> +
> + TP_fast_assign(
> + __entry->function = timer->function;
> + ),
> +
> + TP_printk("func=%pf", __entry->function)
> +);
> +
> +/**
> + * 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>
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-26 18:06 ` [PATCH] " Frederic Weisbecker
@ 2009-05-27 9:28 ` Xiao Guangrong
2009-05-27 14:22 ` Thomas Gleixner
2009-05-27 13:46 ` [PATCH] tracing/events: Add timer and high res timer tracepoints Thomas Gleixner
1 sibling, 1 reply; 19+ messages in thread
From: Xiao Guangrong @ 2009-05-27 9:28 UTC (permalink / raw)
To: Frederic Weisbecker
Cc: Anton Blanchard, rostedt, mingo, tzanussi, jbaron, tglx,
kosaki.motohiro, linux-kernel
Frederic Weisbecker wrote:
> On Tue, May 26, 2009 at 02:26:43PM +1000, Anton Blanchard wrote:
>> Add tracepoints for timer and high res timer execution. We add entry and
>> exit tracepoints so we can calculate timer latency.
>
>
> Your work looks very similar to Xiao Guangrong's patches.
>
> See:
>
> ftrace: add tracepoint for timer
> ftrace: add tracepoint for itimer
> ftrace: add tracepoint for hrimer
>
> I'm not sure which one should be picked between
> his patches and yours.
>
Hi Frederic:
In fact, Anton Blanchard's is different from my patch.
My patch is used for trace timer lifecycle(init/start/expire/cancel), and his
patch is mostly used for trace the execution time of timer function.
Thanks,
Xiao Guangrong
> Frederic.
>
>
>> Example ftrace output:
>>
>> <idle>-0 [000] 264.040506: hrtimer_entry: func=.tick_sched_timer
>> <idle>-0 [000] 264.040508: hrtimer_exit: func=.tick_sched_timer restart=HRTIMER_RESTART
>> <idle>-0 [000] 264.040530: timer_entry: func=.e1000_watchdog
>> <idle>-0 [000] 264.040728: timer_exit: func=.e1000_watchdog
>>
>> 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@samba.org>
>> Acked-by: Thomas Gleixner <tglx@linutronix.de>
>> ---
>>
>> v2: Changed %pF to %pf to remove always 0 function offset.
>>
>> Index: linux-2.6-master/kernel/hrtimer.c
>> ===================================================================
>> --- linux-2.6-master.orig/kernel/hrtimer.c 2009-05-26 12:55:35.000000000 +1000
>> +++ linux-2.6-master/kernel/hrtimer.c 2009-05-26 13:09:55.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-master/kernel/timer.c
>> ===================================================================
>> --- linux-2.6-master.orig/kernel/timer.c 2009-05-26 12:55:35.000000000 +1000
>> +++ linux-2.6-master/kernel/timer.c 2009-05-26 13:09:55.000000000 +1000
>> @@ -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);
>> @@ -947,7 +950,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-master/include/trace/events/timer.h
>> ===================================================================
>> --- /dev/null 1970-01-01 00:00:00.000000000 +0000
>> +++ linux-2.6-master/include/trace/events/timer.h 2009-05-26 13:57:42.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)
>> + ),
>> +
>> + TP_fast_assign(
>> + __entry->function = timer->function;
>> + ),
>> +
>> + TP_printk("func=%pf", __entry->function)
>> +);
>> +
>> +/**
>> + * 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@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
>
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-27 9:28 ` Xiao Guangrong
@ 2009-05-27 14:22 ` Thomas Gleixner
2009-05-27 14:48 ` Frederic Weisbecker
0 siblings, 1 reply; 19+ messages in thread
From: Thomas Gleixner @ 2009-05-27 14:22 UTC (permalink / raw)
To: Xiao Guangrong
Cc: Frederic Weisbecker, Anton Blanchard, rostedt, mingo, tzanussi,
jbaron, kosaki.motohiro, linux-kernel
On Wed, 27 May 2009, Xiao Guangrong wrote:
> In fact, Anton Blanchard's is different from my patch.
> My patch is used for trace timer lifecycle(init/start/expire/cancel), and his
> patch is mostly used for trace the execution time of timer function.
Right, but they should be combined into one set.
Frederic, can you please pick up Anton's patch right away so Xiao can
work on top of it and add the init/start/cancel instrumentation.
Thanks,
tglx
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-27 14:22 ` Thomas Gleixner
@ 2009-05-27 14:48 ` Frederic Weisbecker
2009-05-29 0:55 ` [PATCH] tracing/events: Add timer and high res timertracepoints Zhaolei
0 siblings, 1 reply; 19+ messages in thread
From: Frederic Weisbecker @ 2009-05-27 14:48 UTC (permalink / raw)
To: Thomas Gleixner
Cc: Xiao Guangrong, Anton Blanchard, rostedt, mingo, tzanussi,
jbaron, kosaki.motohiro, linux-kernel
On Wed, May 27, 2009 at 04:22:28PM +0200, Thomas Gleixner wrote:
> On Wed, 27 May 2009, Xiao Guangrong wrote:
> > In fact, Anton Blanchard's is different from my patch.
> > My patch is used for trace timer lifecycle(init/start/expire/cancel), and his
> > patch is mostly used for trace the execution time of timer function.
>
> Right, but they should be combined into one set.
Ok.
> Frederic, can you please pick up Anton's patch right away so Xiao can
> work on top of it and add the init/start/cancel instrumentation.
>
> Thanks,
>
> tglx
Sure. I've applied it on
git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/timer
Xiao can work on top of it.
This is a branch made against tip:/tracing/core
Frederic.
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timertracepoints
2009-05-27 14:48 ` Frederic Weisbecker
@ 2009-05-29 0:55 ` Zhaolei
0 siblings, 0 replies; 19+ messages in thread
From: Zhaolei @ 2009-05-29 0:55 UTC (permalink / raw)
To: Frederic Weisbecker, Thomas Gleixner
Cc: Xiao Guangrong, Anton Blanchard, rostedt, mingo, tzanussi,
jbaron, kosaki.motohiro, linux-kernel
* From: "Frederic Weisbecker" <fweisbec@gmail.com>
> On Wed, May 27, 2009 at 04:22:28PM +0200, Thomas Gleixner wrote:
>> On Wed, 27 May 2009, Xiao Guangrong wrote:
>> > In fact, Anton Blanchard's is different from my patch.
>> > My patch is used for trace timer lifecycle(init/start/expire/cancel), and his
>> > patch is mostly used for trace the execution time of timer function.
>>
>> Right, but they should be combined into one set.
>
>
> Ok.
>
>
>> Frederic, can you please pick up Anton's patch right away so Xiao can
>> work on top of it and add the init/start/cancel instrumentation.
>>
>> Thanks,
>>
>> tglx
>
>
> Sure. I've applied it on
> git://git.kernel.org/pub/scm/linux/kernel/git/frederic/random-tracing.git tracing/timer
>
> Xiao can work on top of it.
> This is a branch made against tip:/tracing/core
Hello, Frederic
We'll rebase our patch on it.
Thanks
Zhaolei
>
> Frederic.
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
>ÿôèº{.nÇ+·®+%Ëÿ±éݶ\x17¥wÿº{.nÇ+·¥{±þG«éÿ{ayº\x1dÊÚë,j\a¢f£¢·hïêÿêçz_è®\x03(éÝ¢j"ú\x1a¶^[m§ÿÿ¾\a«þG«éÿ¢¸?¨èÚ&£ø§~á¶iOæ¬z·vØ^\x14\x04\x1a¶^[m§ÿÿÃ\fÿ¶ìÿ¢¸?I¥
^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: [PATCH] tracing/events: Add timer and high res timer tracepoints
2009-05-26 18:06 ` [PATCH] " Frederic Weisbecker
2009-05-27 9:28 ` Xiao Guangrong
@ 2009-05-27 13:46 ` Thomas Gleixner
1 sibling, 0 replies; 19+ messages in thread
From: Thomas Gleixner @ 2009-05-27 13:46 UTC (permalink / raw)
To: Frederic Weisbecker
Cc: Anton Blanchard, rostedt, mingo, tzanussi, jbaron,
kosaki.motohiro, linux-kernel
On Tue, 26 May 2009, Frederic Weisbecker wrote:
> On Tue, May 26, 2009 at 02:26:43PM +1000, Anton Blanchard wrote:
> >
> > Add tracepoints for timer and high res timer execution. We add entry and
> > exit tracepoints so we can calculate timer latency.
>
>
> Your work looks very similar to Xiao Guangrong's patches.
>
> See:
>
> ftrace: add tracepoint for timer
> ftrace: add tracepoint for itimer
> ftrace: add tracepoint for hrimer
>
> I'm not sure which one should be picked between
> his patches and yours.
Actually we want a combination of both.
Thanks,
tglx
^ permalink raw reply [flat|nested] 19+ messages in thread