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: (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
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
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
* 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 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
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
\ /| \ | /
idle-0 0Dnh2 499us : hrtimer_interrupt (8137a917860
8100382c3e98)
idle-0 0Dnh2 501us : trace_special_sym (8028e5f5 0 0)
idle-0 0Dnh3 503us : effective_prio ...-14029 (-5 -5)
idle-0 0Dnh3 504us : __activate_task ...-14029 (-5 1)
idle-0 0Dnh3 506us+: try_to_wake_up ...-14029 (-5 20)
idle-0 0.n.1 511us+: hrtimer_restart_sched_tick (8137a91b5fb 0)
idle-0 0Dn.2 514us+: enqueue_hrtimer (8137a9b1d75
8100040691f0)
idle-0 0Dn.1 518us+: trace_special_sym (8024a548 0 0)
...-10060 0D..2 522us : thread_return idle-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
\ /| \ | /
idle-0 1Dnh31us+: __trace_start_sched_wakeup ...-746 (29
1)
idle-0 1Dnh34us+: trace_special_sym (80247e98 0 0)
idle-0 1Dnh38us+: try_to_wake_up ...-746 (170 20)
idle-0 1Dnh2 29us+: hrtimer_interrupt (803de15eb1e
81007dfc2160)
idle-0 1Dnh1 34us : trace_special_sym (8028e5f5 0 0)
idle-0 1Dnh2 36us : __activate_task ...-22 (101 1)
idle-0 1Dnh2 38us+: try_to_wake_up ...-22 (101 20)
idle-0 1.n.1 41us : hrtimer_restart_sched_tick (803de16a56b 0)
idle-0 1Dn.2 43us : enqueue_hrtimer (803de1ff5b2
81000407a3f0)
idle-0 1Dn.1 45us+: trace_special_sym (8024a548 0 0)
...-746 1D..2 50us+: thread_return idle-0 (20 170)
...-746 1D.h2
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
| / _=>
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/
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/
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
* 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 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
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 softirq--17 (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
\ /| \ | /
idle-0 1Dnh33us+: __trace_start_sched_wakeup ...-813 (29
1)
idle-0 1Dnh38us+: try_to_wake_up ...-813 (170 20)
idle-0 1Dnh1 22us+: do_IRQ (8026f32c 12 0)
idle-0 1Dnh2 25us+: trace_special_sym (8028f2ad 0 0)
idle-0 1Dnh3 29us+: __activate_task ...-412 (149 1)
idle-0 1Dnh3 33us+: try_to_wake_up ...-412 (149 20)
idle-0 1.n.1 40us+: hrtimer_restart_sched_tick (d48a31262d 0)
idle-0 1Dn.2 44us+: enqueue_hrtimer (d48a527afd
81000407a950)
idle-0 1Dn.1 52us+: trace_special_sym (8024b93e 0 0)
...-813 1D..2 60us+: thread_return idle-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
| / _= need-resched
|| / _---= hardirq/softirq
||| /
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 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: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
\ /| \ | /
idle-0 1Dn.3 4270us+: trace_change_sched_cpu (0 1 0)
idle-0 1Dn.3 4273us : deactivate_task ...-819 (170 2)
idle-0 1Dn.3 4275us : __activate_task ...-819 (170 1)
...-819 1D..2 4278us : thread_return idle-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
* 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
* 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/
