Re: [PATCH 2/4] tracing: add event trace infrastructure

From: Ingo Molnar
Date: Wed Feb 25 2009 - 22:20:36 EST



* Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:

>
>
> On Wed, 25 Feb 2009, Ingo Molnar wrote:
>
> >
> > * Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> >
> > > > # _------=> CPU#
> > > > # / _-----=> irqs-off
> > > > # | / _----=> need-resched
> > > > # || / _---=> hardirq/softirq
> > > > # ||| / _--=> preempt-depth
> > > > # |||| /
> > > > # ||||| delay
> > > > # cmd pid ||||| time | caller
> > > > # \ / ||||| \ | /
> > > > <idle>-0 0d..1 0us+: trace_hardirqs_off_thunk (apic_timer_interrupt)
> > > > <idle>-0 0d.s. 97us : __do_softirq (do_softirq)
> > > > <idle>-0 0d.s1 98us : trace_hardirqs_on (do_softirq)
> > [...]
> > > >
> > > > your time starts now.
> > >
> > > Note, that is a legacy format, that works great for the
> > > latency tracers. Those include (the example you used) irqsoff,
> > > the preempt off, wake up latencies. This gives us a nice
> > > listing of why we are hitting a latency. All other plugins
> > > generally use the trace file, although they could also use
> > > that file too.
> > >
> > > As for your English comment. I showed the header to my wife,
> > > and she had no idea what irqs-off means, nor need-resched, nor
> > > preempt-depth ;-) They are not quite English as they are
> > > technical terms. Most of the names are hard coded into the
> > > kernel too.
> > >
> > > Yeah, maybe that file (latency_trace) is a bit too much. I for
> > > one love it. It is great to load a kernel on some remote box,
> > > and run the irqs off latency tracer to see where the
> > > interrupts are disabled for the longest time. This format is
> > > really nice because it shows me when we are in an interrupt,
> > > or interrupts are disabled, and when the task should have been
> > > rescheduled.
> > >
> > > This has help find places that we miss a preemption check too.
> >
> > Could we get that, as PeterZ has suggested, as a trace_option
> > column in the 'trace' file? It would be default off for
> > non-latency tracers, with latency tracing plugins turning it on
> > by default. Would that work?
>
> I guess adding options will be a high priority for me now. I
> can't parse irqsoff output anymore :-(
>
> Besides the information of the ..... area, the times were all
> based off of the start of the trace, not global. This allowed
> you to see the latency in the trace.

That is something that is sane to have as a default anyway. It
always annoys me that i have to start looking at a trace by
subtracting the first timestamp from the last timestamp.

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