[Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Jason Baron]

introduce softirq entry/exit tracepoints. These are useful for
augmenting existing tracers, and to figure out softirq frequencies and
timings.

Signed-off-by: Jason Baron <jbaron@redhat.com>

---

 include/trace/irq_event_types.h |   12 ++++++++++++
 kernel/softirq.c                |    7 ++++++-
 2 files changed, 18 insertions(+), 1 deletions(-)


diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 214bb92..38b4bdd 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
 		  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
+TRACE_FORMAT(irq_softirq_entry,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
+	);
+
+TRACE_FORMAT(irq_softirq_exit,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
+	);
+
 #undef TRACE_SYSTEM
diff --git a/kernel/softirq.c b/kernel/softirq.c
index ba1511f..c378d53 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -24,6 +24,7 @@
 #include <linux/ftrace.h>
 #include <linux/smp.h>
 #include <linux/tick.h>
+#include <trace/irq.h>
 
 #include <asm/irq.h>
 /*
@@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
  */
 #define MAX_SOFTIRQ_RESTART 10
 
+DEFINE_TRACE(irq_softirq_entry);
+DEFINE_TRACE(irq_softirq_exit);
+
 asmlinkage void __do_softirq(void)
 {
 	struct softirq_action *h;
@@ -212,8 +216,9 @@ restart:
 		if (pending & 1) {
 			int prev_count = preempt_count();
 
+			trace_irq_softirq_entry(h, softirq_vec);
 			h->action(h);
-
+			trace_irq_softirq_exit(h, softirq_vec);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Frederic Weisbecker]

On Thu, Mar 12, 2009 at 02:36:03PM -0400, Jason Baron wrote:
> 
> introduce softirq entry/exit tracepoints. These are useful for
> augmenting existing tracers, and to figure out softirq frequencies and
> timings.
> 
> Signed-off-by: Jason Baron <jbaron@redhat.com>
> 
> ---
> 
>  include/trace/irq_event_types.h |   12 ++++++++++++
>  kernel/softirq.c                |    7 ++++++-
>  2 files changed, 18 insertions(+), 1 deletions(-)
> 
> 
> diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> index 214bb92..38b4bdd 100644
> --- a/include/trace/irq_event_types.h
> +++ b/include/trace/irq_event_types.h
> @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
>  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
>  );
>  
> +TRACE_FORMAT(irq_softirq_entry,
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +	TP_ARGS(h, vec),
> +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> +	);
> +
> +TRACE_FORMAT(irq_softirq_exit,
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +	TP_ARGS(h, vec),
> +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> +	);
> +
>  #undef TRACE_SYSTEM
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index ba1511f..c378d53 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -24,6 +24,7 @@
>  #include <linux/ftrace.h>
>  #include <linux/smp.h>
>  #include <linux/tick.h>
> +#include <trace/irq.h>
>  
>  #include <asm/irq.h>
>  /*
> @@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
>   */
>  #define MAX_SOFTIRQ_RESTART 10
>  
> +DEFINE_TRACE(irq_softirq_entry);
> +DEFINE_TRACE(irq_softirq_exit);


Just one nit here. The "irq_" prefix seems to me too much.
On the trace we have:

/* irq_softirq_entry: softirq=nb action=nb_to_logical_name */

It's even too much words that says the same things.
Moreover, we have the logical name, the number seems not very useful
because we have its logical translation just after.

I would suggest to have just:

/* softirq_entry: nb_to_logical_name */

ie:

/* softirq_entry: SCHED_SOFTIRQ */

Don't you think it's more clear and obvious?

Other than that, I think these tracepoints are a good idea.


>  asmlinkage void __do_softirq(void)
>  {
>  	struct softirq_action *h;
> @@ -212,8 +216,9 @@ restart:
>  		if (pending & 1) {
>  			int prev_count = preempt_count();
>  
> +			trace_irq_softirq_entry(h, softirq_vec);
>  			h->action(h);
> -
> +			trace_irq_softirq_exit(h, softirq_vec);
>  			if (unlikely(prev_count != preempt_count())) {
>  				printk(KERN_ERR "huh, entered softirq %td %s %p"
>  				       "with preempt_count %08x,"

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Ingo Molnar]

* Frederic Weisbecker <fweisbec@gmail.com> wrote:

> On Thu, Mar 12, 2009 at 02:36:03PM -0400, Jason Baron wrote:
> > 
> > introduce softirq entry/exit tracepoints. These are useful for
> > augmenting existing tracers, and to figure out softirq frequencies and
> > timings.
> > 
> > Signed-off-by: Jason Baron <jbaron@redhat.com>
> > 
> > ---
> > 
> >  include/trace/irq_event_types.h |   12 ++++++++++++
> >  kernel/softirq.c                |    7 ++++++-
> >  2 files changed, 18 insertions(+), 1 deletions(-)
> > 
> > 
> > diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> > index 214bb92..38b4bdd 100644
> > --- a/include/trace/irq_event_types.h
> > +++ b/include/trace/irq_event_types.h
> > @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
> >  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
> >  );
> >  
> > +TRACE_FORMAT(irq_softirq_entry,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > +	);
> > +
> > +TRACE_FORMAT(irq_softirq_exit,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > +	);
> > +
> >  #undef TRACE_SYSTEM
> > diff --git a/kernel/softirq.c b/kernel/softirq.c
> > index ba1511f..c378d53 100644
> > --- a/kernel/softirq.c
> > +++ b/kernel/softirq.c
> > @@ -24,6 +24,7 @@
> >  #include <linux/ftrace.h>
> >  #include <linux/smp.h>
> >  #include <linux/tick.h>
> > +#include <trace/irq.h>
> >  
> >  #include <asm/irq.h>
> >  /*
> > @@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
> >   */
> >  #define MAX_SOFTIRQ_RESTART 10
> >  
> > +DEFINE_TRACE(irq_softirq_entry);
> > +DEFINE_TRACE(irq_softirq_exit);
> 
> 
> Just one nit here. The "irq_" prefix seems to me too much.
> On the trace we have:
> 
> /* irq_softirq_entry: softirq=nb action=nb_to_logical_name */
> 
> It's even too much words that says the same things.
> Moreover, we have the logical name, the number seems not very useful
> because we have its logical translation just after.
> 
> I would suggest to have just:
> 
> /* softirq_entry: nb_to_logical_name */
> 
> ie:
> 
> /* softirq_entry: SCHED_SOFTIRQ */
> 
> Don't you think it's more clear and obvious?

yeah.

> Other than that, I think these tracepoints are a good idea.

agreed.

Acked-by: Ingo Molnar <mingo@elte.hu>

	Ingo

[tip:tracing/ftrace] tracing: tracepoints for softirq entry/exit - tracepoints

[Jason Baron]

Commit-ID:  39842323ceb368d2ea36ab7696aedbe296e13b61
Gitweb:     http://git.kernel.org/tip/39842323ceb368d2ea36ab7696aedbe296e13b61
Author:     Jason Baron <jbaron@redhat.com>
AuthorDate: Thu, 12 Mar 2009 14:36:03 -0400
Commit:     Steven Rostedt <srostedt@redhat.com>
CommitDate: Thu, 12 Mar 2009 21:20:58 -0400

tracing: tracepoints for softirq entry/exit - tracepoints

Introduce softirq entry/exit tracepoints. These are useful for
augmenting existing tracers, and to figure out softirq frequencies and
timings.

[
  s/irq_softirq_/softirq_/ for trace point names and
  Fixed printf format in TRACE_FORMAT macro
   - Steven Rostedt
]

LKML-Reference: <20090312183603.GC3352@redhat.com>
Signed-off-by: Jason Baron <jbaron@redhat.com>
Signed-off-by: Steven Rostedt <srostedt@redhat.com>


---
 include/trace/irq_event_types.h |   12 ++++++++++++
 kernel/softirq.c                |    7 ++++++-
 2 files changed, 18 insertions(+), 1 deletions(-)

diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 214bb92..85964eb 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
 		  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
+TRACE_FORMAT(softirq_entry,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", (int)(h - vec), softirq_to_name[h-vec])
+	);
+
+TRACE_FORMAT(softirq_exit,
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+	TP_ARGS(h, vec),
+	TP_FMT("softirq=%d action=%s", (int)(h - vec), softirq_to_name[h-vec])
+	);
+
 #undef TRACE_SYSTEM
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 9f90fdc..a5e8123 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -24,6 +24,7 @@
 #include <linux/ftrace.h>
 #include <linux/smp.h>
 #include <linux/tick.h>
+#include <trace/irq.h>
 
 #include <asm/irq.h>
 /*
@@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
  */
 #define MAX_SOFTIRQ_RESTART 10
 
+DEFINE_TRACE(softirq_entry);
+DEFINE_TRACE(softirq_exit);
+
 asmlinkage void __do_softirq(void)
 {
 	struct softirq_action *h;
@@ -212,8 +216,9 @@ restart:
 		if (pending & 1) {
 			int prev_count = preempt_count();
 
+			trace_softirq_entry(h, softirq_vec);
 			h->action(h);
-
+			trace_softirq_exit(h, softirq_vec);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Mathieu Desnoyers]

* Jason Baron (jbaron@redhat.com) wrote:
> 
> introduce softirq entry/exit tracepoints. These are useful for
> augmenting existing tracers, and to figure out softirq frequencies and
> timings.
> 
> Signed-off-by: Jason Baron <jbaron@redhat.com>
> 
> ---
> 
>  include/trace/irq_event_types.h |   12 ++++++++++++
>  kernel/softirq.c                |    7 ++++++-
>  2 files changed, 18 insertions(+), 1 deletions(-)
> 
> 
> diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> index 214bb92..38b4bdd 100644
> --- a/include/trace/irq_event_types.h
> +++ b/include/trace/irq_event_types.h
> @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
>  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
>  );
>  
> +TRACE_FORMAT(irq_softirq_entry,
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +	TP_ARGS(h, vec),
> +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> +	);
> +
> +TRACE_FORMAT(irq_softirq_exit,
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +	TP_ARGS(h, vec),
> +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])

The softirq tracepoints are a good idea indeed (I have similar ones in
the LTTng tree). My main concern is about the fact that you output the
softirq name in plain text to the trace buffers. I would rather prefer
to save only the softirq (h-vec) into the trace and dump the mapping
(h-vec) to name only once, so we can save precious trace bytes.

Mathieu

> +	);
> +
>  #undef TRACE_SYSTEM
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index ba1511f..c378d53 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -24,6 +24,7 @@
>  #include <linux/ftrace.h>
>  #include <linux/smp.h>
>  #include <linux/tick.h>
> +#include <trace/irq.h>
>  
>  #include <asm/irq.h>
>  /*
> @@ -186,6 +187,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
>   */
>  #define MAX_SOFTIRQ_RESTART 10
>  
> +DEFINE_TRACE(irq_softirq_entry);
> +DEFINE_TRACE(irq_softirq_exit);
> +
>  asmlinkage void __do_softirq(void)
>  {
>  	struct softirq_action *h;
> @@ -212,8 +216,9 @@ restart:
>  		if (pending & 1) {
>  			int prev_count = preempt_count();
>  
> +			trace_irq_softirq_entry(h, softirq_vec);
>  			h->action(h);
> -
> +			trace_irq_softirq_exit(h, softirq_vec);
>  			if (unlikely(prev_count != preempt_count())) {
>  				printk(KERN_ERR "huh, entered softirq %td %s %p"
>  				       "with preempt_count %08x,"
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Ingo Molnar]

* Mathieu Desnoyers <compudj@krystal.dyndns.org> wrote:

> * Jason Baron (jbaron@redhat.com) wrote:
> > 
> > introduce softirq entry/exit tracepoints. These are useful for
> > augmenting existing tracers, and to figure out softirq frequencies and
> > timings.
> > 
> > Signed-off-by: Jason Baron <jbaron@redhat.com>
> > 
> > ---
> > 
> >  include/trace/irq_event_types.h |   12 ++++++++++++
> >  kernel/softirq.c                |    7 ++++++-
> >  2 files changed, 18 insertions(+), 1 deletions(-)
> > 
> > 
> > diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> > index 214bb92..38b4bdd 100644
> > --- a/include/trace/irq_event_types.h
> > +++ b/include/trace/irq_event_types.h
> > @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
> >  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
> >  );
> >  
> > +TRACE_FORMAT(irq_softirq_entry,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > +	);
> > +
> > +TRACE_FORMAT(irq_softirq_exit,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> 
> The softirq tracepoints are a good idea indeed (I have similar 
> ones in the LTTng tree). My main concern is about the fact 
> that you output the softirq name in plain text to the trace 
> buffers. I would rather prefer to save only the softirq 
> (h-vec) into the trace and dump the mapping (h-vec) to name 
> only once, so we can save precious trace bytes.

The right solution is to change this tracepoint to TRACE_EVENT() 
format. Jason, do you have time to do that?

	Ingo

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Steven Rostedt]

On Fri, 13 Mar 2009, Mathieu Desnoyers wrote:

> * Jason Baron (jbaron@redhat.com) wrote:
> > 
> > introduce softirq entry/exit tracepoints. These are useful for
> > augmenting existing tracers, and to figure out softirq frequencies and
> > timings.
> > 
> > Signed-off-by: Jason Baron <jbaron@redhat.com>
> > 
> > ---
> > 
> >  include/trace/irq_event_types.h |   12 ++++++++++++
> >  kernel/softirq.c                |    7 ++++++-
> >  2 files changed, 18 insertions(+), 1 deletions(-)
> > 
> > 
> > diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> > index 214bb92..38b4bdd 100644
> > --- a/include/trace/irq_event_types.h
> > +++ b/include/trace/irq_event_types.h
> > @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
> >  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
> >  );
> >  
> > +TRACE_FORMAT(irq_softirq_entry,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > +	);
> > +
> > +TRACE_FORMAT(irq_softirq_exit,
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +	TP_ARGS(h, vec),
> > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> 
> The softirq tracepoints are a good idea indeed (I have similar ones in
> the LTTng tree). My main concern is about the fact that you output the
> softirq name in plain text to the trace buffers. I would rather prefer
> to save only the softirq (h-vec) into the trace and dump the mapping
> (h-vec) to name only once, so we can save precious trace bytes.

The TP_FMT is only used by those tracers that want to use it. Any tracer 
can still hook directly to the trace point and do what every they want.

-- Steve

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> 
> On Fri, 13 Mar 2009, Mathieu Desnoyers wrote:
> 
> > * Jason Baron (jbaron@redhat.com) wrote:
> > > 
> > > introduce softirq entry/exit tracepoints. These are useful for
> > > augmenting existing tracers, and to figure out softirq frequencies and
> > > timings.
> > > 
> > > Signed-off-by: Jason Baron <jbaron@redhat.com>
> > > 
> > > ---
> > > 
> > >  include/trace/irq_event_types.h |   12 ++++++++++++
> > >  kernel/softirq.c                |    7 ++++++-
> > >  2 files changed, 18 insertions(+), 1 deletions(-)
> > > 
> > > 
> > > diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> > > index 214bb92..38b4bdd 100644
> > > --- a/include/trace/irq_event_types.h
> > > +++ b/include/trace/irq_event_types.h
> > > @@ -40,4 +40,16 @@ TRACE_EVENT(irq_handler_exit,
> > >  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
> > >  );
> > >  
> > > +TRACE_FORMAT(irq_softirq_entry,
> > > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > > +	TP_ARGS(h, vec),
> > > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > > +	);
> > > +
> > > +TRACE_FORMAT(irq_softirq_exit,
> > > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > > +	TP_ARGS(h, vec),
> > > +	TP_FMT("softirq=%d action=%s", h - vec, softirq_to_name[h-vec])
> > 
> > The softirq tracepoints are a good idea indeed (I have similar ones in
> > the LTTng tree). My main concern is about the fact that you output the
> > softirq name in plain text to the trace buffers. I would rather prefer
> > to save only the softirq (h-vec) into the trace and dump the mapping
> > (h-vec) to name only once, so we can save precious trace bytes.
> 
> The TP_FMT is only used by those tracers that want to use it. Any tracer 
> can still hook directly to the trace point and do what every they want.
> 
> -- Steve
> 

By doing so, you are removing the ability to use the TP_FMT information
to perform high-speed system-wide tracing. I thought the goal was to
create a unified buffering, but sadly I don't see the high-speed
requirements being part of that plan.

Mathieu


-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Steven Rostedt]

On Mon, 16 Mar 2009, Mathieu Desnoyers wrote:
> > > 
> > > The softirq tracepoints are a good idea indeed (I have similar ones in
> > > the LTTng tree). My main concern is about the fact that you output the
> > > softirq name in plain text to the trace buffers. I would rather prefer
> > > to save only the softirq (h-vec) into the trace and dump the mapping
> > > (h-vec) to name only once, so we can save precious trace bytes.
> > 
> > The TP_FMT is only used by those tracers that want to use it. Any tracer 
> > can still hook directly to the trace point and do what every they want.
> > 
> > -- Steve
> > 
> 
> By doing so, you are removing the ability to use the TP_FMT information
> to perform high-speed system-wide tracing. I thought the goal was to
> create a unified buffering, but sadly I don't see the high-speed
> requirements being part of that plan.

TP_FMT has nothing to do with the unified buffering. The unified buffer 
does not even know about it. But if you want high-speed event tracing, 
that is what the TRACE_EVENT was created for.

The TRACE_FORMAT was made for things that will be recording string 
information anyway, and recording a string into the buffer via memcpy or a 
sprintf format (binary printk) doesn't make much difference.

Then trace points for entry and exit does not fall into that category, and 
should be represented by a TRACE_EVENT instead.

-- Steve

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Steven Rostedt]

On Mon, 16 Mar 2009, Steven Rostedt wrote:

> 
> On Mon, 16 Mar 2009, Mathieu Desnoyers wrote:
> > > > 
> > > > The softirq tracepoints are a good idea indeed (I have similar ones in
> > > > the LTTng tree). My main concern is about the fact that you output the
> > > > softirq name in plain text to the trace buffers. I would rather prefer
> > > > to save only the softirq (h-vec) into the trace and dump the mapping
> > > > (h-vec) to name only once, so we can save precious trace bytes.
> > > 
> > > The TP_FMT is only used by those tracers that want to use it. Any tracer 
> > > can still hook directly to the trace point and do what every they want.
> > > 
> > > -- Steve
> > > 
> > 
> > By doing so, you are removing the ability to use the TP_FMT information
> > to perform high-speed system-wide tracing. I thought the goal was to
> > create a unified buffering, but sadly I don't see the high-speed
> > requirements being part of that plan.
> 
> TP_FMT has nothing to do with the unified buffering. The unified buffer 
> does not even know about it. But if you want high-speed event tracing, 
> that is what the TRACE_EVENT was created for.

Here's an example:

The "event tracing" uses the format field to show those events for the 
hook in the sched switching, and wake ups.

The wake up tracer on the other hand, does not care about the format, it 
only cares about having a hook where a a task is woken up, and where it 
gets scheduled in, and perhaps events in between. But it uses its own 
formatting to do the output.

-- Steve

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> 
> On Mon, 16 Mar 2009, Steven Rostedt wrote:
> 
> > 
> > On Mon, 16 Mar 2009, Mathieu Desnoyers wrote:
> > > > > 
> > > > > The softirq tracepoints are a good idea indeed (I have similar ones in
> > > > > the LTTng tree). My main concern is about the fact that you output the
> > > > > softirq name in plain text to the trace buffers. I would rather prefer
> > > > > to save only the softirq (h-vec) into the trace and dump the mapping
> > > > > (h-vec) to name only once, so we can save precious trace bytes.
> > > > 
> > > > The TP_FMT is only used by those tracers that want to use it. Any tracer 
> > > > can still hook directly to the trace point and do what every they want.
> > > > 
> > > > -- Steve
> > > > 
> > > 
> > > By doing so, you are removing the ability to use the TP_FMT information
> > > to perform high-speed system-wide tracing. I thought the goal was to
> > > create a unified buffering, but sadly I don't see the high-speed
> > > requirements being part of that plan.
> > 
> > TP_FMT has nothing to do with the unified buffering. The unified buffer 
> > does not even know about it. But if you want high-speed event tracing, 
> > that is what the TRACE_EVENT was created for.
> 
> Here's an example:
> 
> The "event tracing" uses the format field to show those events for the 
> hook in the sched switching, and wake ups.
> 
> The wake up tracer on the other hand, does not care about the format, it 
> only cares about having a hook where a a task is woken up, and where it 
> gets scheduled in, and perhaps events in between. But it uses its own 
> formatting to do the output.
> 
> -- Steve
> 

If I understand you correctly, the format string is only useful to the
text-output tracer ? Why can't it be used to identify both text and
binary events ?

And remember that from my perspective, information is only useful if
available for system-wide tracing. Specialized tracers come as a subset
of system-wide tracing anyway when the latter is implemented with the
proper hooks.

Mathieu


-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> 
> On Mon, 16 Mar 2009, Mathieu Desnoyers wrote:
> > > > 
> > > > The softirq tracepoints are a good idea indeed (I have similar ones in
> > > > the LTTng tree). My main concern is about the fact that you output the
> > > > softirq name in plain text to the trace buffers. I would rather prefer
> > > > to save only the softirq (h-vec) into the trace and dump the mapping
> > > > (h-vec) to name only once, so we can save precious trace bytes.
> > > 
> > > The TP_FMT is only used by those tracers that want to use it. Any tracer 
> > > can still hook directly to the trace point and do what every they want.
> > > 
> > > -- Steve
> > > 
> > 
> > By doing so, you are removing the ability to use the TP_FMT information
> > to perform high-speed system-wide tracing. I thought the goal was to
> > create a unified buffering, but sadly I don't see the high-speed
> > requirements being part of that plan.
> 
> TP_FMT has nothing to do with the unified buffering. The unified buffer 
> does not even know about it. But if you want high-speed event tracing, 
> that is what the TRACE_EVENT was created for.
> 
> The TRACE_FORMAT was made for things that will be recording string 
> information anyway, and recording a string into the buffer via memcpy or a 
> sprintf format (binary printk) doesn't make much difference.
> 

Are you saying that dynamically parsing a format string in a binary
printk has the same performance impact as a memcpy ? I would be very
interested to see your benchmarks.

Mathieu

> Then trace points for entry and exit does not fall into that category, and 
> should be represented by a TRACE_EVENT instead.
> 
> -- Steve
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Jason Baron]

hi,

ok, below is a re-spun patch 2/2 which converts to the TRACE_EVENT
format.

thanks,

-Jason


Signed-off-by: Jason Baron <jbaron@redhat.com>

---

 include/trace/irq_event_types.h |   36 ++++++++++++++++++++++++++++++++++++
 kernel/softirq.c                |    7 ++++++-
 2 files changed, 42 insertions(+), 1 deletions(-)


diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 214bb92..de1f2a9 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -40,4 +40,40 @@ TRACE_EVENT(irq_handler_exit,
 		  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
+TRACE_EVENT(softirq_action_entry,
+
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+
+	TP_ARGS(h, vec),
+
+	TP_STRUCT__entry(
+		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
+	),
+
+	TP_fast_assign(
+		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
+			MAX_SOFTIRQ_NAME_LEN);
+	),
+
+	TP_printk("softirq entry: %s", __entry->softirq_name)
+);
+
+TRACE_EVENT(softirq_action_exit,
+
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+
+	TP_ARGS(h, vec),
+
+	TP_STRUCT__entry(
+		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
+	),
+
+	TP_fast_assign(
+		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
+			MAX_SOFTIRQ_NAME_LEN);
+	),
+
+	TP_printk("softirq exit: %s", __entry->softirq_name)
+);
+
 #undef TRACE_SYSTEM
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 8f3ae57..5e96c77 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -24,6 +24,7 @@
 #include <linux/ftrace.h>
 #include <linux/smp.h>
 #include <linux/tick.h>
+#include <trace/irq.h>
 
 #include <asm/irq.h>
 /*
@@ -185,6 +186,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
  */
 #define MAX_SOFTIRQ_RESTART 10
 
+DEFINE_TRACE(softirq_action_entry);
+DEFINE_TRACE(softirq_action_exit);
+
 asmlinkage void __do_softirq(void)
 {
 	struct softirq_action *h;
@@ -211,8 +215,9 @@ restart:
 		if (pending & 1) {
 			int prev_count = preempt_count();
 
+			trace_softirq_action_entry(h, softirq_vec);
 			h->action(h);
-
+			trace_softirq_action_exit(h, softirq_vec);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Steven Rostedt]

On Mon, 16 Mar 2009, Jason Baron wrote:

> hi,
> 
> ok, below is a re-spun patch 2/2 which converts to the TRACE_EVENT
> format.

Thanks, some comments though.

> 
> thanks,
> 
> -Jason
> 
> 
> Signed-off-by: Jason Baron <jbaron@redhat.com>
> 
> ---
> 
>  include/trace/irq_event_types.h |   36 ++++++++++++++++++++++++++++++++++++
>  kernel/softirq.c                |    7 ++++++-
>  2 files changed, 42 insertions(+), 1 deletions(-)
> 
> 
> diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> index 214bb92..de1f2a9 100644
> --- a/include/trace/irq_event_types.h
> +++ b/include/trace/irq_event_types.h
> @@ -40,4 +40,40 @@ TRACE_EVENT(irq_handler_exit,
>  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
>  );
>  
> +TRACE_EVENT(softirq_action_entry,
> +
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +
> +	TP_ARGS(h, vec),
> +
> +	TP_STRUCT__entry(
> +		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
> +	),
> +
> +	TP_fast_assign(
> +		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
> +			MAX_SOFTIRQ_NAME_LEN);

memcpy isn't fast ;-)

What you want is this:

	TP_STRUCT__entry(
		__field(	int,	vec	)
	),

	TP_fast_assign(
		__entry->vec = h - vec;
> +	),
> +
> +	TP_printk("softirq entry: %s", __entry->softirq_name)

	TP_printk("softirq entry: %s", softirq_to_name[__entry->vec])

> +);
> +
> +TRACE_EVENT(softirq_action_exit,
> +
> +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> +
> +	TP_ARGS(h, vec),
> +
> +	TP_STRUCT__entry(
> +		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
> +	),
> +
> +	TP_fast_assign(
> +		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
> +			MAX_SOFTIRQ_NAME_LEN);
> +	),
> +
> +	TP_printk("softirq exit: %s", __entry->softirq_name)


And do the same here.

-- Steve

> +);
> +
>  #undef TRACE_SYSTEM
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 8f3ae57..5e96c77 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -24,6 +24,7 @@
>  #include <linux/ftrace.h>
>  #include <linux/smp.h>
>  #include <linux/tick.h>
> +#include <trace/irq.h>
>  
>  #include <asm/irq.h>
>  /*
> @@ -185,6 +186,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
>   */
>  #define MAX_SOFTIRQ_RESTART 10
>  
> +DEFINE_TRACE(softirq_action_entry);
> +DEFINE_TRACE(softirq_action_exit);
> +
>  asmlinkage void __do_softirq(void)
>  {
>  	struct softirq_action *h;
> @@ -211,8 +215,9 @@ restart:
>  		if (pending & 1) {
>  			int prev_count = preempt_count();
>  
> +			trace_softirq_action_entry(h, softirq_vec);
>  			h->action(h);
> -
> +			trace_softirq_action_exit(h, softirq_vec);
>  			if (unlikely(prev_count != preempt_count())) {
>  				printk(KERN_ERR "huh, entered softirq %td %s %p"
>  				       "with preempt_count %08x,"
> 

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> 
> On Mon, 16 Mar 2009, Jason Baron wrote:
> 
> > hi,
> > 
> > ok, below is a re-spun patch 2/2 which converts to the TRACE_EVENT
> > format.
> 
> Thanks, some comments though.
> 
> > 
> > thanks,
> > 
> > -Jason
> > 
> > 
> > Signed-off-by: Jason Baron <jbaron@redhat.com>
> > 
> > ---
> > 
> >  include/trace/irq_event_types.h |   36 ++++++++++++++++++++++++++++++++++++
> >  kernel/softirq.c                |    7 ++++++-
> >  2 files changed, 42 insertions(+), 1 deletions(-)
> > 
> > 
> > diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
> > index 214bb92..de1f2a9 100644
> > --- a/include/trace/irq_event_types.h
> > +++ b/include/trace/irq_event_types.h
> > @@ -40,4 +40,40 @@ TRACE_EVENT(irq_handler_exit,
> >  		  __entry->irq, __entry->ret ? "handled" : "unhandled")
> >  );
> >  
> > +TRACE_EVENT(softirq_action_entry,
> > +
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +
> > +	TP_ARGS(h, vec),
> > +
> > +	TP_STRUCT__entry(
> > +		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
> > +			MAX_SOFTIRQ_NAME_LEN);
> 
> memcpy isn't fast ;-)
> 

When given a constant size, memcpy is inlined by the compiler and turned
into a simple mov instruction. That shouldn't change a thing.

Mathieu

> What you want is this:
> 
> 	TP_STRUCT__entry(
> 		__field(	int,	vec	)
> 	),
> 
> 	TP_fast_assign(
> 		__entry->vec = h - vec;
> > +	),
> > +
> > +	TP_printk("softirq entry: %s", __entry->softirq_name)
> 
> 	TP_printk("softirq entry: %s", softirq_to_name[__entry->vec])
> 
> > +);
> > +
> > +TRACE_EVENT(softirq_action_exit,
> > +
> > +	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
> > +
> > +	TP_ARGS(h, vec),
> > +
> > +	TP_STRUCT__entry(
> > +		__array(	char,	softirq_name,	MAX_SOFTIRQ_NAME_LEN )
> > +	),
> > +
> > +	TP_fast_assign(
> > +		memcpy(__entry->softirq_name, softirq_to_name[h-vec],
> > +			MAX_SOFTIRQ_NAME_LEN);
> > +	),
> > +
> > +	TP_printk("softirq exit: %s", __entry->softirq_name)
> 
> 
> And do the same here.
> 
> -- Steve
> 
> > +);
> > +
> >  #undef TRACE_SYSTEM
> > diff --git a/kernel/softirq.c b/kernel/softirq.c
> > index 8f3ae57..5e96c77 100644
> > --- a/kernel/softirq.c
> > +++ b/kernel/softirq.c
> > @@ -24,6 +24,7 @@
> >  #include <linux/ftrace.h>
> >  #include <linux/smp.h>
> >  #include <linux/tick.h>
> > +#include <trace/irq.h>
> >  
> >  #include <asm/irq.h>
> >  /*
> > @@ -185,6 +186,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
> >   */
> >  #define MAX_SOFTIRQ_RESTART 10
> >  
> > +DEFINE_TRACE(softirq_action_entry);
> > +DEFINE_TRACE(softirq_action_exit);
> > +
> >  asmlinkage void __do_softirq(void)
> >  {
> >  	struct softirq_action *h;
> > @@ -211,8 +215,9 @@ restart:
> >  		if (pending & 1) {
> >  			int prev_count = preempt_count();
> >  
> > +			trace_softirq_action_entry(h, softirq_vec);
> >  			h->action(h);
> > -
> > +			trace_softirq_action_exit(h, softirq_vec);
> >  			if (unlikely(prev_count != preempt_count())) {
> >  				printk(KERN_ERR "huh, entered softirq %td %s %p"
> >  				       "with preempt_count %08x,"
> > 
> 

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [Patch 2/2] tracepoints for softirq entry/exit - tracepoints

[Jason Baron]

On Mon, Mar 16, 2009 at 03:17:09PM -0400, Steven Rostedt wrote:
> memcpy isn't fast ;-)
> 
> What you want is this:
> 
> 	TP_STRUCT__entry(
> 		__field(	int,	vec	)
> 	),
> 
> 	TP_fast_assign(
> 		__entry->vec = h - vec;

definitely simplifies things! ok, re-spun patch again.

use TRACE_EVENT to record the softirq vector number in the trace and then use
the new softirq_to_name array to output the softirq vector name.

Signed-off-by: Jason Baron <jbaron@redhat.com>


---

 include/trace/irq_event_types.h |   34 ++++++++++++++++++++++++++++++++++
 kernel/softirq.c                |    7 ++++++-
 2 files changed, 40 insertions(+), 1 deletions(-)


diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
index 214bb92..acb8217 100644
--- a/include/trace/irq_event_types.h
+++ b/include/trace/irq_event_types.h
@@ -40,4 +40,38 @@ TRACE_EVENT(irq_handler_exit,
 		  __entry->irq, __entry->ret ? "handled" : "unhandled")
 );
 
+TRACE_EVENT(softirq_action_entry,
+
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+
+	TP_ARGS(h, vec),
+
+	TP_STRUCT__entry(
+		__field(	int,	vec	)
+	),
+
+	TP_fast_assign(
+		__entry->vec = h - vec;
+	),
+
+	TP_printk("softirq entry: %s", softirq_to_name[__entry->vec])
+);
+
+TRACE_EVENT(softirq_action_exit,
+
+	TP_PROTO(struct softirq_action *h, struct softirq_action *vec),
+
+	TP_ARGS(h, vec),
+
+	TP_STRUCT__entry(
+		__field(	int,	vec	)
+	),
+
+	TP_fast_assign(
+		__entry->vec = h - vec;
+	),
+
+	TP_printk("softirq exit: %s", softirq_to_name[__entry->vec])
+);
+
 #undef TRACE_SYSTEM
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 8f3ae57..5e96c77 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -24,6 +24,7 @@
 #include <linux/ftrace.h>
 #include <linux/smp.h>
 #include <linux/tick.h>
+#include <trace/irq.h>
 
 #include <asm/irq.h>
 /*
@@ -185,6 +186,9 @@ EXPORT_SYMBOL(local_bh_enable_ip);
  */
 #define MAX_SOFTIRQ_RESTART 10
 
+DEFINE_TRACE(softirq_action_entry);
+DEFINE_TRACE(softirq_action_exit);
+
 asmlinkage void __do_softirq(void)
 {
 	struct softirq_action *h;
@@ -211,8 +215,9 @@ restart:
 		if (pending & 1) {
 			int prev_count = preempt_count();
 
+			trace_softirq_action_entry(h, softirq_vec);
 			h->action(h);
-
+			trace_softirq_action_exit(h, softirq_vec);
 			if (unlikely(prev_count != preempt_count())) {
 				printk(KERN_ERR "huh, entered softirq %td %s %p"
 				       "with preempt_count %08x,"