Hi,
This is nothing particularily new. I'm just presenting it to
represent what I'm seeign and get some guidance about how to find out
what's going on.
This is my AMD64 machine. It was VERY lightly loaded. Just Gnome
and Aqualung which was running using Jack. Around 1PM I went to the
other room to watch a DVD and returned around 3PM. The only thing I
can think of that would cause an xrun around 1:23 or 1:34 would be
xscreensaver, or possibly soem updatedb operation that might have
started.
When I returned at 3PM I started copying some audio files across
the network to a ogg file server. This was about 400MB of data. The
copies worked fine but during the copies I got a few more xruns:
12:08:46.070 Audio connection change.
12:08:48.119 Audio connection graph change.
subgraph starting at qjackctl-8905 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
12:10:27.191 XRUN callback (1).
**** alsa_pcm: xrun of at least 3.553 msecs
13:23:38.218 XRUN callback (2).
**** alsa_pcm: xrun of at least 2.263 msecs
subgraph starting at qjackctl-8905 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
13:34:39.647 XRUN callback (3).
**** alsa_pcm: xrun of at least 6.233 msecs
15:15:46.072 XRUN callback (4).
**** alsa_pcm: xrun of at least 2.339 msecs
15:20:08.262 XRUN callback (5).
**** alsa_pcm: xrun of at least 0.098 msecs
subgraph starting at qjackctl-8905 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
15:20:40.459 XRUN callback (6).
**** alsa_pcm: xrun of at least 5.159 msecs
15:36:21.595 XRUN callback (7).
**** alsa_pcm: xrun of at least 0.462 msecs
16:05:41.308 Audio connection graph change.
16:05:41.430 Audio connection graph change.
After the copies stopped the machine was idle until I wrote this
email. I'm also running MythTV on here right now. No problems.
Just a few xruns I'd like to better understand and get rid of over time.
lightning ~ # lsmod
Module Size Used by
realtime 13832 0
snd_seq_midi 11456 0
snd_pcm_oss 54304 1
snd_mixer_oss 20480 2 snd_pcm_oss
snd_seq_oss 37120 0
snd_seq_midi_event 11392 2 snd_seq_midi,snd_seq_oss
snd_seq 58848 8 snd_seq_midi,snd_seq_oss,snd_seq_midi_event
sbp2 27652 3
ohci1394 35532 0
ieee1394 99888 2 sbp2,ohci1394
snd_hdsp 54724 4
snd_rawmidi 27680 2 snd_seq_midi,snd_hdsp
snd_seq_device 10892 3 snd_seq_midi,snd_seq_oss,snd_rawmidi
snd_hwdep 12960 1 snd_hdsp
snd_intel8x0 37408 3
snd_ac97_codec 107224 1 snd_intel8x0
snd_ac97_bus 7168 1 snd_ac97_codec
snd_pcm 92296 6
snd_pcm_oss,snd_hdsp,snd_intel8x0,snd_ac97_codecsnd_timer
26120 2 snd_seq,snd_pcm
snd 55752 21
snd_pcm_oss,snd_mixer_oss,snd_seq_oss,snd_seq,snd_hdsp,snd_rawmidi,snd_seq_device,snd_hwdep,snd_intel8x0,snd_ac97_codec,snd_pcm,snd_timer
snd_page_alloc 13328 3 snd_hdsp,snd_intel8x0,snd_pcm
lightning ~ #
lightning ~ # uname -a
Linux lightning 2.6.14-rc3-rt9 #1 SMP PREEMPT Wed Oct 5 09:16:16 PDT
2005 x86_64 AMD Athlon(tm) 64 Processor 3000+ AuthenticAMD GNU/Linux
lightning ~ #
Thanks,
Mark
* Mark Knecht <[email protected]> wrote:
> Hi,
> This is nothing particularily new. I'm just presenting it to
> represent what I'm seeign and get some guidance about how to find out
> what's going on.
lets first check whether all the RT priorities are set up correctly for
your audio setup. Could you send me your /proc/interrupts, your .config
and the output of:
ps -eo pid,pri,rtprio,cmd
there are lots of built-in methods in the -rt kernel to figure out the
source of latencies. If the default methods do not show anything then
worst-case we can activate the kernel's latency tracer to record the
actual xrun critical path.
Ingo
NOTE: THere are many messages I haven't read through yet so I may send
more data later as per requests there.
On 10/6/05, Ingo Molnar <[email protected]> wrote:
>
> * Mark Knecht <[email protected]> wrote:
>
> > Hi,
> > This is nothing particularily new. I'm just presenting it to
> > represent what I'm seeign and get some guidance about how to find out
> > what's going on.
>
> lets first check whether all the RT priorities are set up correctly for
> your audio setup. Could you send me your /proc/interrupts, your .config
> and the output of:
>
> ps -eo pid,pri,rtprio,cmd
>
> there are lots of built-in methods in the -rt kernel to figure out the
> source of latencies. If the default methods do not show anything then
> worst-case we can activate the kernel's latency tracer to record the
> actual xrun critical path.
>
> Ingo
>
Hi Ingo,
OK, so starting the day I saw that you had posted -rt10 so that's
what I'm working with now:
lightning ~ # uname -a
Linux lightning 2.6.14-rc3-rt10 #1 SMP PREEMPT Thu Oct 6 08:14:03 PDT
2005 x86_64 AMD Athlon(tm) 64 Processor 3000+ AuthenticAMD GNU/Linux
lightning ~ #
The sound card that is critical to this machine is the hdsp one at IRQ
58. The one at 225 is not used in realtime mode.
lightning ~ # cat /proc/interrupts
CPU0
0: 39462 IO-APIC-edge timer
1: 210 IO-APIC-edge i8042
7: 2 IO-APIC-edge lpptest
8: 0 IO-APIC-edge rtc
9: 0 IO-APIC-level acpi
12: 6286 IO-APIC-edge i8042
14: 48 IO-APIC-edge ide0
50: 2 IO-APIC-level ehci_hcd:usb1
58: 3922 IO-APIC-level hdsp
66: 2 IO-APIC-level ohci1394
217: 13592 IO-APIC-level ohci_hcd:usb2, eth0
225: 0 IO-APIC-level libata, NVidia CK804
233: 11973 IO-APIC-level libata
NMI: 72
LOC: 39417
ERR: 1
MIS: 0
lightning ~ #
lightning ~ # cat /proc/asound/cards
0 [CK804 ]: NFORCE - NVidia CK804
NVidia CK804 with ALC850 at 0xda103000, irq 225
1 [DSP ]: H-DSP - Hammerfall DSP
RME Hammerfall HDSP 9652 at 0xda000000, irq 58
lightning ~ #
lightning ~ # ps -eo pid,pri,rtprio,cmd
PID PRI RTPRIO CMD
1 23 - init [3]
2 139 99 [migration/0]
3 41 1 [softirq-high/0]
4 41 1 [softirq-timer/0]
5 41 1 [softirq-net-tx/]
6 41 1 [softirq-net-rx/]
7 41 1 [softirq-scsi/0]
8 41 1 [softirq-tasklet]
9 34 - [desched/0]
10 41 1 [events/0]
11 28 - [khelper]
12 28 - [kthread]
14 19 - [kacpid]
15 89 49 [IRQ 9]
130 29 - [kblockd/0]
133 29 - [khubd]
202 22 - [pdflush]
203 24 - [pdflush]
205 27 - [aio/0]
204 14 - [kswapd0]
798 88 48 [IRQ 8]
801 87 47 [IRQ 7]
802 29 - [kseriod]
805 86 46 [IRQ 12]
815 85 45 [IRQ 6]
850 84 44 [IRQ 14]
861 29 - [ata/0]
865 27 - [scsi_eh_0]
866 27 - [scsi_eh_1]
867 83 43 [IRQ 225]
870 27 - [scsi_eh_2]
871 27 - [scsi_eh_3]
872 82 42 [IRQ 233]
887 81 41 [IRQ 50]
893 80 40 [IRQ 217]
908 79 39 [IRQ 1]
912 24 - [kjournald]
970 26 - udevd
4545 78 38 [IRQ 58]
4599 24 - [khpsbpkt]
4694 77 37 [IRQ 66]
4695 23 - [knodemgrd_0]
6321 24 - /usr/sbin/syslog-ng
7111 23 - /usr/sbin/cupsd
7117 76 36 [IRQ 4]
7188 22 - /usr/sbin/sshd
7224 23 - /usr/sbin/cron
7343 23 - /sbin/portmap
7370 27 - [rpciod/0]
7371 23 - [lockd]
7394 22 - /sbin/agetty 38400 tty1 linux
7398 22 - /sbin/agetty 38400 tty2 linux
7400 22 - /sbin/agetty 38400 tty3 linux
7401 23 - /sbin/agetty 38400 tty4 linux
7408 23 - /sbin/agetty 38400 tty5 linux
7409 23 - /sbin/agetty 38400 tty6 linux
7527 23 - /usr/bin/gdm
7529 23 - /usr/bin/gdm
7534 23 - /usr/X11R6/bin/X :0 -audit 0 -auth /var/gdm/:0.Xauth
-nolisten tcp vt7
7567 23 - gnome-session
7582 23 - /usr/bin/ssh-agent -- gnome-session
7584 23 - /usr/libexec/gconfd-2 5
7587 21 - /usr/bin/gnome-keyring-daemon
7589 23 - /usr/libexec/bonobo-activation-server --ac-activate
--ior-output-fd=19
7591 23 - /usr/libexec/gnome-settings-daemon
--oaf-activate-iid=OAFIID:GNOME_SettingsDaemon --oa 7601 24 -
xscreensaver -nosplash
7627 24 - metacity --sm-save-file 1126471293-7521-180409387.ms
7629 23 - nautilus --sm-config-prefix /nautilus-pR56zY/
--sm-client-id 11c0a80138000112560470300 7631 23 - gnome-panel
--sm-config-prefix /gnome-panel-Ckbfvi/ --sm-client-id
11c0a80138000112627 7648 23 - /usr/libexec/gnome-vfs-daemon
--oaf-activate-iid=OAFIID:GNOME_VFS_Daemon_Factory --oaf 7656 23
- /usr/libexec/mapping-daemon
7659 24 - /usr/libexec/mixer_applet2
--oaf-activate-iid=OAFIID:GNOME_MixerApplet_Factory --oaf-i 7661 23
- /usr/libexec/clock-applet
--oaf-activate-iid=OAFIID:GNOME_ClockApplet_Factory --oaf-io 7663 23
- /usr/libexec/wnck-applet
--oaf-activate-iid=OAFIID:GNOME_Wncklet_Factory --oaf-ior-fd= 7665 23
- /usr/bin/gnome-terminal
7666 21 - gnome-pty-helper
7667 24 - bash
7672 22 - su -
7675 23 - -bash
8398 24 - hdspmixer
8400 24 - qjackctl
8402 20 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
8410 23 - /bin/bash /usr/libexec/mozilla-launcher
8421 24 - /opt/firefox/firefox-bin
8437 22 - ps -eo pid,pri,rtprio,cmd
lightning ~ #
Even with Jack running I don't see the jackd process getting any
special priority. Is this correct, or is that part that gets higher
prioity just not listed here.
.config attached.
Thanks!
- Mark
On Thu, 2005-10-06 at 09:00 -0700, Mark Knecht wrote:
> Even with Jack running I don't see the jackd process getting any
> special priority. Is this correct, or is that part that gets higher
> prioity just not listed here.
ps does not show all threads of multithreaded processes by default.
Use:
ps -Leo pid,pri,rtprio,cmd
and you should see that 2 JACK threads get RT priority.
Lee
On 10/6/05, Lee Revell <[email protected]> wrote:
> On Thu, 2005-10-06 at 09:00 -0700, Mark Knecht wrote:
> > Even with Jack running I don't see the jackd process getting any
> > special priority. Is this correct, or is that part that gets higher
> > prioity just not listed here.
>
> ps does not show all threads of multithreaded processes by default.
> Use:
>
> ps -Leo pid,pri,rtprio,cmd
>
> and you should see that 2 JACK threads get RT priority.
>
> Lee
Thanks Lee. That's what I thought might be happening.
8398 24 - hdspmixer
8400 24 - qjackctl
8400 49 9 qjackctl
8402 20 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
8402 20 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
8402 23 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
8402 60 20 /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
8402 50 10 /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
Cheers,
Mark
On 10/6/05, Mark Knecht <[email protected]> wrote:
> On 10/6/05, Lee Revell <[email protected]> wrote:
> > On Thu, 2005-10-06 at 09:00 -0700, Mark Knecht wrote:
> > > Even with Jack running I don't see the jackd process getting any
> > > special priority. Is this correct, or is that part that gets higher
> > > prioity just not listed here.
> >
> > ps does not show all threads of multithreaded processes by default.
> > Use:
> >
> > ps -Leo pid,pri,rtprio,cmd
> >
> > and you should see that 2 JACK threads get RT priority.
> >
> > Lee
>
> Thanks Lee. That's what I thought might be happening.
>
> 8398 24 - hdspmixer
> 8400 24 - qjackctl
> 8400 49 9 qjackctl
> 8402 20 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
> 8402 20 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
> 8402 23 - /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
> 8402 60 20 /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
> 8402 50 10 /usr/bin/jackd -R -dalsa -dhw:1 -r44100 -p128 -n2
>
> Cheers,
> Mark
>
Hi Ingo,
OK, after about an hour or moderately heavy usage while running
Jack - I've built a new new kernel, done an emerge sync and am in the
process of an emerge world right now (it's building glibc) along with
playing music and browsing the web - I just had my first xrun:
configuring for 44100Hz, period = 128 frames, buffer = 2 periods
nperiods = 2 for capture
nperiods = 2 for playback
08:51:42.919 Server configuration saved to "/home/mark/.jackdrc".
08:51:42.919 Statistics reset.
08:51:43.037 Client activated.
08:51:43.038 Audio connection change.
08:51:43.042 Audio connection graph change.
09:11:52.063 Audio connection graph change.
09:11:52.122 Audio connection change.
09:11:54.217 Audio connection graph change.
subgraph starting at qjackctl-8400 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
09:54:17.656 XRUN callback (1).
**** alsa_pcm: xrun of at least 4.351 msecs
So....how do I begin to find out what caused that, or will cause
similar xruns in the future?
Is it that rt priorities are not set up correctly? Or is it something else?
I must say that the kernel has really improved for me over the last
couple of weeks. This is great performance from where I was before I
joined the LKML. I think you guys are making good progress, most
especially for my AMD64 platform.
Thanks!
Cheers,
Mark
On Thu, 2005-10-06 at 10:06 -0700, Mark Knecht wrote:
> Is it that rt priorities are not set up correctly? Or is it something else?
Yes. JACK is running at a lower priority on your system than all the
IRQ threads. So disk activity is likely to cause xruns. In qjackctl's
Setup screen set "Priority" to 80.
Lee
On 10/6/05, Lee Revell <[email protected]> wrote:
> On Thu, 2005-10-06 at 10:06 -0700, Mark Knecht wrote:
> > Is it that rt priorities are not set up correctly? Or is it something else?
>
> Yes. JACK is running at a lower priority on your system than all the
> IRQ threads. So disk activity is likely to cause xruns. In qjackctl's
> Setup screen set "Priority" to 80.
>
> Lee
>
>
OK, done. Testing will likely take a while to be sure that this is enough.
Is there anything I should be doing with the priority of my HDSP ISR?
That change back on 2.6.9-rtX was like a light switch for turning off
xruns at that time.
Thanks,
Mark