[alsa-devel] Sound disappears after a long run, pcm_rate plugin maybe

[Takashi Iwai]

At Thu, 28 Jun 2007 11:29:58 +1000,
Dave Airlie wrote:
> 
> Hi,
> 
> I've been debugging this bug which I first noticed close to a year ago
> but worked around by disabling dmix. Now I've had to enable dmix and
> try and fix it.
> 
> My system is  SDL on alsa-lib-1.0.13 on 2.6.21 on intel 810 with a
> Realtek ALC655.
> 
> I'm using SDL to open a 22050 16-bit stereo stream, and dmix is set to 48000.
> 
> When I run sound in my single app (only one app running for testing
> purposes) around 20-24 hours later (I haven't got exact timings as I
> can't sit in front of the pc for so long) the sound stop s happening
> just in that app.
> 
> I can run aplay separately and it plays fine.
> 
> If I stop my app (ctrl-C and cont in gdb) or attach/detach strace, I
> get an XRUN and my SDL code calls snd_pcm_prepare and the sounds comes
> back. Now I can't tell you how much it sucks to only get a single
> debugging run every 24 hours for 1 break point and if gdb stuffs it up
> you lose big time.
> 
> I think I've tracked it down to pcm_rate.c as in if I open the sound
> card at 48000 instead of 22050 it doesn't happen and I've added a lot
> of printfs to the rate code in 1.0.13 and gotten huge log file traces
> of it..
> 
> In a normal rate trace when things are working I get traces like this:
> snd_pcm_rate_sync_playback_area: 442023720 442023720 525 986185728
> snd_pcm_rate_sync_playback_area: 442023720 442023720 1549 986185728
> snd_pcm_rate_sync_playback_area: 442023720 442023720 1549 986185728
> snd_pcm_rate_sync_playback_area: 442024660 442023720 1549 986185728
> snd_pcm_rate_commit_area: 6 940 1024 1881
> snd_pcm_rate_sync_playback_area: 940 442023720 1881
> snd_pcm_rate_sync_playback_area: 442024660 442024660 525 986185728
> snd_pcm_rate_sync_playback_area: 442024660 442024660 1549 986185728
> snd_pcm_rate_sync_playback_area: 442024660 442024660 1549 986185728
> snd_pcm_rate_sync_playback_area: 442025595 442024660 1549 986185728
> snd_pcm_rate_sync_playback_area: 442025600 442024660 1549 986185728
> snd_pcm_rate_commit_area: 946 940 1024 1881
> snd_pcm_rate_sync_playback_area: 940 442024660 1881
> snd_pcm_rate_sync_playback_area: 442025600 442025600 525 986185728
> snd_pcm_rate_sync_playback_area: 442025600 442025600 1549 986185728
> snd_pcm_rate_sync_playback_area: 442025600 442025600 1549 986185728
> snd_pcm_rate_sync_playback_area: 442026540 442025600 1549 986185728
> snd_pcm_rate_commit_area: 5 940 1024 1881
> snd_pcm_rate_sync_playback_area: 940 442025600 1881
> snd_pcm_rate_sync_playback_area: 442026540 442026540 525 986185728
> snd_pcm_rate_sync_playback_area: 442026540 442026540 1549 986185728
> snd_pcm_rate_sync_playback_area: 442026540 442026540 1549 986185728
> snd_pcm_rate_sync_playback_area: 442027476 442026540 1549 986185728
> snd_pcm_rate_sync_playback_area: 442027480 442026540 1549 986185728
> 
> playback are debug code
>         slave_size = snd_pcm_avail_update(slave);
>         if (slave_size < 0)
>                 return slave_size;
>          fprintf(stderr,"%s: %u %d %u %u\n", __func__, appl_ptr,
> rate->last_commit_ptr, slave_size, pcm->boundary);
>         if (appl_ptr < rate->last_commit_ptr)
>                 xfer = appl_ptr - rate->last_commit_ptr + pcm->boundary;
>         else
>                 xfer = appl_ptr - rate->last_commit_ptr;
>         while (xfer >= pcm->period_size &&
>                (snd_pcm_uframes_t)slave_size >=
> rate->gen.slave->period_size) {                 err =
> snd_pcm_rate_commit_next_period(pcm, rate->last_commit_ptr %
> pcm->buffer_size);                 fprintf(stderr, "%s: %u %u %u\n",
> __func__, xfer, rate->last_commit_ptr, pcm->buffer_size);
>                 if (err == 0)
> 
> commit area debug
>        fprintf(stderr,"%s: %u %u %u %u\n", __func__, appl_offset,
> size, slave_size, pcm->buffer_size);
>         areas = snd_pcm_mmap_areas(pcm);
>         if (cont >= size) {
> 
> In the not so good case (with different debug - two sites and I hadn't
> access to my debug code from one so I wrote it again)
> you get large numbers of
> snd_pcm_rate_sync_playback_area: 152605942 912 152385750
> snd_pcm_rate_sync_playback_area: 152605942 912 152385750
> snd_pcm_rate_sync_playback_area: 152606412 912 152385750
> snd_pcm_rate_sync_playback_area: 152606412 912 152385750
> snd_pcm_rate_sync_playback_area: 152606705 912 152385750
> snd_pcm_rate_sync_playback_area: 152606882 912 152385750
> snd_pcm_rate_sync_playback_area: 152606882 912 152385750
> snd_pcm_rate_sync_playback_area: 152607352 912 152385750
> snd_pcm_rate_sync_playback_area: 152607352 912 152385750
> ......
> snd_pcm_rate_sync_playback_area: 152769972 912 152385750
> snd_pcm_rate_sync_playback_area: 152770381 1936 152385750
> snd_pcm_rate_commit_area: 1411 572 470
> snd_pcm_rate_sync_playback_area: 384631 1 1936 152385750 739770368
> snd_pcm_rate_sync_playback_area: 152770442 912 152386220
> .... more of these....
> snd_pcm_rate_sync_playback_area: 152910502 912 152386220
> snd_pcm_rate_sync_playback_area: 152910502 912 152386220
> snd_pcm_rate_sync_playback_area: 152910972 912 152386220
> snd_pcm_rate_sync_playback_area: 152910972 912 152386220
> appl ptr is 152910972
> recalc: 3022344724 1411 3072 470 1024
> snd_pcm_rate_sync_playback_area: 152910972 1936 152386220
> snd_pcm_rate_commit_area: 1411 1042 470
> snd_pcm_rate_sync_playback_area: 524752 1 1936 152386220 739770368
> snd_pcm_rate_sync_playback_area: 152910972 1936 152386690
> snd_pcm_rate_commit_area: 1411 101 470
> snd_pcm_rate_sync_playback_area: 524282 1 1936 152386690 739770368
> snd_pcm_rate_sync_playback_area: 152910972 1936 152387160
> ... this pattern repeats one commit per two playbacks until it goes
> back in the top...
> 
> the debug code for these are
> recalc:       fprintf(stderr,"%s: %lu %lu %lu %lu %lu\n", __func__, val,
>                 pcm->buffer_size, slave->buffer_size,
>                 pcm->period_size, slave->period_size);
> commit area
>     areas = snd_pcm_mmap_areas(pcm);
>         fprintf(stderr,"%s: %u %u %u\n", __func__, pcm->buffer_size,
> appl_offset, size);
>         if (cont >= size) {
> 
> playback area:
>         fprintf(stderr,"%s: %u %d %d\n", __func__, appl_ptr,
> slave_size, rate->last_commit_ptr);
>         if (appl_ptr < rate->last_commit_ptr)
>                 xfer = appl_ptr - rate->last_commit_ptr + pcm->boundary;
>         else
>                 xfer = appl_ptr - rate->last_commit_ptr;
>         while (xfer >= pcm->period_size &&
>                (snd_pcm_uframes_t)slave_size >= rate->gen.slave->period_size) {
> 
>                 err = snd_pcm_rate_commit_next_period(pcm,
> rate->last_commit_ptr % pcm->buffer_size);
>                 fprintf(stderr,"%s: %u %d %d %u %u\n", __func__, xfer,
> err, slave_size, rate->last_commit_ptr, pcm->boundary);
> 
> I'm hoping it is just some calculation in the rate plugin overflowing
> and I was blaming SDL but I've fixed up the codepaths to look like
> aplay and it still happened..
> 
> any hints would be appreciated on a) what that rate code is actually
> doing in the fail case, b) what the rate code is doing in the non-fail
> case :-)

Having just a quick look, I don't understand the numbers well yet, but
my first suspect is about the 32bit int overflow (for this kind of
problem).

A virtual machine with snapshot would be really helpful for analyzing
such a problem...


Takashi