fc2, xorg, 2.6.x, scheduling latency peaks

Fernando Pablo Lopez-Lezcano nando at ccrma.Stanford.EDU
Wed Jun 2 00:43:23 UTC 2004


On Fri, 2004-05-28 at 11:01, Fernando Pablo Lopez-Lezcano wrote:
> On Thu, 2004-05-27 at 22:58, Arjan van de Ven wrote:
> > On Fri, 2004-05-28 at 02:39, Fernando Pablo Lopez-Lezcano wrote:
> > > On Thu, 2004-05-27 at 17:25, Fernando Pablo Lopez-Lezcano wrote:
> > > > Hi all. I'm trying to track the cause of high scheduling latency peaks
> > > > in FC2 that make the system unusable for low latency audio work. 
> > > > 
> > > > Test systems: PIV laptop, radeon video chipset, AMD64 desktop, radeon
> > > > video chipset. How I test: I run the Jack (Jack Audio Connection Kit)
> > > > sound server with 2 or 3 128 frame buffers for low latency operation
> > > > through the Qjackctl gui front-end. I then start GUI apps that use Jack
> > > > (for example Freqtweak, Hydrogen and Jamin). I see plenty of buffer
> > > > xruns of varying durations during the app load process and afterwards.
> > > 
> > > More data I forgot to include:
> > > Jack is running with SCHED_FIFO priority. For achieving that I run a
> > > custom kernel (currently based on Arjan's 1.391) with preempt enabled
> > > and the realcap kernel module (by Jack O'Quin) added.
> > 
> > can you disable preempt? That should improve latencies....

It does not (in my tests), quite the reverse. 

> I'll try that and report back.

Preempt does not make any difference to the problem I'm seeing. First
some pretty pictures. This is the result of running latencytest 0.5.3
(patched to compile with the newer kernels):

a) 2.6.6-1.391 with preempt on:
http://ccrma.stanford.edu/~nando/latencytest/20040601/2.6.6-1.391.1.ll.rhfc2.ccrma/

b) 2.6.6-1.391 with preempt off:
http://ccrma.stanford.edu/~nando/latencytest/20040601/2.6.6-1.391.2.ll.rhfc2.ccrma/

c) 2.6.6-1.391 with preempt off and bad radeon latency patch (see
comments below):
http://ccrma.stanford.edu/~nando/latencytest/20040601/2.6.6-1.391.3.ll.rhfc2.ccrma/

d) 2.6.6-1.391 with preempt on and bad radeon latency patch:
http://ccrma.stanford.edu/~nando/latencytest/20040601/2.6.6-1.391.4.ll.rhfc2.ccrma/

Some comments: it would seem to me that preempt does make a difference,
the latency spikes tend to be smaller, as I would expect (at least in
what latencytest measures). 

In [c] and [d] I'm applying an additional latency patch to the drm
kernel driver that affects radeon, r128 and mga based cards. The patch
is old and _illegal_ as it does reschedules with a lock on. So far the
computer has not locked up but I guess it is a matter of time :-)
Without this patch or an equivalent properly done patch a computer with
a radeon (or r128/mga) chipset is useless for low latency audio. 

Now, you could say that the graphs look pretty good. 
And I would agree. 
Regretfully latencytest is not all there is. 

A real test with the Jack low latency server reveals that something else
is creating latency hits. This is an example of what I see if I start
jack inside qjackctl (a gui frontend) and after it is running I start
freqtweak, BTW I get similar results running any of the aforementioned
kernel builds (jack is running SCHED_FIFO, with 4 buffers of 128 frames
in this example):

========
17:24:09.745 Startup script...
17:24:09.745 artsshell -q terminate
17:24:10.015 Startup script terminated with exit status=256.
17:24:10.015 JACK is starting...
17:24:10.016 /usr/bin/jackstart -R -dalsa -dhw:0 -r48000 -p128 -n4
17:24:10.022 JACK was started with PID=3051 (0xbeb).
back from read, ret = 1 errno == Success
jackd 0.98.0
Copyright 2001-2003 Paul Davis and others.
jackd comes with ABSOLUTELY NO WARRANTY
This is free software, and you are welcome to redistribute it
under certain conditions; see the file COPYING for details
loading driver ..
apparent rate = 48000
creating alsa driver ... hw:0|hw:0|128|4|48000|0|0|nomon|swmeter|-|32bit
control device hw:0
configuring for 48000Hz, period = 128 frames, buffer = 4 periods
Couldn't open hw:0 for 32bit samples trying 24bit instead
Couldn't open hw:0 for 24bit samples trying 16bit instead
Couldn't open hw:0 for 32bit samples trying 24bit instead
Couldn't open hw:0 for 24bit samples trying 16bit instead
17:24:12.101 Server configuration saved to "/home/nando/.jackdrc"
17:24:12.102 Statistics reset.
17:24:12.452 Client activated.
17:24:12.454 Audio connection change.
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=14,
status = 0, state = Triggered)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=14,
status = 0, state = Triggered)
**** alsa_pcm: xrun of at least 0.115 msecs
17:24:12.494 Audio connection graph change.
**** alsa_pcm: xrun of at least 16.162 msecs
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=14,
status = 0, state = Triggered)
17:24:12.507 XRUN callback. (1)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=14,
status = 0, state = Triggered)
**** alsa_pcm: xrun of at least 0.096 msecs
17:24:12.515 XRUN callback. (2)
**** alsa_pcm: xrun of at least 2.575 msecs
17:24:12.524 XRUN callback. (3)
17:24:12.528 XRUN callback. (4)
17:31:48.938 Audio connection graph change.
17:31:49.064 Audio connection change.
17:31:49.454 Audio connection graph change.
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
delay of 1291.000 usecs exceeds estimated spare time of 1207.000;
restart ...
17:31:49.996 XRUN callback. (5)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Triggered)
**** alsa_pcm: xrun of at least 2.380 msecs
17:31:50.024 XRUN callback. (6)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
delay of 1338.000 usecs exceeds estimated spare time of 1207.000;
restart ...
17:31:50.027 XRUN callback. (7)
17:31:50.037 XRUN callback. (8)
**** alsa_pcm: xrun of at least 3.733 msecs
17:31:50.047 XRUN callback. (9)
**** alsa_pcm: xrun of at least 2.054 msecs
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
subgraph starting at qjackctl-3037 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
**** alsa_pcm: xrun of at least 0.993 msecs
17:31:52.148 XRUN callback. (10)
**** alsa_pcm: xrun of at least 11.116 msecs
17:31:52.164 XRUN callback. (11)
========

.... and so on and so forth. 

So, latencytest is happy but a real test with real applications is not. 

Other important data points:

- xruns seem to be related to graphics activity
- booting FC2 into 2.4.26 with the low latency and preempt patches gives
me similar results (latency hits when running jack and jack apps)
- booting FC1 into 2.4.26 (same hardware, just replace the hard disk)
gives me a rock solid system (no xruns whatsoever, down to 128x2). 

So, it would seem to me that it is not (only) the kernel..........

Things I could not make work:
- testing 2.6.6-1.391.x in FC1. For some reason init does not get
executed, probably a library problem somewhere...

Other stuff I tried:
- getting a better irq for the audio card (on a desktop)
- trying to tune pci latencies

Any ideas on what could cause this????

Please keep in mind that I can use FC1 with 2.4.26 on the exact same
hardware and it works just fine...

-- Fernando






More information about the fedora-devel-list mailing list