[PATCH] tracing/events: Add timer and high res timer tracepoints

[PATCH] tracing/events: Add timer and high res timer tracepoints

[Anton Blanchard]

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)
+	),
+
+	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>

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[KOSAKI Motohiro]

> 
> 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/

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Thomas Gleixner]

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>

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Frédéric Weisbecker]

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/
>

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Steven Rostedt]

[-- 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

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Anton Blanchard]

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

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Frederic Weisbecker]

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..?

[PATCH] tracing/events: Add timer and high res timer tracepoints

[Anton Blanchard]

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>

[PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit

[Anton Blanchard]

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
 [...]

[PATCH] tracing/events: Use %pf in workqueue trace events

[Anton Blanchard]

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
 [...]

tracing/events: Add tasklet tracepoints

[Anton Blanchard]

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 */

[PATCH v3] tracing/events: Add timer and high res timer tracepoints

[Anton Blanchard]

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>

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Frederic Weisbecker]

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>

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Xiao Guangrong]

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/
> 
> 

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Thomas Gleixner]

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

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Thomas Gleixner]

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

Re: [PATCH] tracing/events: Add timer and high res timer tracepoints

[Frederic Weisbecker]

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.

Re: [PATCH] tracing/events: Add timer and high res timertracepoints

[Zhaolei]

* 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¥

Re: [PATCH] tracing/events: Rename worklet_execute to worklet_entry and worklet_complete to worklet_exit

[Frédéric Weisbecker]

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
>  [...]
>