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 3000 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'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

  • 0 in reply to Former Member

    I can confirm the issue that Paul reported; getting the exact same error message. Since the last update in this thread was on May 3rd, I wonder if any solution has been found so far to get rid of this error without rebooting?

     

    Thomas

  • 0 in reply to Former Member

    Hi all

    I have just come back to this problem of 'running out of coherent memory for DMA' with the wolfson card (Hoping that someone else would fix the problem!!)

     

    I confirm that it is NOT a problem with size of memory , but indeed a memory leak.

    Specifically, the problem is that in bcm2708-dmaengine.c , the function bcm2708_dma_desc_free (which should free the memory used by the alsa sound driver for aplay/arecord etc) is NEVER called.

     

    I have a simple patch that can be applied to bcm2708-dmaengine.c, for anyone that understands how to rebuild the RPi kernel (find details elsewhere).

    The patch works by checking whether coherent memory has already been allocated, when further coherent memory is requested, and if so forces the old memory to be free'd. It presumes that the I2S driver is the only thing using this cyclic dma, and just 2 blocks (for playback and record) are managed.

    (If bcm2708_dma_desc_free DOES start getting called properly in future, my code will print diags to remind to remove this patch)

     

    I am still using a version of 3.12 kernel (but saw the problem with the standard 3.10 kernel) - I cannot see that anyone has fixed this issue already, but I have not confirmed that the problem has not 'gone away' already with later kernels.

     

    It fixes the problem for me - hope it helps others.

     

    Matt Willis

    Oxford Creative Technology Ltd

    Attachments:
    bcm2708_rpi_wsp_cyclic_dma.patch.zip
  • 0 in reply to matwillis

    Last night, somebody pointed me to this thread and told me that the problem is that bcm2835_dma_terminate_all doesn't free the resources bcm2835_dma_desc_free would free. However, it calls vchan_dma_desc_free_list, which would in turn call bcm2835_dma_desc_free, so that doesn't quite add up. I don't have the hardware to investigate this properly myself, but if somebody can provide some more information to go on, I could certainly fix it. Otherwise, I would have to write a test module to try to trigger the problem.

  • 0 in reply to Former Member

    Adding printk statements to bcm2835_dma_desc_free and bcm2835_dma_terminate_all showed that bcm2835_dma_desc_free is called for scatter/gather DMA allocated by bcm2835_dma_prep_slave_sg but not for cyclic DMA allocated by bcm2835_dma_prep_dma_cyclic. I can see that bcm2835_dma_terminate_all sets c->desc to NULL before it calls vchan_dma_desc_free_list, so I think it's already leaked by that point. The issue seems to be that the control block in c->desc isn't freed before c->desc is set to NULL.

     

    If you do manage to get hold of one, I can reproduce the issue with a Wolfson board using the Volumio distribution (I'm running with a custom kernel built from https://github.com/manish-wolfsonmicro, which is the subject of https://github.com/raspberrypi/linux/pull/705/files), put a bunch of files in the playlist and run "mpc next" in a loop.

Reply Children