Re: 2.6.19-rc6-rt8: alsa xruns
On Wed, 2006-11-29 at 20:51 +0100, Ingo Molnar wrote:
> * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote:
>
> > > ok, i reproduced something similar on one of my boxes and it turned
> > > out to be a tracer bug. I've uploaded -rt10, could you try it? (The
> > > xruns will likely remain, but at least the tracer should be more
> > > usable now to find out the reason for the xruns.)
> >
> > I'm testing -rt10 right now (your binary rpm). Looks like the number
> > and length of the xruns went down, at least for now. All below 2mSec -
> > jack is running 128x2 @ 48000Hz. I'll let it run for a while and
> > report the traces (I have a script that collects all traces above
> > 60us, but not all xruns trigger a trace).
>
> ok.
>
> How do you gather the traces, are you using manual control of tracing
> via prctl(0,1) / prctl(0,0) - or the built-in wakeup tracing method?
Just wakeup tracing (no manual control).
> The wakeup tracing method will detect fundamental problems in -rt
> scheduling, but other types of delays can be better debugged via
> explicit tracing. [jackd used to have the gettimeofday(0,1)/(0,0) hack -
> this API hack has been replaced by prctl(0,1)/(0,0) to start/stop
> tracing] Take a look at linux/scripts/trace-it.c on how to set up
> manually triggered tracing. [if you do that then all you need to do is
> to start/stop the trace - the kernel will do a maximum search and will
> record the longest delay between start/stop calls.]
I'll see if I can patch jack to use the new api so I can trigger this
stuff from within jack. That may give us more meaningful results (I'm
seeing traces but some don't have an "origin", they start with a big
offset already, see some below).
Right now it is 12:25 and jack has not reported xruns since 10:43. Go
figure (several jack apps running, top running, and I'm installing and
testing packages as well == network + hard disk, but the load is not
very high in absolute terms).
-- Fernando
[*]
( ardour-10060|#0): new 526 us maximum-latency wakeup.
preemption latency trace v1.1.5 on 2.6.18-3.rt10.0001
latency: 526 us, #13/13, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: ardour-10060 (uid:500 nice:0 policy:1 rt_prio:61)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
/
| delay
cmd pid | time | caller
\ /| \ | /
-0 0Dnh2 499us : hrtimer_interrupt (8137a917860
8100382c3e98)
-0 0Dnh2 501us : trace_special_sym (8028e5f5 0 0)
-0 0Dnh3 503us : effective_prio <<...>-14029> (-5 -5)
-0 0Dnh3 504us : __activate_task <<...>-14029> (-5 1)
-0 0Dnh3 506us+: try_to_wake_up <<...>-14029> (-5 20)
-0 0.n.1 511us+: hrtimer_restart_sched_tick (8137a91b5fb 0)
-0 0Dn.2 514us+: enqueue_hrtimer (8137a9b1d75
8100040691f0)
-0 0Dn.1 518us+: trace_special_sym (8024a548 0 0)
<...>-10060 0D..2 522us : thread_return <-0> (20 161)
<...>-10060 0D..1 523us+: trace_stop_sched_switched <<...>-10060>
(38 0)
<...>-10060 0...1 526us : thread_return (thread_return)
vim:ft=help
or this one, but this is not long:
( IRQ 18-746 |#1): new 70 us maximum-latency wakeup.
preemption latency trace v1.1.5 on 2.6.18-3.rt10.0001
latency: 70 us, #19/19, CPU#1 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: IRQ 18-746 (uid:0 nice:-5 policy:1 rt_prio:70)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
/
| delay
cmd pid | time | caller
\ /| \ | /
-0 1Dnh31us+: __trace_start_sched_wakeup <<...>-746> (29
1)
-0 1Dnh34us+: trace_special_sym (80247e98 0 0)
-0 1Dnh38us+: try_to_wake_up <<...>-746> (170 20)
-0 1Dnh2 29us+: hrtimer_interrupt (803de15eb1e
81007dfc2160)
-0 1Dnh1 34us : trace_special_sym (8028e5f5 0 0)
-0 1Dnh2 36us : __activate_task <<...>-22> (101 1)
-0 1Dnh2 38us+: try_to_wake_up <<...>-22> (101 20)
-0 1.n.1 41us : hrtimer_restart_sched_tick (803de16a56b 0)
-0 1Dn.2 43us : enqueue_hrtimer (803de1ff5b2
81000407a3f0)
-0 1Dn.1 45us+: trace_special_sym (8024a548 0 0)
<...>-746 1D..2 50us+: thread_return <-0> (20 170)
<..
Re: 2.6.19-rc6-rt8: alsa xruns
On Wed, 2006-11-29 at 20:51 +0100, Ingo Molnar wrote: > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > Also, can you see the xruns/latencies with latencytest too? (That one > might be easier to reproduce for me.) I can do that. Is this the old latency test script? (http://www.gardena.net/benno/linux/latencytest-0.42-png.tar.gz) Most probably there are newer versions... -- Fernando - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > ok, i reproduced something similar on one of my boxes and it turned > > out to be a tracer bug. I've uploaded -rt10, could you try it? (The > > xruns will likely remain, but at least the tracer should be more > > usable now to find out the reason for the xruns.) > > I'm testing -rt10 right now (your binary rpm). Looks like the number > and length of the xruns went down, at least for now. All below 2mSec - > jack is running 128x2 @ 48000Hz. I'll let it run for a while and > report the traces (I have a script that collects all traces above > 60us, but not all xruns trigger a trace). ok. How do you gather the traces, are you using manual control of tracing via prctl(0,1) / prctl(0,0) - or the built-in wakeup tracing method? The wakeup tracing method will detect fundamental problems in -rt scheduling, but other types of delays can be better debugged via explicit tracing. [jackd used to have the gettimeofday(0,1)/(0,0) hack - this API hack has been replaced by prctl(0,1)/(0,0) to start/stop tracing] Take a look at linux/scripts/trace-it.c on how to set up manually triggered tracing. [if you do that then all you need to do is to start/stop the trace - the kernel will do a maximum search and will record the longest delay between start/stop calls.] Also, can you see the xruns/latencies with latencytest too? (That one might be easier to reproduce for me.) Also, my experience is that if there's a short succession of latencies after each other, then it's usually the first trace that makes most sense to analyze - the others might just be 'followup' or 'secondary' delays caused by the tracing/printing overhead of the first trace. So generally i concentrate on the first trace. But if the traces are reasonably apart then each of them makes sense - and sometimes one trace is more informative than another. Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Wed, 2006-11-29 at 14:43 +0100, Ingo Molnar wrote: > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > > > > > (japa-4096 |#0): new 17 us maximum-latency wakeup. > > > > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup. > > > > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup. > > > > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup. > > > > > (japa-4096 |#0): new 1445 us maximum-latency wakeup. > > > > > (japa-4096 |#0): new 2110 us maximum-latency wakeup. > > > > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup. > > > > > (japa-4096 |#0): new 2548 us maximum-latency wakeup. > > > > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup. > > ok, i reproduced something similar on one of my boxes and it turned out > to be a tracer bug. I've uploaded -rt10, could you try it? (The xruns > will likely remain, but at least the tracer should be more usable now to > find out the reason for the xruns.) I'm testing -rt10 right now (your binary rpm). Looks like the number and length of the xruns went down, at least for now. All below 2mSec - jack is running 128x2 @ 48000Hz. I'll let it run for a while and report the traces (I have a script that collects all traces above 60us, but not all xruns trigger a trace). -- Fernando - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Wed, 29 Nov 2006, Ingo Molnar wrote: please talk to John and Thomas about GTOD interfaces. Right now the solution used by the latency tracer is working out pretty OK - but if something better comes along i can use that too. It's not a burning issue though, unless you know of some bug. (i'm not sure what you mean by it becoming constrictive) It doesn't appear to handle clock switching, so for instance, if generic time switches from the tsc, to the acpi_pm would the latency tracer tolerate it ? Also a combination of HRT enabled, and a faulty acpi_pm would cause the tracer to use the PIT .. The PIT takes spinlocks during it's read so I'd imgaine the system would crash, or something else not so good. Also with HRT enabled, you would end up using the acpi_pm even if the TSC is stable which is slower .. That's what I mean when I say constrictive . I've been working with John and Thomas to make the clocksource more usable (and lots of cleanups), ftp://source.mvista.com/pub/dwalker/clocksource/clocksource-v8/ Daniel - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > > > (japa-4096 |#0): new 17 us maximum-latency wakeup. > > > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup. > > > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup. > > > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 1445 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 2110 us maximum-latency wakeup. > > > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 2548 us maximum-latency wakeup. > > > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup. ok, i reproduced something similar on one of my boxes and it turned out to be a tracer bug. I've uploaded -rt10, could you try it? (The xruns will likely remain, but at least the tracer should be more usable now to find out the reason for the xruns.) Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > I'll turn off the machine and cold boot it...) > > No difference, actually it looks like the regression re-regresses if I > enable the trace... Arghhh. yeah, that happens sometimes if some race is particularly narrow :-/ > Toggling /proc/sys/kernel/trace_enabled makes the long xruns reported > by jack come and go. i'll try to reproduce it. Can you see it with my yum kernel too? (that would simplify checking this on many testboxes) Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Daniel Walker <[EMAIL PROTECTED]> wrote: > > i fixed this in -rt8: the latency tracer now uses the time of day > > clocksource - pmtimer in this case. (that means function tracing is > > slower than with the TSC, but latency figures are more reliable.) > > I have a patch set to make the using the clocksources a little nicer.. > Is there anything I should add to that interface to help enable > latency tracing, or are you satisfied with using the timekeeping > clocksource? It might get constrictive after a while. please talk to John and Thomas about GTOD interfaces. Right now the solution used by the latency tracer is working out pretty OK - but if something better comes along i can use that too. It's not a burning issue though, unless you know of some bug. (i'm not sure what you mean by it becoming constrictive) Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 13:35 -0800, Fernando Lopez-Lezcano wrote:
> On Tue, 2006-11-28 at 13:04 -0800, Fernando Lopez-Lezcano wrote:
> > On Tue, 2006-11-28 at 12:37 -0800, Fernando Lopez-Lezcano wrote:
> > > On Tue, 2006-11-28 at 21:09 +0100, Ingo Molnar wrote:
> > > > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote:
> > > >
> > > > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when
> > > > > using jackd and jack clients. This is a sample from the output of
> > > > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21):
> > > >
> > > > > (japa-4096 |#0): new 17 us maximum-latency wakeup.
> > > > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup.
> > > > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup.
> > > > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup.
> > > > > (japa-4096 |#0): new 1445 us maximum-latency wakeup.
> > > > > (japa-4096 |#0): new 2110 us maximum-latency wakeup.
> > > > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup.
> > > > > (japa-4096 |#0): new 2548 us maximum-latency wakeup.
> > > > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup.
> > > >
> > > > hm, lets fix this. Could you enable tracing (on the yum rpm) via:
> > > >
> > > > echo 1 > /proc/sys/kernel/trace_enabled
> > > >
> > > > does /proc/latency_trace have any meaningful events included for such a
> > > > long delay? If not then it would be nice to rebuild the kernel with
> > > > CONFIG_LATENCY_TRACING - and in any case my previous suggestion holds
> > > > too: booting with maxcpus=1 to reproduce the latencies will give easier
> > > > to interpret latency traces.
> > >
> > > Sorry, it looks like it is an smp issue. Booting with maxcpus=1 reduces
> > > the xrun reports significantly (only three so far but very short, in the
> > > range of 0.029 to 0.041 ms). The long ones seem to have gone away, so
> > > far...
> >
> > Strange, I rebooted smp and I'm not seeing the very long xruns I was
> > seeing before, only short ones as reported above. Here are some traces,
> > but nothing that makes sense I think.
> >
> > I'll turn off the machine and cold boot it...)
>
> No difference, actually it looks like the regression re-regresses if I
> enable the trace... Arghhh.
>
> Toggling /proc/sys/kernel/trace_enabled makes the long xruns reported by
> jack come and go.
I still get long xruns with the trace on, but it does not look like it
says anything important:
preemption latency trace v1.1.5 on 2.6.18-1.0001.3.rt8.fc6.ccrma
latency: 4283 us, #8/8, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: IRQ 18-819 (uid:0 nice:-5 policy:1 rt_prio:70)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
/
| delay
cmd pid | time | caller
\ /| \ | /
-0 1Dn.3 4270us+: trace_change_sched_cpu (0 1 0)
-0 1Dn.3 4273us : deactivate_task <<...>-819> (170 2)
-0 1Dn.3 4275us : __activate_task <<...>-819> (170 1)
<...>-819 1D..2 4278us : thread_return <-0> (20 170)
<...>-819 1D..1 4280us+: trace_stop_sched_switched <<...>-819> (29
1)
<...>-819 1...1 4283us : thread_return (thread_return)
vim:ft=help
I wonder if it is something that starts happening after some uptime.
I'll try rebooting again.
-- Fernando
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 21:14 +0100, Ingo Molnar wrote: > * Lee Revell <[EMAIL PROTECTED]> wrote: > > > On Tue, 2006-11-28 at 11:58 -0800, Fernando Lopez-Lezcano wrote: > > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > > > using jackd and jack clients. This is a sample from the output of > > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): > > > > Any improvement if you disable high res timers? > > > > Also, the latency tracer does not work on dual core AMD machines due > > to the TSC drift. Might as well disable it. > > i fixed this in -rt8: the latency tracer now uses the time of day > clocksource - pmtimer in this case. (that means function tracing is > slower than with the TSC, but latency figures are more reliable.) I have a patch set to make the using the clocksources a little nicer.. Is there anything I should add to that interface to help enable latency tracing, or are you satisfied with using the timekeeping clocksource? It might get constrictive after a while. Daniel - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 13:04 -0800, Fernando Lopez-Lezcano wrote: > On Tue, 2006-11-28 at 12:37 -0800, Fernando Lopez-Lezcano wrote: > > On Tue, 2006-11-28 at 21:09 +0100, Ingo Molnar wrote: > > > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > > > > > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > > > > using jackd and jack clients. This is a sample from the output of > > > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): > > > > > > > (japa-4096 |#0): new 17 us maximum-latency wakeup. > > > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup. > > > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup. > > > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 1445 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 2110 us maximum-latency wakeup. > > > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup. > > > > (japa-4096 |#0): new 2548 us maximum-latency wakeup. > > > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup. > > > > > > hm, lets fix this. Could you enable tracing (on the yum rpm) via: > > > > > > echo 1 > /proc/sys/kernel/trace_enabled > > > > > > does /proc/latency_trace have any meaningful events included for such a > > > long delay? If not then it would be nice to rebuild the kernel with > > > CONFIG_LATENCY_TRACING - and in any case my previous suggestion holds > > > too: booting with maxcpus=1 to reproduce the latencies will give easier > > > to interpret latency traces. > > > > Sorry, it looks like it is an smp issue. Booting with maxcpus=1 reduces > > the xrun reports significantly (only three so far but very short, in the > > range of 0.029 to 0.041 ms). The long ones seem to have gone away, so > > far... > > Strange, I rebooted smp and I'm not seeing the very long xruns I was > seeing before, only short ones as reported above. Here are some traces, > but nothing that makes sense I think. > > I'll turn off the machine and cold boot it...) No difference, actually it looks like the regression re-regresses if I enable the trace... Arghhh. Toggling /proc/sys/kernel/trace_enabled makes the long xruns reported by jack come and go. -- Fernando - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 12:37 -0800, Fernando Lopez-Lezcano wrote:
> On Tue, 2006-11-28 at 21:09 +0100, Ingo Molnar wrote:
> > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote:
> >
> > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when
> > > using jackd and jack clients. This is a sample from the output of
> > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21):
> >
> > > (japa-4096 |#0): new 17 us maximum-latency wakeup.
> > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup.
> > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup.
> > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup.
> > > (japa-4096 |#0): new 1445 us maximum-latency wakeup.
> > > (japa-4096 |#0): new 2110 us maximum-latency wakeup.
> > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup.
> > > (japa-4096 |#0): new 2548 us maximum-latency wakeup.
> > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup.
> >
> > hm, lets fix this. Could you enable tracing (on the yum rpm) via:
> >
> > echo 1 > /proc/sys/kernel/trace_enabled
> >
> > does /proc/latency_trace have any meaningful events included for such a
> > long delay? If not then it would be nice to rebuild the kernel with
> > CONFIG_LATENCY_TRACING - and in any case my previous suggestion holds
> > too: booting with maxcpus=1 to reproduce the latencies will give easier
> > to interpret latency traces.
>
> Sorry, it looks like it is an smp issue. Booting with maxcpus=1 reduces
> the xrun reports significantly (only three so far but very short, in the
> range of 0.029 to 0.041 ms). The long ones seem to have gone away, so
> far...
Strange, I rebooted smp and I'm not seeing the very long xruns I was
seeing before, only short ones as reported above. Here are some traces,
but nothing that makes sense I think.
I'll turn off the machine and cold boot it...)
-- Fernando
preemption latency trace v1.1.5 on 2.6.18-1.0001.3.rt8.fc6.ccrma
latency: 16023 us, #8/8, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: jackd-3739 (uid:500 nice:0 policy:1 rt_prio:62)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
/
| delay
cmd pid | time | caller
\ /| \ | /
qjackctl-3740 0Dn.11us : __trace_start_sched_wakeup <<...>-3739>
(37 0)
qjackctl-3740 0Dn.13us : try_to_wake_up <<...>-3739> (162 161)
qjackctl-3740 0Dn.14us : trace_special_sym (802668da 0 0)
<...>-3739 1D..28us : thread_return (199 162)
<...>-3739 1D..1 10us+: trace_stop_sched_switched <<...>-3739> (37
1)
<...>-3739 1...1 13us : thread_return (thread_return)
vim:ft=help
preemption latency trace v1.1.5 on 2.6.18-1.0001.3.rt8.fc6.ccrma
latency: 71 us, #14/14, CPU#1 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: IRQ 18-813 (uid:0 nice:-5 policy:1 rt_prio:70)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
/
| delay
cmd pid | time | caller
\ /| \ | /
-0 1Dnh33us+: __trace_start_sched_wakeup <<...>-813> (29
1)
-0 1Dnh38us+: try_to_wake_up <<...>-813> (170 20)
-0 1Dnh1 22us+: do_IRQ (8026f32c 12 0)
-0 1Dnh2 25us+: trace_special_sym (8028f2ad 0 0)
-0 1Dnh3 29us+: __activate_task <<...>-412> (149 1)
-0 1Dnh3 33us+: try_to_wake_up <<...>-412> (149 20)
-0 1.n.1 40us+: hrtimer_restart_sched_tick (d48a31262d 0)
-0 1Dn.2 44us+: enqueue_hrtimer (d48a527afd
81000407a950)
-0 1Dn.1 52us+: trace_special_sym (8024b93e 0 0)
<...>-813 1D..2 60us+: thread_return <-0> (20 170)
<...>-813 1D..1 64us+: trace_stop_sched_switched <<...>-813> (29
1)
<...>-813 1...1 71us : thread_return (thread_return)
vim:ft=help
preemption latency trace v1.1.5 on 2.6.18-1.0001.3.rt8.fc6.ccrma
latency: 2255 us, #11/11, CPU#0 | (M:rt VP:0, KP:0, SP:1 HP:1 #P:2)
-
| task: japa-3782 (uid:500 nice:0 policy:1 rt_prio:61)
-
_--=> CPU#
/ _-=> irqs-off
| / _=> ne
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 21:09 +0100, Ingo Molnar wrote: > * Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > > using jackd and jack clients. This is a sample from the output of > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): > > > (japa-4096 |#0): new 17 us maximum-latency wakeup. > > ( beagled-3412 |#1): new 19 us maximum-latency wakeup. > > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup. > > ( snd-4040 |#1): new 1107 us maximum-latency wakeup. > > (japa-4096 |#0): new 1445 us maximum-latency wakeup. > > (japa-4096 |#0): new 2110 us maximum-latency wakeup. > > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup. > > (japa-4096 |#0): new 2548 us maximum-latency wakeup. > > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup. > > hm, lets fix this. Could you enable tracing (on the yum rpm) via: > > echo 1 > /proc/sys/kernel/trace_enabled > > does /proc/latency_trace have any meaningful events included for such a > long delay? If not then it would be nice to rebuild the kernel with > CONFIG_LATENCY_TRACING - and in any case my previous suggestion holds > too: booting with maxcpus=1 to reproduce the latencies will give easier > to interpret latency traces. Sorry, it looks like it is an smp issue. Booting with maxcpus=1 reduces the xrun reports significantly (only three so far but very short, in the range of 0.029 to 0.041 ms). The long ones seem to have gone away, so far... > (but if it's SMP-only then no problem, the > latency traces are still valuable) -- Fernando - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Lee Revell <[EMAIL PROTECTED]> wrote: > On Tue, 2006-11-28 at 11:58 -0800, Fernando Lopez-Lezcano wrote: > > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > > using jackd and jack clients. This is a sample from the output of > > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): > > Any improvement if you disable high res timers? > > Also, the latency tracer does not work on dual core AMD machines due > to the TSC drift. Might as well disable it. i fixed this in -rt8: the latency tracer now uses the time of day clocksource - pmtimer in this case. (that means function tracing is slower than with the TSC, but latency figures are more reliable.) Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
On Tue, 2006-11-28 at 11:58 -0800, Fernando Lopez-Lezcano wrote: > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > using jackd and jack clients. This is a sample from the output of > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): Any improvement if you disable high res timers? Also, the latency tracer does not work on dual core AMD machines due to the TSC drift. Might as well disable it. Lee - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: 2.6.19-rc6-rt8: alsa xruns
* Fernando Lopez-Lezcano <[EMAIL PROTECTED]> wrote: > Hi, I'm trying out the latest -rt patch and getting alsa xruns when > using jackd and jack clients. This is a sample from the output of > qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): > (japa-4096 |#0): new 17 us maximum-latency wakeup. > ( beagled-3412 |#1): new 19 us maximum-latency wakeup. > ( IRQ 18-1081 |#1): new 26 us maximum-latency wakeup. > ( snd-4040 |#1): new 1107 us maximum-latency wakeup. > (japa-4096 |#0): new 1445 us maximum-latency wakeup. > (japa-4096 |#0): new 2110 us maximum-latency wakeup. > (qjackctl-4038 |#1): new 2328 us maximum-latency wakeup. > (japa-4096 |#0): new 2548 us maximum-latency wakeup. > ( IRQ 18-1081 |#0): new 10291 us maximum-latency wakeup. hm, lets fix this. Could you enable tracing (on the yum rpm) via: echo 1 > /proc/sys/kernel/trace_enabled does /proc/latency_trace have any meaningful events included for such a long delay? If not then it would be nice to rebuild the kernel with CONFIG_LATENCY_TRACING - and in any case my previous suggestion holds too: booting with maxcpus=1 to reproduce the latencies will give easier to interpret latency traces. (but if it's SMP-only then no problem, the latency traces are still valuable) Ingo - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
2.6.19-rc6-rt8: alsa xruns
Hi, I'm trying out the latest -rt patch and getting alsa xruns when using jackd and jack clients. This is a sample from the output of qjackctl / jackd (jack 0.102.25, qjackctl 0.2.21): alsa_pcm: xrun of at least 0.034 msecs 11:38:03.681 XRUN callback (154). delay of 18710.000 usecs exceeds estimated spare time of 2604.000; restart ... delay of 31993.000 usecs exceeds estimated spare time of 2605.000; restart ... 11:38:12.748 XRUN callback (155). delay of 110914.000 usecs exceeds estimated spare time of 2605.000; restart ... 11:38:14.976 XRUN callback (156). alsa_pcm: xrun of at least 0.033 msecs 11:38:15.547 XRUN callback (1 skipped). alsa_pcm: xrun of at least 0.033 msecs 11:38:20.044 XRUN callback (158). alsa_pcm: xrun of at least 0.035 msecs 11:38:21.903 XRUN callback (159). delay of 5480.000 usecs exceeds estimated spare time of 2600.000; restart ... 11:38:23.758 XRUN callback (1 skipped). alsa_pcm: xrun of at least 10.878 msecs 11:38:55.076 XRUN callback (161). alsa_pcm: xrun of at least 5.338 msecs 11:38:56.750 XRUN callback (162). delay of 12588.000 usecs exceeds estimated spare time of 2606.000; restart ... 11:39:13.049 XRUN callback (163). alsa_pcm: xrun of at least 0.258 msecs 11:39:15.039 XRUN callback (1 skipped). alsa_pcm: xrun of at least 0.032 msecs 11:39:28.572 XRUN callback (165). alsa_pcm: xrun of at least 10.818 msecs 11:41:03.001 XRUN callback (166). alsa_pcm: xrun of at least 6.475 msecs 11:41:14.144 XRUN callback (167). alsa_pcm: xrun of at least 4.931 msecs 11:41:25.643 XRUN callback (168). alsa_pcm: xrun of at least 21.347 msecs 11:41:28.163 XRUN callback (169). alsa_pcm: xrun of at least 11.910 msecs 11:41:28.513 XRUN callback (1 skipped). alsa_pcm: xrun of at least 5.623 msecs 11:42:04.347 XRUN callback (171). delay of 180434.000 usecs exceeds estimated spare time of 2607.000; restart ... 11:43:13.748 XRUN callback (172). delay of 205776.000 usecs exceeds estimated spare time of 2607.000; restart ... delay of 221779.000 usecs exceeds estimated spare time of 2607.000; restart ... 11:43:15.263 XRUN callback (2 skipped). delay of 25987.000 usecs exceeds estimated spare time of 2607.000; restart ... 11:43:24.325 XRUN callback (175). delay of 25990.000 usecs exceeds estimated spare time of 2607.000; restart ... 11:43:25.519 XRUN callback (1 skipped). alsa_pcm: xrun of at least 31.450 msecs 11:43:29.760 XRUN callback (177). alsa_pcm: xrun of at least 35.110 msecs 11:44:12.244 XRUN callback (178). alsa_pcm: xrun of at least 1.843 msecs 11:45:25.668 XRUN callback (179). 11:46:19.516 XRUN callback (180). alsa_pcm: xrun of at least 15.978 msecs delay of 50782.000 usecs exceeds estimated spare time of 2606.000; restart ... 11:46:41.114 XRUN callback (181). alsa_pcm: xrun of at least 17.744 msecs 11:46:54.612 XRUN callback (182). alsa_pcm: xrun of at least 0.089 msecs 11:47:02.364 XRUN callback (183). alsa_pcm: xrun of at least 0.027 msecs 11:47:03.102 XRUN callback (1 skipped). delay of 3891.000 usecs exceeds estimated spare time of 2608.000; restart ... 11:47:04.812 XRUN callback (185). delay of 5224.000 usecs exceeds estimated spare time of 2577.000; restart ... alsa_pcm: xrun of at least 0.501 msecs 11:47:05.151 XRUN callback (2 skipped). 11:47:13.614 XRUN callback (188). delay of 15536.000 usecs exceeds estimated spare time of 2602.000; restart ... alsa_pcm: xrun of at least 0.156 msecs 11:47:15.461 XRUN callback (1 skipped). alsa_pcm: xrun of at least 0.037 msecs 11:47:41.528 XRUN callback (190). delay of 5303.000 usecs exceeds estimated spare time of 2606.000; restart ... 11:47:45.515 XRUN callback (191). alsa_pcm: xrun of at least 0.361 msecs 11:48:25.755 XRUN callback (192). delay of 2940.000 usecs exceeds estimated spare time of 2601.000; restart ... 11:49:28.306 XRUN callback (193). delay of 20574.000 usecs exceeds estimated spare time of 2615.000; restart ... 11:49:43.013 XRUN callback (194). alsa_pcm: xrun of at least 0.030 msecs 11:50:41.496 XRUN callback (195). alsa_pcm: xrun of at least 27.624 msecs 11:51:04.761 XRUN callback (196). alsa_pcm: xrun of at least 13.712 msecs 11:51:24.033 XRUN callback (197). delay of 3956.000 usecs exceeds estimated spare time of 2611.000; restart ... 11:51:54.670 XRUN callback (198). alsa_pcm: xrun of at least 0.033 msecs 11:51:56.452 XRUN callback (199). alsa_pcm: xrun of at least 0.039 msecs 11:52:00.756 XRUN callback (200). alsa_pcm: xrun of at least 0.732 msecs 11:52:29.894 XRUN callback (201). The test machine is an Athlon X2 4400 running FC6 x86_64 booting into a rebuilt 2.6.19-rc6-rt8 rpm package based on Ingo's packages (same .config except for 4KSTACKS=off). - jackd and clients running with realtime priorities - irqs priorities reordered with the rtirq script, this is the status after running it: PID CLS RTPRIO NI PRI %CPU STAT COMMAND 5
