Re: [PATCH] new irq tracer

[Jason Baron <jbaron@redhat.com>]

On Wed, Feb 25, 2009 at 12:34:12PM -0500, Mathieu Desnoyers wrote:
> * Jason Baron (jbaron@redhat.com) wrote:
> > On Wed, Feb 25, 2009 at 11:48:28AM -0500, Masami Hiramatsu wrote:
> > > KOSAKI Motohiro wrote:
> > > >>  /**
> > > >>   * handle_IRQ_event - irq action chain handler
> > > >>   * @irq:	the interrupt number
> > > >> @@ -354,7 +358,9 @@ irqreturn_t handle_IRQ_event(unsigned int irq, struct irqaction *action)
> > > >>  		local_irq_enable_in_hardirq();
> > > >>  
> > > >>  	do {
> > > >> +		trace_irq_entry(irq);
> > > >>  		ret = action->handler(irq, action->dev_id);
> > > >> +		trace_irq_exit(irq, ret);
> > > >>  		if (ret == IRQ_HANDLED)
> > > >>  			status |= action->flags;
> > > >>  		retval |= ret;
> > > > 
> > > > Nobdy want unnecessary redundant tracepoint.
> > > > Please discuss with mathieu, and merge his tracepoint.
> > > 
> > > Hmm, from the viewpoint of trouble shooting, the place of LTTng's tracepoint
> > > is enough. However, from the same viewpoint, it should pass irq-number
> > > to irq-exit event too, because we may lost some previous events by buffer-overflow
> > > etc.
> > > 
> > >          trace_irq_entry(irq, NULL);
> > >          ret = _handle_IRQ_event(irq, action);
> > >          trace_irq_exit(irq, ret);
> > >                         ^^^^
> > > 
> > 
> > the lttng tracepoints wrap the calls to _handle_IRQ_event in 3
> > different places. So the above suggested irq tracepoint provides the
> > same information with 4 less tracepoints in the code. So I believe its
> > simpler - plus we can understand which action handlers are handling the
> > interrupt.
> > 
> 
> The main thing I dislike about only tracing action->handler() calls is
> that you are not tracing an IRQ per se, but rather the invocation of a
> given handler within the interrupt. For instance, it would be difficult
> to calculate the maximum interrupt latency for a given interrupt line,
> because you don't have the "real" irq entry/exit events, just the
> individual handler() calls.
> 
> But I agree that knowing which handler is called is important.
> 
> How about this compromise :
> 
> trace_irq_entry(irq, action)
>   _handle_IRQ_event()
>     for each action  {
>       trace_irq_handler(action, ret);
>       ret = action->handler(irq, action->dev_id);
>       ...
>     }
> trace_irq_exit(action_ret);
> 
> Would that give you the information you need ?
> 
> Here trace_irq_handler would be passed the _current_ action invoked and
> the _previous_ action return value. Note that we should initialize
> irqreturn_t ret to some initial value if we do this. That should keep
> the tracing overhead minimal.
> 

maybe...although that would require re-arranging the 'while' loop in
'handle_IRQ_event' from a do..while loop to a 'while' loop, which will
require an extra branch check, and then we still have to record the last 'ret'
value. I'm not that keen on re-arranging this for trace data...

Using Steve's new 'DEFINE_TRACE_FMT', I can get function graph trace
as follows using the original two tracepoints (patch below):

 3)               |                      handle_IRQ_event() {
 3)               |                        /* (irq_handler_entry) irq=28 handler=eth0 */
 3)               |                        e1000_intr_msi() {
 3)   2.460 us    |                          __napi_schedule();
 3)   9.416 us    |                        }
 3)               |                        /* (irq_handler_exit) irq=28 handler=eth0 return=handled */
 3) + 22.935 us   |                      }

thanks,

-Jason


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

 include/trace/irq.h             |    9 +++++++++
 include/trace/irq_event_types.h |   17 +++++++++++++++++
 kernel/irq/handle.c             |    6 ++++++
 kernel/trace/events.c           |    2 ++
 4 files changed, 34 insertions(+), 0 deletions(-)
 create mode 100644 include/trace/irq.h
 create mode 100644 include/trace/irq_event_types.h


diff --git a/include/trace/irq.h b/include/trace/irq.h
new file mode 100644
index 0000000..ff5d449
--- /dev/null
+++ b/include/trace/irq.h
@@ -0,0 +1,9 @@
+#ifndef _TRACE_IRQ_H
+#define _TRACE_IRQ_H
+
+#include <linux/interrupt.h>
+#include <linux/tracepoint.h>
+
+#include <trace/irq_event_types.h>
+
+#endif
diff --git a/include/trace/irq_event_types.h b/include/trace/irq_event_types.h
new file mode 100644
index 0000000..5889bfd
--- /dev/null
+++ b/include/trace/irq_event_types.h
@@ -0,0 +1,17 @@
+
+/* use <trace/irq.h> instead */
+#ifndef DEFINE_TRACE_FMT
+# error Do not include this file directly.
+# error Unless you know what you are doing.
+#endif
+
+DEFINE_TRACE_FMT(irq_handler_entry,
+	TPPROTO(int irq, struct irqaction *action),
+	TPARGS(irq, action),
+	TPFMT("irq=%d handler=%s", irq, action->name));
+
+DEFINE_TRACE_FMT(irq_handler_exit,
+	TPPROTO(int irq, struct irqaction *action, int ret),
+	TPARGS(irq, action, ret),
+	TPFMT("irq=%d handler=%s return=%s",
+		irq, action->name, ret ? "handled" : "unhandled"));
diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
index fdff380..bcebc2e 100644
--- a/kernel/irq/handle.c
+++ b/kernel/irq/handle.c
@@ -18,6 +18,7 @@
 #include <linux/rculist.h>
 #include <linux/hash.h>
 #include <linux/bootmem.h>
+#include <trace/irq.h>
 
 #include "internals.h"
 
@@ -338,6 +339,9 @@ irqreturn_t no_action(int cpl, void *dev_id)
 	return IRQ_NONE;
 }
 
+DEFINE_TRACE(irq_handler_entry);
+DEFINE_TRACE(irq_handler_exit);
+
 /**
  * handle_IRQ_event - irq action chain handler
  * @irq:	the interrupt number
@@ -354,7 +358,9 @@ irqreturn_t handle_IRQ_event(unsigned int irq, struct irqaction *action)
 		local_irq_enable_in_hardirq();
 
 	do {
+		trace_irq_handler_entry(irq, action);
 		ret = action->handler(irq, action->dev_id);
+		trace_irq_handler_exit(irq, action, ret);
 		if (ret == IRQ_HANDLED)
 			status |= action->flags;
 		retval |= ret;
diff --git a/kernel/trace/events.c b/kernel/trace/events.c
index 38c89ee..3c75623 100644
--- a/kernel/trace/events.c
+++ b/kernel/trace/events.c
@@ -6,8 +6,10 @@
 
 /* trace/<type>.h here */
 #include <trace/sched.h>
+#include <trace/irq.h>
 
 #include "trace_events.h"
 
 /* trace/<type>_event_types.h here */
 #include <trace/sched_event_types.h>
+#include <trace/irq_event_types.h>