linux-kernel - Re: [PATCH] new irq tracer

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20090226162046.GA5889@nowhere>
Date:	Thu, 26 Feb 2009 17:20:47 +0100
From:	Frederic Weisbecker <fweisbec@...il.com>
To:	Jason Baron <jbaron@...hat.com>
Cc:	Mathieu Desnoyers <compudj@...stal.dyndns.org>, mingo@...e.hu,
	Masami Hiramatsu <mhiramat@...hat.com>,
	KOSAKI Motohiro <kosaki.motohiro@...fujitsu.com>,
	Peter Zijlstra <peterz@...radead.org>,
	"Frank Ch. Eigler" <fche@...hat.com>, rostedt@...dmis.org,
	linux-kernel@...r.kernel.org, acme@...stprotocols.net
Subject: Re: [PATCH] new irq tracer

On Thu, Feb 26, 2009 at 10:11:05AM -0500, Jason Baron wrote:
> On Wed, Feb 25, 2009 at 12:34:12PM -0500, Mathieu Desnoyers wrote:
> > * Jason Baron (jbaron@...hat.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
> 


I'm impressed by this new TRACE_FMT system.
It means that I will just need to toggle a value on a /debug/trace/events/irq_stuff/enable
to have the useful informations as comments inside a trace, or in a whole dedicated traces.

I've played with it a part of the night to test the bprintk patch, this is awesome!

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/