Re: 2.6.15-rc7-rt1

[Mark Knecht <markknecht@gmail.com>]

On 1/5/06, Mark Knecht <markknecht@gmail.com> wrote:
> On 1/5/06, Lee Revell <rlrevell@joe-job.com> wrote:
> > On Thu, 2006-01-05 at 11:33 -0800, Mark Knecht wrote:
> > > I expect that I am probably still getting a low level of xruns. I
> > > hope one day we can make that work a bit better.
> >
> > Were you ever able to get latency tracing to work on your box?
> >
> > Lee
>
> Not yet, due to the power failure and being off line. I'll give it a
> shot this evening.
>
> Does anyone with an AMD64 platform have this working?
>
> Thanks,
> Mark
>

Hi Lee,
   OK, I rebuilt the new kernel (2.6.15-rt2) with latency tracing
enabled. I still get xruns when running Jack and Aqualung. The tracing
doesn't show anything new although I do have the IRQ off tracing
turned on and don't see the long timer delays that Iused to see.

   What the following shows is that I have a 14uS delay before
mounting my 1394 audio drive. I mount the drive which goes normally. I
then started Aqualung and am just playing some audio from the 1394
drive. I also start MythTV and am streaming a TV show. Along the way I
get another 14uS delay which is fine. However in the process of doing
that I get a 2.9mS xrun but I see nothing in the latency tracing info.

   I can send along the config file if that would help.

<SNIP>
16:20:45.814 Patchbay deactivated.
16:20:45.891 Statistics reset.
16:20:45.952 MIDI connection graph change.
16:20:46.112 MIDI connection change.
16:20:47.701 JACK is starting...
16:20:47.701 /usr/bin/jackd -R -P80 -p512 -dalsa -dhw:1 -r44100 -p64 -n2
16:20:47.713 JACK was started with PID=7942 (0x1f06).
jackd 0.100.5
Copyright 2001-2005 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
JACK compiled with System V SHM support.
loading driver ..
apparent rate = 44100
creating alsa driver ... hw:1|hw:1|64|2|44100|0|0|nomon|swmeter|-|32bit
control device hw:1
configuring for 44100Hz, period = 64 frames, buffer = 2 periods
nperiods = 2 for capture
nperiods = 2 for playback
16:20:49.730 Server configuration saved to "/home/mark/.jackdrc".
16:20:49.731 Statistics reset.
16:20:49.893 Client activated.
16:20:49.895 Audio connection change.
16:20:49.898 Audio connection graph change.
16:21:41.419 Audio connection graph change.
16:21:41.550 Audio connection change.
16:21:43.684 Audio connection graph change.
subgraph starting at qjackctl-7941 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
16:30:47.171 XRUN callback (1).
16:30:47.171 XRUN callback (2).
**** alsa_pcm: xrun of at least 1.422 msecs
**** alsa_pcm: xrun of at least 2.896 msecs
subgraph starting at qjackctl-7941 timed out (subgraph_wait_fd=17,
status = 0, state = Finished)
16:34:40.068 XRUN callback (3).
**** alsa_pcm: xrun of at least 1.196 msecs
**** alsa_pcm: xrun of at least 2.906 msecs
16:34:40.628 XRUN callback (1 skipped).
<SNIP>


(               X-7771 |#0): new 14 us maximum-latency critical section.
  => started at timestamp 165360021: <__schedule+0xb8/0x596>
  =>   ended at timestamp 165360035: <thread_return+0xb5/0x11a>

Call Trace:<ffffffff8014d79f>{check_critical_timing+479}
<ffffffff803c79e0>{unix_poll+ 0}
       <ffffffff8014db78>{sub_preempt_count_ti+88}
<ffffffff80403c0c>{thread_return+70 }
       <ffffffff80403c7b>{thread_return+181} <ffffffff80403de5>{schedule+261}
       <ffffffff804048ed>{schedule_timeout+141}
<ffffffff8013b2e0>{process_timeout+0}
       <ffffffff8018d237>{do_select+967} <ffffffff8018cd80>{__pollwait+0}
       <ffffffff8018d57d>{sys_select+749} <ffffffff8010dc86>{system_call+126}

  =>   dump-end timestamp 165360140

ieee1394: Error parsing configrom for node 0-00:1023
ieee1394: Node changed: 0-00:1023 -> 0-01:1023
ieee1394: Node added: ID:BUS[0-00:1023]  GUID[0050c504e0006463]
scsi4 : SCSI emulation for IEEE-1394 SBP-2 Devices
ieee1394: sbp2: Logged into SBP-2 device
ieee1394: Node 0-00:1023: Max speed [S400] - Max payload [2048]
  Vendor: Maxtor 6  Model: Y160P0            Rev: YAR4
  Type:   Direct-Access-RBC                  ANSI SCSI revision: 04
SCSI device sdb: 320173056 512-byte hdwr sectors (163929 MB)
sdb: asking for cache data failed
sdb: assuming drive cache: write through
SCSI device sdb: 320173056 512-byte hdwr sectors (163929 MB)
sdb: asking for cache data failed
sdb: assuming drive cache: write through
  sdb: sdb1 sdb2 sdb3
sd 4:0:0:0: Attached scsi disk sdb
EXT3-fs warning: maximal mount count reached, running e2fsck is recommended
kjournald starting.  Commit interval 5 seconds
EXT3 FS on sdb1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
(               X-7771 |#0): new 14 us maximum-latency critical section.
  => started at timestamp 900866152: <__schedule+0xb8/0x596>
  =>   ended at timestamp 900866166: <thread_return+0xb5/0x11a>

Call Trace:<ffffffff8014d79f>{check_critical_timing+479}
<ffffffff8014db78>{sub_preemp t_count_ti+88}
       <ffffffff80403c0c>{thread_return+70}
<ffffffff80403c7b>{thread_return+181}
       <ffffffff80403de5>{schedule+261} <ffffffff804048ed>{schedule_timeout+141}
       <ffffffff8013b2e0>{process_timeout+0} <ffffffff8018d237>{do_select+967}
       <ffffffff8018cd80>{__pollwait+0} <ffffffff8018d57d>{sys_select+749}
       <ffffffff8010dab2>{sys_rt_sigreturn+578}
<ffffffff8010dc86>{system_call+126}

  =>   dump-end timestamp 900866281

lightning ~ #

Thanks,
Mark