Re: [PATCH] new irq tracer

[Frederic Weisbecker <fweisbec@gmail.com>]

On Wed, Feb 18, 2009 at 10:46:20PM +0100, Peter Zijlstra wrote:
> On Wed, 2009-02-18 at 16:35 -0500, Jason Baron wrote:
> > On Wed, Feb 18, 2009 at 10:15:25PM +0100, Peter Zijlstra wrote:
> > > On Wed, 2009-02-18 at 14:53 -0500, Jason Baron wrote:
> > > > hi,
> > > > 
> > > > Using a copule of tracepoints i've implemented an 'irq tracer' which has
> > > > the following column format:
> > > > 
> > > > [time][irq][action][handled][cpu][length]
> > > > 
> > > > for example on my system:
> > > > 
> > > > [ 1038.927248381]     28     eth0      1        3     0.000002745
> > > > [ 1038.927544688]     28     eth0      1        3     0.000002520
> > > > [ 1038.927593609]     28     eth0      1        3     0.000002509
> > > > [ 1038.974087675]     29     ahci      1        1     0.000013135
> > > > [ 1038.974288475]     29     ahci      1        1     0.000005542
> > > > [ 1038.974414324]     29     ahci      1        1     0.000007953
> > > > 
> > > > I think this patch is useful in understanding irq system behavior, and
> > > > for tracking down irq driver handlers that are firing too often or
> > > > spending too much time handling an irq. This approach could be extended
> > > > to the timer irq and for softirqs...
> > > 
> > > The function graph tracer can already do this, it has a special section
> > > to recognize irq entry function, and already measures time spend.
> > > 
> > > I guess with Steve's new triggers (probes or whatever they ended up
> > > being called) you could limit it to just IRQ entry points.
> > > 
> > 
> > i did look at the graph tracer first. While it does measure irq related
> > functions, it does not give this level of detail concerning which irq #,
> > which irq handler is involved, and whether or not the irq was handled
> > successfully or not. So I believe this tracepoints add a level of detail
> > that the graph tracer does not have. Furthermore, this patch requires 2
> > tracepoints, not instrumentation for all kernel functions.
> 
> How useful is that return value?
> 
> Much of the other data is already available, /proc/interrupts will
> happily tell you the source of your interrupt storm. The irq-off latency
> tracer will tell you if stuff takes too much time, the graph tracer can
> tell you what is taking how much time.
> 
> I really am having a difficult time seeing the use in such narrow
> tracers.
> 

Well, something that could be done would be to use this irq tracing framework
to produce the average of time spent in each irq handler.

kernel/trace/trace_stat.c gives some infrastructure for that.

BTW, I have the project to build a function hashlist, based on the function list
provided by dynamic ftrace, to store the average of time spent for each traced
function, using the function graph tracer.