this is a trace generated with printk, rdtscll and some post-perl
munging. the cycles were trimmed to the significant range. i have
added commentary.
i am tracing 3 functions in the ALSA kernel code:
snd_pcm_capture_poll
snd_pcm_playback_poll
snd_pcm_hw_ptr_interrupt
both poll routines have static counters to track how many times they
are called, these show up in the trace below.
also, please recall the central loop in the kernel do_poll() routine:
for (;;) {
unsigned int i;
set_current_state(TASK_INTERRUPTIBLE);
count = 0;
for (i=0; i < nchunks; i++)
do_pollfd(POLLFD_PER_PAGE, fds[i], &pt, &count);
if (nleft)
do_pollfd(nleft, fds[nchunks], &pt, &count);
pt = NULL;
if (count || !timeout || signal_pending(current))
break;
count = wait->error;
if (count)
break;
timeout = schedule_timeout(timeout);
}
current->state = TASK_RUNNING;
this means that the ALSA routine will always be called twice per
poll(2) if the task sleeps: once before the sleep, and once when it wakes up.
scenario: trident, 64 frame period, 64 frame avail_min, 128 frame
buffer, SR=44100, period interval = 1.45msecs
in what follows, i follow the trace until the first error. in the
actual traces, i have many of these kinds of events - they occur very
frequently. it didn't seem worth showing more than 1 at this point.
to me, this strongly suggests a problem with full duplex operation and
poll, at least for the trident driver.
--p
--------------------------------------------------------------------
Elapsed(msecs) Interval(usecs) Cycles Event [count:] avail = N
--------------------------------------------------------------------
the first poll call, with both descriptors. note 20usecs
between calls into the ALSA poll routines.
0.000000 ------ 7165190 playback poll 0: avail = 0
0.020551 20.551 7174438 capture poll 0: avail = 0
nothing was available, so we slept for 1.34msecs and then
we're woken up. note the 17usecs between wakeups.
1.341258 1320.707 7768756 wakeup stream playback with 65
1.358256 16.998 7776405 wakeup stream capture with 64
do_poll() makes its second call to the ALSA poll routines,
with both descriptors
1.377356 19.100 7785000 playback poll 1: avail = 65
1.385587 8.231 7788704 capture poll 1: avail = 64
third poll call with both descriptors (10usecs separates calls
to the ALSA poll functions). "nothing" available, so we sleep.
1.649220 263.633 7907339 playback poll 2: avail = 1
1.659400 10.180 7911920 capture poll 2: avail = 0
ok, new period, we wake up both streams (1.2msec after sleeping)
2.822569 1163.169 8435346 wakeup stream playback with 66
2.837836 15.267 8442216 wakeup stream capture with 65
do_poll() calls ALSA poll functions again
2.852616 14.780 8448867 playback poll 3: avail = 66
2.860751 8.136 8452528 capture poll 3: avail = 65
next call to poll, "nothing" available, so we sleep
3.086562 225.811 8554143 playback poll 4: avail = 2
3.096738 10.176 8558722 capture poll 4: avail = 1
next period (1.2msecs later) we wake up the playback stream
4.243527 1146.789 9074777 wakeup stream playback with 65
do_poll() checks avail again, playback OK, capture has nothing
4.262256 18.729 9083205 playback poll 5: avail = 65
4.270720 8.464 9087014 capture poll 5: avail = 1
19usecs later, we wake up the capture stream
4.289936 19.216 9095661 wakeup stream capture with 65
user space calls back into poll to see if capture stream is ready,
and indeed it is. no race occured there.
4.456404 166.469 9170572 capture poll 6: avail = 65
next call to poll with both descriptors, nothing available, so sleep
4.638300 181.896 9252425 playback poll 6: avail = 1
4.647751 9.451 9256678 capture poll 7: avail = 1
next period, wake up just playback stream
5.729311 1081.560 9743380 wakeup stream playback with 66
5.747478 18.167 9751555 playback poll 7: avail = 66
user space calls back to check on capture stream, its not ready
<-------- KEY MOMENT ----------->
i don't know why we see this twice. its somewhat like the
2 calls to the poll routine caused by do_poll(), except that we
can see that the task is not woken because avail is too small. it
didn't timeout either: the timeout is set to 1 second.
what i do see is that we haven't woken up the capture stream since
4.29 msecs. note how long until we do it again ...
<------------------------------->
5.760960 13.482 9757622 capture poll 8: avail = 1
5.914029 153.069 9826503 capture poll 9: avail = 1
next period, wakeup playback stream; user space is still asleep
waiting on the capture stream.
7.165711 1251.682 10389760 wakeup stream playback with 129
next period, wakeup playback stream, user space is still asleep,
waiting on the capture stream.
8.628598 1462.887 11048059 wakeup stream playback with 193
same period, wake up capture stream
<------ KEY MOMENT ---------------->
this is the first time we woke the capture stream since 4.29msec;
4.34msec have elapsed. what happened?
<---------------------------------->
8.656880 28.282 11060786 wakeup stream capture with 65
we return from the poll on the capture stream made at 5.91msec,
finally having data (and having let an xrun happen)
8.685029 28.149 11073453 capture poll 10: avail = 65
call poll with both descriptors, nothing available so sleep
9.010920 325.891 11220104 playback poll 8: avail = 0
9.024667 13.747 11226290 capture poll 11: avail = 0
next period, (1.34msec later) wake up playback stream
10.362140 1337.473 11828153 wakeup stream playback with 65
Etc. etc.
_______________________________________________
Alsa-devel mailing list
[EMAIL PROTECTED]
https://lists.sourceforge.net/lists/listinfo/alsa-devel
