Featured Articles
Announcing Pi
Technical Specifications
Raspberry Pi FAQs
Win a Pi
Raspberry Pi Wishlist
Actions
Forum Thread Details
  • State Suggested Answer
  • Replies 21 replies
  • Answers 1 answer
  • Subscribers 664 subscribers
  • Views 2303 views
  • Users 0 members are here
Related

Driver instability issue

Former Member

I've got the Wolfson Audio card running with an application that makes use of the Line-In and Line-Out ports. The Line-In port is _constantly_ read and to the Line-out port audio is written in parallel from time to time. Sampling rate is 48k. The kernel is compiled following the description here in this forum.

 

 

I now had the issue twice that the app hangs after about a day and a half. The second time I was able to collect the following info:

 

End of dmesg:

root@raspberrypi:/home/pi# dmesg | tail
 [135777.724427] arizona spi0.1: FLL1: Timed out waiting for lock
 [136377.676455] arizona spi0.1: FLL1: Timed out waiting for lock
 [136977.638482] arizona spi0.1: FLL1: Timed out waiting for lock
 [137577.600549] arizona spi0.1: FLL1: Timed out waiting for lock
 [138099.977529] arizona spi0.1: FLL1: Timed out waiting for lock
 [138777.524608] arizona spi0.1: FLL1: Timed out waiting for lock
 [139377.496589] arizona spi0.1: FLL1: Timed out waiting for lock
 [139977.448573] arizona spi0.1: FLL1: Timed out waiting for lock
 [139977.522931] ERROR: 4096 KiB atomic DMA coherent pool is too small!
 [139977.522931] Please increase it with coherent_pool= kernel parameter!

 

 

The app hangs. After kill -9 any attempt to restart fails with the following message from the app:

 

*** ERROR: snd_pcm_start failed (unrecoverable error): Cannot allocate memory
 *** ERROR: Start capture failed

 

Here is the end of the corresponding strace of an app start attempt:

 

stat64("/usr/share/alsa/alsa.conf", {st_mode=S_IFREG|0644, st_size=9184, ...}) = 0
 open("/dev/snd/controlC0", O_RDONLY|O_CLOEXEC) = 5
 fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0
 ioctl(5, UI_DEV_CREATE, 0xbef492cc)     = 0
 close(5)                                = 0
 open("/dev/snd/controlC0", O_RDWR|O_CLOEXEC) = 5
 fcntl64(5, F_SETFD, FD_CLOEXEC)         = 0
 ioctl(5, USBDEVFS_CONTROL or USBDEVFS_CONTROL32, 0xbef4946c) = 0
 ioctl(5, 0x40045532, 0xbef494a4)        = 0
 open("/dev/snd/pcmC0D0c", O_RDWR|O_NONBLOCK|O_CLOEXEC) = 6
 fcntl64(6, F_SETFD, FD_CLOEXEC)         = 0
 close(5)                                = 0
 ioctl(6, AGPIOC_ACQUIRE or APM_IOC_STANDBY, 0xbef492e8) = 0
 fcntl64(6, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
 ioctl(6, AGPIOC_INFO, 0xbef492dc)       = 0
 clock_gettime(CLOCK_MONOTONIC, {172144, 75851672}) = 0
 ioctl(6, AGPIOC_SETUP, 0xbef492e4)      = 0
 mmap2(NULL, 4096, PROT_READ, MAP_SHARED, 6, 0x80000) = -1 ENXIO (No such device or address)
 ioctl(6, 0xc0844123, 0xbef49408)        = 0
 fcntl64(6, F_GETFL)                     = 0x802 (flags O_RDWR|O_NONBLOCK)
 fcntl64(6, F_SETFL, O_RDWR)             = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4110, 0x1935718)         = 0
 ioctl(6, 0xc25c4111, 0x1935718)         = 0
 ioctl(6, 0xc0844123, 0x1935bb8)         = 0
 ioctl(6, 0xc0684113, 0xbef496d4)        = 0
 ioctl(6, 0x4140, 0xb69d5000)            = 0
 ioctl(6, 0xc0844123, 0x1935bb8)         = 0
 ioctl(6, 0xc0684113, 0x19353e0)         = 0
 ioctl(6, 0x4140, 0xb69d5000)            = 0
 ioctl(6, 0xc0844123, 0x1935bb8)         = 0
 ioctl(6, 0xc0844123, 0x1935bb8)         = 0
 ioctl(6, 0x4142, 0x1935bb8)             = -1 ENOMEM (Cannot allocate memory)
 write(2, "*** ERROR: snd_pcm_start failed "..., 55*** ERROR: snd_pcm_start failed (unrecoverable error): ) = 55
 write(2, "Cannot allocate memory", 22Cannot allocate memory)  = 22
 write(2, "\n", 1
 )                       = 1
 write(2, "*** ERROR: Start capture failed", 31*** ERROR: Start capture failed) = 31
 write(2, "\n", 1
 )                       = 1
 ioctl(6, 0x4143, 0xb69d5000)            = 0
 ioctl(6, 0x4112, 0xf5519900)            = 0
 close(6)                                = 0
 write(2, "*** ERROR: Could not open audio "..., 53*** ERROR: Could not open audio device for receiver ") = 53
 write(2, "Rx1", 3Rx1)                      = 3
 write(2, "\"\n", 2"
 )                     = 2
 close(4)                                = 0
 brk(0x1955000)                          = 0x1955000
 brk(0x1947000)                          = 0x1947000
 write(2, "*** ERROR: Could not initialize "..., 36*** ERROR: Could not initialize RX ") = 36
 write(2, "Rx1", 3Rx1)                      = 3
 write(2, "\"\n", 2"
 )                     = 2
 write(2, "*** ERROR: Could not initialize "..., 46*** ERROR: Could not initialize Logic object ") = 46
 write(2, "RepeaterLogic", 13RepeaterLogic)           = 13
 write(2, "\". Skipping...\n", 15". Skipping...
 )       = 15
 write(2, "*** ERROR: No logics available. "..., 47*** ERROR: No logics available. Bailing out...
 ) = 47
 exit_group(1)                           = ?

 

BTW, the app is supposed to run _for-ever_ reading and processing audio... running for two years without restart is common for users of this app on x86 hardware.

 

Is there any driver update on the way that could fix this (and allow lower sampling rates on the analogue input)?

Thanks?

  • 0

    Hello,

     

    Same problem here. I get :

    $ dmesg

    [   50.251371] bcm2708-i2s bcm2708-i2s.0: I2S SYNC error!

    ...

    [ 1951.018326] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1951.298349] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1954.918413] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1955.279983] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1955.568428] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1959.318603] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1959.678602] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1959.968874] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1963.388727] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1963.738951] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1964.028746] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1967.608900] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1967.978938] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1968.258892] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1971.679057] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1972.019120] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1972.299357] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1974.244021] ERROR: 4096 KiB atomic DMA coherent pool is too small!

    [ 1974.244021] Please increase it with coherent_pool= kernel parameter!

    [ 1975.789256] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1976.129211] arizona spi0.1: FLL1: Timed out waiting for lock

    [ 1976.409258] arizona spi0.1: FLL1: Timed out waiting for lock

  • 0

    SvxLink?

     

    I also see the

      arizona spi0.1: FLL1: Timed out waiting for lock

    and

      bcm2708-i2s bcm2708-i2s.0: I2S SYNC error!

    messages, but I think they are benign.

    The bcm2708-i2s bcm2708-i2s.0: I2S SYNC error message pops up when i configure the sound card, i.e. when I run the "Reset.." + some other use case script.

     

    My system also constantly reads from Line In and every 10 minutes it plays a sound on Line Out. No, not  SvxLink. Simple mp3 streaming and time announcements with two different applications.

    I get the arizona spi0.1: FLL1: Timed out waiting for lock message every time Line Out is opened for playback.

    But in my case, everything seems to work.

     

    The killer in your case is ERROR: 4096 KiB atomic DMA coherent pool is too small!

    That is when the I2S driver for the Broadcom BCM2708 - sound/soc/bcm/bcm2708-i2s.c - tries to allocate memory from the 4MB pool (the "coherent pool") that is set aside for DMA transfers, and fails.

     

    What you could try is to increase the size of the coherent pool. You do that by adding e.g. coherent_pool=6M to the end of the single line in /boot/cmdline.txt, to increase the size to 6 MB.
    That could make the error go away. Or the error might still show up, but it would probably take longer.

    --

    Ragnar

  • 0 in reply to Former Member

    Hi Ragnar,

     

    the app is indeed svxlink. Sometime today it happened again - and again within less than two days.

     

    [152246.367695] arizona spi0.1: FLL1: Timed out waiting for lock
[152821.921298] arizona spi0.1: FLL1: Timed out waiting for lock
[153421.883321] arizona spi0.1: FLL1: Timed out waiting for lock
[153421.957775] ERROR: 4096 KiB atomic DMA coherent pool is too small!
[153421.957775] Please increase it with coherent_pool= kernel parameter!
root@raspberrypi:/home/pi#

     

    After seeing three times the same behaviour I'd say it's reproducible.

     

    I'll go the other way first. Let's see how long it'll work with coherent_pool=3M image

  • 0

    I did some tests with 0.5-5MB coherent_pool size and while there is some variation in the results, the driver "memory consumption" seems to average about 12 hours per MB.

    Fullscreen contentimage_179532.html Download 
    <html><head><title>Jive SBS</title></head>
<body><font face="arial,helvetica,sans-serif">
<b>Error</b><br><font size="-1">
An general error occurred while processing your request.
</font></font></body></html>

     

    There seems to be a limit from the way the kernel prepares memory early at boot time of 16MB for this type of memory. This limits the maximum working kernel parameter to coherent_pool=15M. Assuming the memory consumption past 5M continues as linear as before I can expect about 7 days before the coherent_pool is empty and a reboot is require. Not great.

  • 0 in reply to Former Member

    Thanks for this precise measurement! This really looks like a memory leak.

    Please try the following to track down the problem:

    1) Run the software e.g. with 1M coherent pool for 4 hours. Then exit the software and start it again.

        This might or might not free the memory so you should have again 6 or 7 hours left until the error occurs.

    2) When this is not the case, please try to unload the module (snd-soc-bcm2708-i2s) and load it again after shutting down the software.

     

    Does this change anything?

     

    Greetings,

    Florian

  • 0 in reply to Former Member

    I did the test with coherent_pool=1M. Rebooted the pi and started the app. After 4 hours quit the app and started it gain. Still, after 6.5 hours uptime the dmesg log shows the well know error message:

     

    [23622.811085] ERROR: 1024 KiB atomic DMA coherent pool is too small!

     

    So exiting the app does not free the consumed memory.

     

    As for the driver module, an unload is not possible.... I use the description here in the forum on how to compile the kernel from source on raspian, and the provided config compiles the driver into the kernel and not as loadable module.

     

    CONFIG_SND_BCM2708_SOC_I2S=y

  • 0 in reply to Former Member

    So exiting the app does not free the consumed memory.

    Good to know. Does the error also occur when you do

    arecord -f DAT | aplay

    ? Or is this even what you do?

     

    the provided config compiles the driver into the kernel and not as loadable module.

    You are right. Although, compiling as module is possible, just a little bit more work since you have to transmit the modules separately (RPi Kernel Compilation - eLinux.org).

  • 0

    Hello.

     

    Im seeing the exact same thing.,
    Im sort of a "noob" on raspberry and linux but i basically am using a deamon script running php and a mysql db to

    exececute mpg123 <filename> and wait for it to play the track to end then enter an infinite loop and get a new track to play.

    So im basically playing one track using mpg123 letting it quit and then starting the process over again.

    i started seeing the "arizona spi0.1: FLL1: Timed out waiting for lock" every time i started a new track, and now after 20hs playing i got the crash..


    Apr 16 11:02:49 raspberrypi kernel: [217375.476467] arizona spi0.1: FLL1: Timed out waiting for lock

    Apr 16 11:02:49 raspberrypi kernel: [217375.479569] ERROR: 4096 KiB atomic DMA coherent pool is too small!

    Apr 16 11:02:49 raspberrypi kernel: [217375.479569] Please increase it with coherent_pool= kernel parameter!


    so i can confirm that closing the program in my case "mpg123" after playing the track , as you said before doesn't solve the issues .. the memory won't free up.


    Any feedback on this is highly appreciated

    //karl

  • 0 in reply to Former Member

    I have tested building snd-soc-bcm2708-i2s as a module. That seems to work OK in itself, but it forces snd-soc-wm5102 to be built as a module too and there I encounter problems.

    Whenever I try to load the wm5102 module I get:

     

    Apr 18 08:48:04 ob kernel: [ 182.199236] snd_soc_wm_adsp: Unknown symbol regulator_enable (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199292] snd_soc_wm_adsp: Unknown symbol regmap_write (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199310] snd_soc_wm_adsp: Unknown symbol regmap_update_bits (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199342] snd_soc_wm_adsp: Unknown symbol regmap_raw_read (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199386] snd_soc_wm_adsp: Unknown symbol snd_soc_put_enum_double (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199403] snd_soc_wm_adsp: Unknown symbol regmap_raw_write_async (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199423] snd_soc_wm_adsp: Unknown symbol devm_regulator_get (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199442] snd_soc_wm_adsp: Unknown symbol snd_soc_get_enum_double (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199476] snd_soc_wm_adsp: Unknown symbol arizona_rate_val (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199500] snd_soc_wm_adsp: Unknown symbol regmap_async_complete (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199530] snd_soc_wm_adsp: Unknown symbol snd_soc_info_enum_ext (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199547] snd_soc_wm_adsp: Unknown symbol snd_soc_info_enum_double (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199564] snd_soc_wm_adsp: Unknown symbol regmap_read (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199581] snd_soc_wm_adsp: Unknown symbol arizona_rate_text (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199603] snd_soc_wm_adsp: Unknown symbol regulator_disable (err 0)

    Apr 18 08:48:04 ob kernel: [ 182.199622] snd_soc_wm_adsp: Unknown symbol regulator_set_voltage (err 0)

    Apr 18 08:48:22 ob kernel: [ 199.916947] snd_soc_wm_adsp: Unknown symbol regulator_enable (err 0)

    Apr 18 08:48:22 ob kernel: [ 199.917007] snd_soc_wm_adsp: Unknown symbol regmap_write (err 0)

     

    the provided config compiles the driver into the kernel and not as loadable module.

    There seems to be a thought behind that...

     

    --

    Ragnar

  • 0

    I'm getting similar behavior with just using arecord. For example with the provided NOOBS distribution, if I record from the built-in mics:

     

    ./Reset_paths.sh; ./Record_from_DMIC.sh;

     

    Then do some recording:

     

    for i in {1..10000}; do arecord -q -d 1 -c 2 -f S16_LE -r 44100 foo.wav || break; echo $i; done

     

    After about 900 or so iterations arecord fails due to what looks like a memory leak filling up some kernel memory and the only way to fix it is to reboot. This is a real show stopper for me.

     

    949

    950

    951

    952

    arecord: pcm_read:1801: read error: Cannot allocate memory

    pi@raspberrypi:~$

     

    Paul