Re: [patch] latency tracer, 2.6.15-rc7

[Mark Knecht <markknecht@gmail.com>]

On 12/30/05, Lee Revell <rlrevell@joe-job.com> wrote:
> On Fri, 2005-12-30 at 09:00 +0100, Ingo Molnar wrote:
> > * Lee Revell <rlrevell@joe-job.com> wrote:
> >
> > > It seems that debug_smp_processor_id is being called a lot, even
> > > though I have a UP config, which I didn't see with the -rt kernel:
> >
> > do you have CONFIG_DEBUG_PREEMPT enabled? (if yes then disable it)
> >
> > > Was this optimized out on UP before?
> >
> > no, because smp_processor_id() debugging is useful on UP too: it checks
> > whether smp_processor_id() is every called with preemption enabled, and
> > reports such bugs.
>
> It seems that the networking code's use of RCU can cause 10ms+
> latencies:
>


Hi,
   I've noted for awhile that on my AMD64 machine that has xrun issues
that at least annecdotally it has always seemed that the network
interface was somehow involved. I wonder if this may turn out to be
true?

Q: Did the latency trace stuff ever get fixed for AMD64? I'm running
2.6.15-rc7-rt1 as of today. I've had xruns all afternoon while working
inside of MythTV. (Start, stop, rewind, pause all over the place...)

15:09:47.132 Statistics reset.
15:09:47.303 Client activated.
15:09:47.304 Audio connection change.
15:09:47.307 Audio connection graph change.
15:09:48.147 Audio connection graph change.
15:09:48.327 Audio connection change.
15:09:50.487 Audio connection graph change.
15:34:05.107 XRUN callback (1).
**** alsa_pcm: xrun of at least 0.148 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:36:15.580 XRUN callback (2).
**** alsa_pcm: xrun of at least 0.707 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:38:07.232 XRUN callback (3).
**** alsa_pcm: xrun of at least 0.967 msecs
**** alsa_pcm: xrun of at least 2.921 msecs
15:38:08.143 XRUN callback (1 skipped).
15:39:36.616 XRUN callback (5).
**** alsa_pcm: xrun of at least 0.079 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:43:04.318 XRUN callback (6).
**** alsa_pcm: xrun of at least 1.065 msecs
**** alsa_pcm: xrun of at least 0.955 msecs
15:43:05.642 XRUN callback (1 skipped).
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:44:16.964 XRUN callback (8).
**** alsa_pcm: xrun of at least 1.311 msecs
**** alsa_pcm: xrun of at least 1.956 msecs
15:44:18.028 XRUN callback (1 skipped).
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:45:11.371 XRUN callback (10).
**** alsa_pcm: xrun of at least 1.409 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:49:22.014 XRUN callback (11).
**** alsa_pcm: xrun of at least 1.332 msecs
16:10:30.306 XRUN callback (12).
**** alsa_pcm: xrun of at least 0.368 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
16:30:05.355 XRUN callback (13).
**** alsa_pcm: xrun of at least 0.873 msecs
subgraph starting at qjackctl-7906 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
16:33:21.938 XRUN callback (14).
**** alsa_pcm: xrun of at least 1.647 msecs

Bad stuff...

- Mark