advice on how to track xruns...

Hi... I'm trying to track xruns I'm getting on an x86_64 smp
platform
running 2.6.19-rt1 (Ingo's latest and greatest). The kernel
I'm trying
out has latency tracing enabled and I have a hacked jackd
that will
trigger the client traces - and all that seems to be working
fine. 

But it looks like the xruns are not happening because of
that part of
the jack graph, if I understand what I see (I see new higher
latency
traces being triggered but they don't coincide with the xrun
messages
from jack, AFAICT). 

Where else could I insert the <begin tracing> and
<end tracing>
statements so that other parts of the jackd execution path
are covered?
Or do the existing ones cover everything that would need to
be covered?

[BTW: the API for the start/end trace in the realtime kernel
has
changed, I'm including a tiny patch that fixes that against
current cvs]

-- Fernando

------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.php?page=join
.php&p=sourceforge&CID=DEVDEV_______________________
________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

On Friday 01 December 2006 23:49, Fernando Lopez-Lezcano
wrote:
> Hi... I'm trying to track xruns I'm getting on an
x86_64 smp platform
> running 2.6.19-rt1 (Ingo's latest and greatest). The
kernel I'm trying
> out has latency tracing enabled and I have a hacked
jackd that will
> trigger the client traces - and all that seems to be
working fine.
>
> But it looks like the xruns are not happening because
of that part of
> the jack graph, if I understand what I see (I see new
higher latency
> traces being triggered but they don't coincide with the
xrun messages
>
> from jack, AFAICT).
>
> Where else could I insert the <begin tracing> and
<end tracing>
> statements so that other parts of the jackd execution
path are covered?
> Or do the existing ones cover everything that would
need to be covered?
>
> [BTW: the API for the start/end trace in the realtime
kernel has
> changed, I'm including a tiny patch that fixes that
against current cvs]
>
> -- Fernando

Hi,

the preemption check in jackd bacically only covers the
client side. It is run 
in the process of the client and basically checks for
voluntary giveup of the 
cpu by the client process [i.e. doing a sleep() or a lock()
on a previously 
locked mutex, or any other system call that might give up
the cpu].

Some soundcards could produce xruns by having buggy drivers
[or buggy hw]. 
I.e. my cs46xx [which went up in smoke some days ago]
produced an xrun 
reliably somewhere around every 5-10 minutes on an otherwise
perfectly 
tuned -rt system [the ice1712 never showed such a problem -
it just runs and 
runs and runs].

My cs46xx chip in my thinkpad t21 shows the same behaviour..

Anyways, if the driver is at fault, then i suppose there are
scenarios where 
it can produce an xrun without triggering a preemption
check. And jackd could 
in theory at least also be at fault without triggering a
preemption check.

Regards,
Flo

-- 
Palimm Palimm!
http://tapas.affenbande.o
rg

------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

On Sat, 2006-12-02 at 00:50 +0100, Florian Schmidt wrote:
> On Friday 01 December 2006 23:49, Fernando
Lopez-Lezcano wrote:
> > Hi... I'm trying to track xruns I'm getting on an
x86_64 smp platform
> > running 2.6.19-rt1 (Ingo's latest and greatest).
The kernel I'm trying
> > out has latency tracing enabled and I have a
hacked jackd that will
> > trigger the client traces - and all that seems to
be working fine.
> >
> > But it looks like the xruns are not happening
because of that part of
> > the jack graph, if I understand what I see (I see
new higher latency
> > traces being triggered but they don't coincide
with the xrun messages
> >
> > from jack, AFAICT).
> >
> > Where else could I insert the <begin
tracing> and <end tracing>
> > statements so that other parts of the jackd
execution path are covered?
> > Or do the existing ones cover everything that
would need to be covered?
> >
> > [BTW: the API for the start/end trace in the
realtime kernel has
> > changed, I'm including a tiny patch that fixes
that against current cvs]
>
> the preemption check in jackd bacically only covers the
client side. It is run 
> in the process of the client and basically checks for
voluntary giveup of the 
> cpu by the client process [i.e. doing a sleep() or a
lock() on a previously 
> locked mutex, or any other system call that might give
up the cpu].
> 
> Some soundcards could produce xruns by having buggy
drivers [or buggy hw]. 
> I.e. my cs46xx [which went up in smoke some days ago]
produced an xrun 
> reliably somewhere around every 5-10 minutes on an
otherwise perfectly 
> tuned -rt system [the ice1712 never showed such a
problem - it just runs and 
> runs and runs].

This is on an ice1712 which otherwise runs fine (same
hardware as other
machines that are working fine with earlier releases)

> Anyways, if the driver is at fault, then i suppose
there are scenarios where 
> it can produce an xrun without triggering a preemption
check. And jackd could 
> in theory at least also be at fault without triggering
a preemption check.

That was the reason for my question, how to check latencies
from within
jackd that are not originated in the clients themselves... 

-- Fernando



------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

On 12/1/06, Fernando Lopez-Lezcano <nandoccrma.stanford.edu> wrote:
> On Sat, 2006-12-02 at 00:50 +0100, Florian Schmidt
wrote:
> > Anyways, if the driver is at fault, then i suppose
there are scenarios where
> > it can produce an xrun without triggering a
preemption check. And jackd could
> > in theory at least also be at fault without
triggering a preemption check.
>
> That was the reason for my question, how to check
latencies from within
> jackd that are not originated in the clients
themselves...

Don't know for sure, but I can make a guess.  The important
realtime
thread in jackd is the one that waits in the backend for
each period from
the sound card.  For ALSA, this occurs in the poll() at line
1284 of
alsa_driver.c.  Turning on preemption checking just after
this and
turning it off just before might show something of interest.

The only other realtime thread is the watchdog timer.  I
doubt that is
worth fooling with.
-- 
 joq

------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

* Jack O'Quin <jack.oquingmail.com> wrote:

> Don't know for sure, but I can make a guess.  The
important realtime 
> thread in jackd is the one that waits in the backend
for each period 
> from the sound card.  For ALSA, this occurs in the
poll() at line 1284 
> of alsa_driver.c.  Turning on preemption checking just
after this and 
> turning it off just before might show something of
interest.

i'd suggest the following technique:

	prctl(0, 0); // trace off
	prctl(0, 1); // trace on
	poll(...);

start up jackd, and /then/ reset
/proc/sys/kernel/preempt_max_latency 
back to 0.

what does this achieve? Firstly, it traces _everything_.
Secondly, it's 
true that poll() will block, but that is not an issue: if
jackd is 
running then the period is given, right? So if there's a
period of 512 
usecs, then one should see 512+ usecs traces typically. The
moment the 
first xrun comes and we miss the 512 usecs, the delay in
poll() should 
be large, and the trace should capture everything that
happened 
inbetween. The trace buffers are large enough and we can
analyze what 
happens there.

this should capture everything that can happen in the
critical path: all 
the kernel's driver activities, jackd's activities and other
task's 
activities.

NOTE: i'd also suggest turning off xrun printing in the
kernel. Printing 
an xrun in the kernel will only unnecessarily delay
processing and might 
provoke an xrun by itself. You'll see that an xrun happened
if a larger 
latency (say 1500 usecs instead of the typical ~512 usecs)
is recorded 
by the tracer.

the other issue is when the client starves jackd and an xrun
happens due 
to that - is that case easily isolated so that we can see it
from the 
trace that this is indeed what happened?

Fernando, you can even insert your own tracepoints into the
trace, from 
userspace, to make it easier to see what happens. The tracer
will record 
every syscall and its return value:

     cc1-10660 7.... 2587us+> sys_mmap (0000000000000000
0000000000004000 0000000000000003)
     cc1-10660 7.... 2590us+< (47435552079872)

so you can use something like:

	gettimeofday(0x1234, 0x5678);

which should show up as:

     cc1-10660 7.... 2587us+> sys_gettimeofday
(0000000000001234 0000000000005678 0000000000000000)

in the trace, which can then be grepped for.

[ there's also the /proc/sys/kernel/trace_all_cpus option
(off by 
  default), which allows the simultaneous tracing of all
CPUs. This is 
  useful if the xrun only happens on SMP. I'd strongly
suggest to 
  reproduce the xruns on UP first - even if they are smaller
there, 
  because UP is so much easier to trace. ]

> The only other realtime thread is the watchdog timer. 
I doubt that is 
> worth fooling with.

yeah, agreed.

	Ingo

------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

On Sat, Dec 02, 2006 at 12:50:01AM +0100, Florian Schmidt
wrote:
> Some soundcards could produce xruns by having buggy
drivers [or buggy hw]. 
> I.e. my cs46xx [which went up in smoke some days ago]
produced an xrun 
> reliably somewhere around every 5-10 minutes on an
otherwise perfectly 
> tuned -rt system [the ice1712 never showed such a
problem - it just runs and 
> runs and runs].

Unless you run several ice1712 cards with pcm_multi, which
hasn't
worked with any -rt kernel I've tried so far (works fine
with vanilla
kernel with CONFIG_PREEMPT=y). I don't know if that's a bug
in 
pcm_multi or -rt (I suspect the former, but don't know how
to
test that).

John

------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el

On Sat, 2006-12-02 at 09:54 +0100, Ingo Molnar wrote:
> * Jack O'Quin <jack.oquingmail.com> wrote:
> 
> > Don't know for sure, but I can make a guess.  The
important realtime 
> > thread in jackd is the one that waits in the
backend for each period 
> > from the sound card.  For ALSA, this occurs in the
poll() at line 1284 
> > of alsa_driver.c.  Turning on preemption checking
just after this and 
> > turning it off just before might show something of
interest.
> 
> i'd suggest the following technique:

Thanks for the detailed advice... The machine I was using
for testing
died over the weekend, not a beep from the speaker, no bios,
no nothing.
Arghhh...

I'll get something else to test as soon as I can and report
back...
-- Fernando



------------------------------------------------------------
-------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the
chance to share your
opinions on IT & business topics through brief surveys -
and earn cash
http://www.techsay.com/default.
php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
Jackit-devel mailing list
Jackit-devellists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/jackit-dev
el