Too many snd_pcm_mmap_readi calls

[Jan Homann <jh@janhomann.de>]

Hi ALSA-Dev-List

I am very new to all this ALSA-Dev-stuff. For a few decades I have been
just an alsa user but now i try to develop a tiny sound recorder like
millions or thousands did before.
On the recorder there is a small while-loop for capturing the pcm data,
encode them and send them to a server every 10ms. On my desktop-pc and
on a Freescale i.mx 233 (ARMv5) the recorder is working quite well.
Now i run into a problem where the recorder is using all the cpu-time on
the arm-device for a few minutes. I tried to debug this behaviour
without any luck. Next i tried to trace the problem and removed as many
calls as possible and put a "gettimeofday" between every remaining call.
Here is the remaining code:
while(1) {

    sleep(1);
    gettimeofday(&time1,NULL);

    snd_pcm_wait( pcm_handle, REC_BUFFER_ELEMENT_SIZE_MS + 10);
    gettimeofday(&time2,NULL);

    snd_pcm_mmap_begin(pcm_handle, &my_areas, &offset, &frames);
    gettimeofday(&time2,NULL);

    snd_pcm_avail_update ( pcm_handle );
    gettimeofday(&time2,NULL);

    snd_pcm_mmap_readi( pcm_handle, network_data.data_UC, ALSA_READ_FRAMES);
    gettimeofday(&time3,NULL);

    snd_pcm_mmap_commit(pcm_handle, offset, frames);
    gettimeofday(&time4,NULL);
}

This is the output from strace:

0.001062 [401b418c] nanosleep({1, 0}, 0xbebd017c) = 0
1.001190 [401a4dac] gettimeofday({1399380864, 459211}, NULL) = 0
0.001032 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.002780 [401a4dac] gettimeofday({1399380864, 463023}, NULL) = 0
0.001063 [401a4dac] gettimeofday({1399380864, 464086}, NULL) = 0
0.001031 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.000968 [401a4dac] gettimeofday({1399380864, 466085}, NULL) = 0
0.001032 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.000968 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.000969 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.001000 [401de46c] ioctl(3, SNDRV_PCM_IOCTL_SYNC_PTR, 0x4e1b0) = 0
0.002249 [401a4dac] gettimeofday({1399380864, 472678}, NULL) = 0
0.001438 [401a4dac] gettimeofday({1399380864, 473740}, NULL) = 0
0.001031 [40149518] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
0.001218 [40149400] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
0.001562 [40149518] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
0.001032 [401b418c] nanosleep({1, 0}, ^CProcess 14219 detached

As you can see, the output starts with the sleep. I just added the sleep
to find my loop-start in the trace-outpus.
Before every gettimeofday there is one call to a snd_pcm-function (ok,
besides the sleep).
There is a block of four ioctl calls between the fourth and the fifth
gettimeofday. This sould be the sound_pcm_mmap_readi.
In the while loop there is only one call to sound_pcm_mmap_read and on
my desktop-pc trace even shows only one call to sound_pcm_mmap_readi.

Maybe anyone can explain to me why the function is called that often on
the arm-device?
Maybe you can give some hints on what to check for the high cpu utilization?

Any hints would be kindly appreciated.

Thanks in advance,
Jan Homann