Re: [patch] Real-Time Preemption, -RT-2.6.9-mm1-V0.4

From: Florian Schmidt
Date: Fri Oct 29 2004 - 09:21:59 EST


On Thu, 28 Oct 2004 17:33:50 +0100 (WEST)
"Rui Nuno Capela" <rncbc@xxxxxxxxx> wrote:

> OK. Here are my early consolidated results. Feel free to comment.
>
> 2.6.9 RT-U3 RT-V0.4.3
> --------- --------- ---------
> XRUN Rate . . . . . . . . . . . 424 8 4 /hour
> Delay Rate (>spare time) . . . 496 0 0 /hour
> Delay Rate (>1000 usecs) . . . 940 8 4 /hour
> Maximum Delay . . . . . . . . . 6904 921 721 usecs
> Maximum Process Cycle . . . . . 1449 1469 1590 usecs
> Average DSP CPU Load . . . . . 38 39 40 %
> Average Context-Switch Rate . . 7480 8929 9726 /sec
>
> Note: all tests were carried out running jackd -v -dalsa -dhw:0 -r44100
> -p128 -n2 -S -P, loaded with 9 (nine) fluidsynth instances, on a
> P4@xxxxxxxx laptop, against the onboard sound device (snd-ali5451).
>
> On the RT kernels only, the following optimizations were issued:
>
> chrt --pid --fifo 90 2 (pidof "ksoftirqd/0" = 2)
> chrt --pid --fifo 60 `pidof "IRQ 5"` (snd-ali5451)
>
> Take care.

hi,

i tried a V0.5.2 with PREEMPT_REALTIME and all debugging off (config
attached). I cannot reproduce your results. I have experienced around 30
xruns in 10 minutes. And big ones, too (> 5ms). I don't know exactly what
kind of load triggers them. Here's a bit of qjackctl message window (btw:
jackd was idle, no clients connected, except for qjackctl):

**** alsa_pcm: xrun of at least 0.594 msecs
**** alsa_pcm: xrun of at least 0.037 msecs
16:20:44.832 XRUN callback (2).
16:20:44.840 XRUN callback (3).
**** alsa_pcm: xrun of at least 0.024 msecs
**** alsa_pcm: xrun of at least 3.682 msecs
16:22:59.834 XRUN callback (4).
16:22:59.839 XRUN callback (5).
**** alsa_pcm: xrun of at least 0.016 msecs
**** alsa_pcm: xrun of at least 3.460 msecs
16:23:03.513 XRUN callback (6).
**** alsa_pcm: xrun of at least 2.028 msecs
16:23:03.869 XRUN callback (7).
**** alsa_pcm: xrun of at least 7.061 msecs
**** alsa_pcm: xrun of at least 4.510 msecs
16:23:03.894 XRUN callback (8).
16:23:03.895 XRUN callback (9).
**** alsa_pcm: xrun of at least 0.428 msecs
**** alsa_pcm: xrun of at least 0.157 msecs
16:23:54.546 XRUN callback (10).
16:23:54.547 XRUN callback (11).
16:23:54.549 XRUN callback (12).
**** alsa_pcm: xrun of at least 1.507 msecs
16:25:49.194 XRUN callback (13).
subgraph starting at qjackctl-1013 timed out (subgraph_wait_fd=14, status = 0, state = Triggered)
**** alsa_pcm: xrun of at least 1.534 msecs
16:28:23.530 XRUN callback (14).
**** alsa_pcm: xrun of at least 0.222 msecs
**** alsa_pcm: xrun of at least 2.674 msecs
**** alsa_pcm: xrun of at least 3.904 msecs
16:28:26.790 XRUN callback (15).
16:28:26.794 XRUN callback (16).
16:28:26.795 XRUN callback (17).
**** alsa_pcm: xrun of at least 0.701 msecs

Here's some setup info:

ksoftirqd/0:
mango:~# chrt -p 2
pid 2's current scheduling policy: SCHED_FIFO
pid 2's current scheduling priority: 99

snd-cs46xx:
mango:~# chrt -p `pidof "IRQ 3"`
pid 118's current scheduling policy: SCHED_FIFO
pid 118's current scheduling priority: 90

mango:~# pidof jackd
1014
mango:~# chrt -p 1014
pid 1014's current scheduling policy: SCHED_OTHER
pid 1014's current scheduling priority: 0
mango:~# chrt -p 1015
pid 1015's current scheduling policy: SCHED_OTHER
pid 1015's current scheduling priority: 0
mango:~# chrt -p 1016
pid 1016's current scheduling policy: SCHED_FIFO
pid 1016's current scheduling priority: 70
mango:~# chrt -p 1017
pid 1017's current scheduling policy: SCHED_FIFO
pid 1017's current scheduling priority: 60

Hmm, it seems i haven't disabled all debugging. This is from dmesg:

BUG: atomic counter underflow at:
[<c010649e>] dump_stack+0x1e/0x20 (20)
[<c025f319>] qdisc_destroy+0xd9/0xe0 (28)
[<c025f506>] dev_shutdown+0x36/0xb0 (28)
[<c0254679>] unregister_netdevice+0x129/0x2b0 (40)
[<c0221919>] unregister_netdev+0x19/0x40 (16)
[<f0902134>] ppp_shutdown_interface+0x64/0xd0 [ppp_generic] (36)
[<f08fe0a6>] ppp_release+0x86/0x90 [ppp_generic] (16)
[<c0155c3f>] __fput+0x14f/0x170 (36)
[<c0154457>] filp_close+0x57/0x80 (28)
[<c01544f0>] sys_close+0x70/0x90 (32)
[<c0105ecf>] syscall_call+0x7/0xb (-8124)

Here's some context from syslog:

Oct 29 15:04:01 mango pppd[324]: LCP: timeout sending Config-Requests
Oct 29 15:04:01 mango pppd[324]: Connection terminated.
Oct 29 15:04:01 mango kernel: BUG: atomic counter underflow at:
Oct 29 15:04:01 mango kernel: [valid_stack_ptr+46/96] dump_stack+0x1e/0x20 (20)
Oct 29 15:04:01 mango kernel: [unregister_netdevice+553/672] qdisc_destroy+0xd9/0xe0 (28)
Oct 29 15:04:01 mango kernel: [ethtool_op_get_tso+6/32] dev_shutdown+0x36/0xb0 (28)
Oct 29 15:04:01 mango kernel: [__sock_create+185/704] unregister_netdevice+0x129/0x2b0 (40)
Oct 29 15:04:01 mango kernel: [blk_wait_queue_drained+25/304] unregister_netdev+0x19/0x40 (16)
Oct 29 15:04:01 mango kernel: [pg0+810783028/1069765632] ppp_shutdown_interface+0x64/0xd0 [ppp_generic] (36)
Oct 29 15:04:01 mango kernel: [pg0+810766502/1069765632] ppp_release+0x86/0x90 [ppp_generic] (16)
Oct 29 15:04:01 mango kernel: [shmem_writepage+463/480] __fput+0x14f/0x170 (36)
Oct 29 15:04:01 mango kernel: [sys_swapon+1591/2080] filp_close+0x57/0x80 (28)
Oct 29 15:04:01 mango kernel: [sys_swapon+1744/2080] sys_close+0x70/0x90 (32)
Oct 29 15:04:01 mango kernel: [do_notify_resume+15/76] syscall_call+0x7/0xb (-8124)
Oct 29 15:04:10 mango pppoe[326]: Timeout waiting for PADS packets
Oct 29 15:04:31 mango pppd[324]: Serial connection established.
Oct 29 15:04:31 mango pppd[324]: Using interface ppp0
Oct 29 15:04:31 mango pppd[324]: Connect: ppp0 <--> /dev/pts/0
Oct 29 15:04:47 mango pppoe[822]: PADS: Service-Name: ''
Oct 29 15:04:47 mango pppoe[822]: PPP session is 2133
Oct 29 15:04:47 mango pppd[324]: CHAP authentication succeeded
Oct 29 15:04:48 mango pppd[324]: Cannot determine ethernet address for proxy ARP
Oct 29 15:04:48 mango pppd[324]: local IP address 213.23.197.161
Oct 29 15:04:48 mango pppd[324]: remote IP address 145.253.4.148
Oct 29 15:04:48 mango pppd[324]: primary DNS address 195.50.140.250
Oct 29 15:04:48 mango pppd[324]: secondary DNS address 145.253.2.11

flo

Attachment: .config
Description: Binary data