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 676 subscribers
  • Views 2994 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?

Parents
  • 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).

Reply Children
  • 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