2.6.15-rt2 - repeatable xrun - no good data in trace

[Mark Knecht <markknecht@gmail.com>]

Hi,
   I did run across a way that I can create a repeatable xrun on my
AMD64 machine by burning a CD in k3b while Jack is running.
Unfortunately I do not see any good trace data in dmesg when I do it.
Here's what I see in Jack. I burning the same iso file 3 times to make
sure it was repeatable:

09:35:33.113 Server configuration saved to "/home/mark/.jackdrc".
09:35:33.113 Statistics reset.
09:35:33.557 Client activated.
09:35:33.559 Audio connection change.
09:35:33.563 Audio connection graph change.
09:35:33.762 Audio connection change.
09:35:33.762 Audio connection graph change.
09:35:33.964 Audio connection change.
09:35:36.037 Audio connection graph change.
11:50:22.792 XRUN callback (1).
delay of 14728.000 usecs exceeds estimated spare time of 1360.000; restart ...
delay of 3184.000 usecs exceeds estimated spare time of 1360.000; restart ...
11:50:22.983 XRUN callback (2).
**** alsa_pcm: xrun of at least 0.039 msecs
delay of 2908.000 usecs exceeds estimated spare time of 1360.000; restart ...
11:50:23.407 XRUN callback (2 skipped).
11:51:13.405 XRUN callback (5).
**** alsa_pcm: xrun of at least 0.027 msecs
12:28:58.864 XRUN callback (6).
delay of 2893.000 usecs exceeds estimated spare time of 1363.000; restart ...
**** alsa_pcm: xrun of at least 0.044 msecs
delay of 9293.000 usecs exceeds estimated spare time of 1363.000; restart ...
12:28:59.265 XRUN callback (2 skipped).
12:39:26.418 XRUN callback (9).
delay of 11516.000 usecs exceeds estimated spare time of 1388.000; restart ...
delay of 8877.000 usecs exceeds estimated spare time of 1388.000; restart ...
12:39:28.373 XRUN callback (1 skipped).
12:40:18.427 XRUN callback (11).
**** alsa_pcm: xrun of at least 0.023 msecs


In dmesg I'm getting only this:

(      dcopserver-8733 |#0): new 10 us maximum-latency critical section.
 => started at timestamp 12171220117: <preempt_schedule+0x53/0xb0>
 =>   ended at timestamp 12171220128: <schedule_tail+0xaa/0x110>

Call Trace:<ffffffff8014d79f>{check_critical_timing+479}
<ffffffff8014db78>{sub_ preempt_count_ti+88}
       <ffffffff8012c3a3>{schedule_tail+67}
<ffffffff8012c40a>{schedule_tail+170 }
       <ffffffff8010db79>{ret_from_fork+5}
 =>   dump-end timestamp 12171220195

(               X-7777 |#0): new 13 us maximum-latency critical section.
 => started at timestamp 12183810145: <__schedule+0xb8/0x596>
 =>   ended at timestamp 12183810158: <thread_return+0xb5/0x11a>

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

 =>   dump-end timestamp 12183810266

Jack is 100.7 from portage. k3b is 0.12.10 from portage. The DVD/CDRW
drive is EIDE based.

Ideas?

- Mark