2.6.14-rc3-rt9 - a few xruns misses

2.6.14-rc3-rt9 - a few xruns misses

[Mark Knecht]

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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Ingo Molnar]

* Mark Knecht <markknecht@gmail.com> 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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Mark Knecht]

[-- Attachment #1: Type: text/plain, Size: 6044 bytes --]

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 <mingo@elte.hu> wrote:
>
> * Mark Knecht <markknecht@gmail.com> 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

[-- Attachment #2: knecht.config-2.6.14-rc3-rt10.bz2 --]
[-- Type: application/x-bzip2, Size: 6518 bytes --]

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Lee Revell]

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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Mark Knecht]

On 10/6/05, Lee Revell <rlrevell@joe-job.com> 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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Mark Knecht]

On 10/6/05, Mark Knecht <markknecht@gmail.com> wrote:
> On 10/6/05, Lee Revell <rlrevell@joe-job.com> 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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Lee Revell]

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

Re: 2.6.14-rc3-rt9 - a few xruns misses

[Mark Knecht]

On 10/6/05, Lee Revell <rlrevell@joe-job.com> 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