Closed benosteen closed 12 years ago
popcornmix
commented
12 years ago hello_audio doesn't use ALSA (it uses OpenMAX IL). ALSA driver is alpha quality (at best). I've seen it work okay with aplay and mpd - can you confirm if they work for you?
raspberrypi
commented
12 years ago Hi Ben Liz mentioned you may have been experiencing general reliability issues with your Raspberry Pi. Is this the case? Can you send me a bit of info if so?
Cheers Eben
On Mon, Apr 16, 2012 at 6:49 PM, Ben O'Steen reply@reply.github.com wrote:
hello_audio builds and runs fine (alarmingly loud ;)) but modprobing the new alsa driver in and trying to play a song using mplayer causes a kernel oops:
Init:
- debian image from torrent, 13/04/2012 version
- apt-get install alsa-base mplayer
- random mp3's put into /home/pi/mp3
Then, on SSH terminal or normal terminal:
root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# modprobe snd_bcm2835 root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# mplayer /home/pi/mp3/ 8-Bit Ninjas - Occam's Disco Razor.mp3 8-Bit Ninjas - Shiny Spaceship.mp3 Pokemon Face.mp3 sound.log root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# mplayer /home/pi/mp3/Pokemon\ Face.mp3 MPlayer 1.0rc3-4.4.4 (C) 2000-2009 MPlayer Team mplayer: could not connect to socket mplayer: No such file or directory Failed to open LIRC support. You will not be able to use your remote control. Playing /home/pi/mp3/Pokemon Face.mp3. Audio only file format detected. Clip info: Title: Pokemon Face Artist: 8-Bit Ninjas Album: Demo Year: Comment: Genre: Other ========================================================================== Opening audio decoder: [mp3lib] MPEG layer-2, layer-3 AUDIO: 44100 Hz, 2 ch, s16le, 128.0 kbit/9.07% (ratio: 16000->176400) Selected audio codec: [mp3] afm: mp3lib (mp3lib MPEG layer-2, layer-3) ========================================================================== socket(): Address family not supported by protocol AO: [pulse] Init failed: Connection refused Failed to initialize audio driver 'pulse' [AO_ALSA] alsa-lib: pcm_hw.c:1293:(snd_pcm_hw_open) open '/dev/snd/pcmC0D0p' failed (-1): Operation not permitted [AO_ALSA] Playback open error: Operation not permitted Failed to initialize audio driver 'alsa' [AO SDL] Samplerate: 44100Hz Channels: Stereo Format s16le [AO SDL] using aalib audio driver. [AO SDL] Unable to open audio: No available audio device Failed to initialize audio driver 'sdl:aalib' Could not open/initialize audio device -> no sound. Audio: no sound Video: no video Exiting... (End of file) root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# ls audio.c audioplay.h hello_audio.bin Makefile sinewave.c root@raspberrypi:/opt/vc/src/hello_pi/hello_audio# cd /home/pi/ root@raspberrypi:/home/pi# ls libfreenect mp3 root@raspberrypi:/home/pi# cd mp3/ root@raspberrypi:/home/pi/mp3# ls Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:Internal error: Oops: 17 [#1] Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:Process ls (pid: 1050, stack limit = 0xcadd6268) Segmentation fault root@raspberrypi:/home/pi/mp3# Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:Stack: (0xcadd7da0 to 0xcadd8000) Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7da0: caea9f68 caea9f6c cba67520 00000000 cb81efa0 768c4c4f cadd7dec cadd7dc8 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7dc0: c00de17c c0197520 ca9c7074 ca9c7074 cadd7e68 cb5fce48 cb6020e0 ca9c7ff8 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7de0: cadd7e3c cadd7df0 c00ea4bc c00de0b4 ca9c7074 cb5fce48 00000074 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7e00: caeaaf60 00000004 00000000 00000000 402d7000 cb81efa0 cb6020e0 cb6020e0 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7e20: caeaaf60 00000000 00000000 00000000 cadd7eac cadd7e40 c00ebecc c00ea3a4 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7e40: 00000000 00000000 00000090 cb81efc0 00000000 cadd7e8c cadd6000 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7e60: cadd7ec4 00000009 9dddb064 768c4c4f 00000001 cb9f5080 caeac000 cadf0de0 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7e80: caead008 cb81efa0 caeaaf60 cb6020e0 00000000 00000005 00000000 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7ea0: cadd7f44 cadd7eb0 c00dda64 c00ebe68 cadd7ecc cadd7ec0 c003cac0 c0197e34 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7ec0: cadd7f04 cadd7ed0 c00145e4 c003cabc cb80d260 00000000 00000000 00000007 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7ee0: c039d644 c008e494 cadd7f78 be9f7bf0 cb9f5200 00000000 cadd7fac cadd7f08 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7f00: c00083c4 c0014450 400e6524 cba9ee40 caeaaf68 00000001 cb6020e0 caeaaf60 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7f20: c008e494 cb602144 00000000 cb6020e0 cadd6000 00000000 cadd7f74 cadd7f48 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7f40: c008e88c c00dd90c cadd7f94 cadd7f78 c007e590 00000000 0133ee38 00008000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7f60: caeaaf60 c000e3c8 cadd7fa4 cadd7f78 c008ea3c c008e800 0133ee38 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7f80: 00008000 00000000 0133ee38 00000000 400e6524 000000d9 00000000 cadd7fa8 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7fa0: c000e220 c008e9d4 0133ee38 00000000 00000003 0133ee38 00008000 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7fc0: 0133ee38 00000000 400e6524 000000d9 0133ee24 0133ee20 00000000 000271f8 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:7fe0: 402d7700 be9f7838 402d77a4 402d76c8 60000010 00000003 00000000 00000000 Message from syslogd@raspberrypi at Apr 16 17:35:41 ... kernel:Code: e5953000 e3130001 1a000013 e3c34003 (e5946008)On primary tty on the RPi, the main kernel oops is shown:
From /var/log/syslog:
Apr 16 17:34:46 raspberrypi kernel: ### snd_bcm2835_alsa_probe c039e448 ############### PROBING FOR bcm2835 ALSA device (0):(1) ############### Apr 16 17:34:46 raspberrypi kernel: Creating card... Apr 16 17:34:46 raspberrypi kernel: Creating device/chip .. Apr 16 17:34:46 raspberrypi kernel: Adding controls .. Apr 16 17:34:46 raspberrypi kernel: Registering card .... Apr 16 17:34:46 raspberrypi kernel: bcm2835 ALSA CARD CREATED! Apr 16 17:34:46 raspberrypi kernel: ### BCM2835 ALSA driver init OK ### Apr 16 17:35:02 raspberrypi kernel: snd_bcm2835_playback_open:97 Alsa open (0) Apr 16 17:35:02 raspberrypi kernel: vcos: [1041]: vc_vchi_audio_init:258 vc_vchi_audio_init: failed to open VCHI service connection (status=-1) Apr 16 17:35:02 raspberrypi kernel: vcos: [1041]: bcm2835_audio_open_connection:374 bcm2835_audio_open_connection: failed to initialize audio service Apr 16 17:35:41 raspberrypi kernel: Unable to handle kernel NULL pointer dereference at virtual address 00000008 Apr 16 17:35:41 raspberrypi kernel: pgd = caeac000 Apr 16 17:35:41 raspberrypi kernel: [00000008] *pgd=0adef831, *pte=00000000, *ppte=00000000 Apr 16 17:35:41 raspberrypi kernel: Internal error: Oops: 17 [#1] Apr 16 17:35:41 raspberrypi kernel: Modules linked in: snd_bcm2835 snd_pcm snd_seq snd_timer snd_seq_device snd snd_page_alloc fuse joydev evdev sd_mod Apr 16 17:35:41 raspberrypi kernel: CPU: 0 Not tainted (3.1.9+ #84) Apr 16 17:35:41 raspberrypi kernel: pc : [<c0197544>] lr : [<c00de17c>] psr: 60000013 Apr 16 17:35:41 raspberrypi kernel: sp : cadd7da0 ip : cadd7dc8 fp : cadd7dc4 Apr 16 17:35:41 raspberrypi kernel: r10: 00000000 r9 : 00000000 r8 : cb81efa0 Apr 16 17:35:41 raspberrypi kernel: r7 : cba67528 r6 : 00000000 r5 : caea9f68 r4 : 00000000 Apr 16 17:35:41 raspberrypi kernel: r3 : 00000000 r2 : cba67528 r1 : cb81efa0 r0 : cba67528 Apr 16 17:35:41 raspberrypi kernel: Flags: nZCv IRQs on FIQs on Mode SVC_32 ISA ARM Segment user Apr 16 17:35:41 raspberrypi kernel: Control: 00c5387d Table: 0aeac008 DAC: 00000015 Apr 16 17:35:41 raspberrypi kernel: Process ls (pid: 1050, stack limit = 0xcadd6268) Apr 16 17:35:41 raspberrypi kernel: Stack: (0xcadd7da0 to 0xcadd8000) Apr 16 17:35:41 raspberrypi kernel: 7da0: caea9f68 caea9f6c cba67520 00000000 cb81efa0 768c4c4f cadd7dec cadd7dc8 Apr 16 17:35:41 raspberrypi kernel: 7dc0: c00de17c c0197520 ca9c7074 ca9c7074 cadd7e68 cb5fce48 cb6020e0 ca9c7ff8 Apr 16 17:35:41 raspberrypi kernel: 7de0: cadd7e3c cadd7df0 c00ea4bc c00de0b4 ca9c7074 cb5fce48 00000074 00000000 Apr 16 17:35:41 raspberrypi kernel: 7e00: caeaaf60 00000004 00000000 00000000 402d7000 cb81efa0 cb6020e0 cb6020e0 Apr 16 17:35:41 raspberrypi kernel: 7e20: caeaaf60 00000000 00000000 00000000 cadd7eac cadd7e40 c00ebecc c00ea3a4 Apr 16 17:35:41 raspberrypi kernel: 7e40: 00000000 00000000 00000090 cb81efc0 00000000 cadd7e8c cadd6000 00000000 Apr 16 17:35:41 raspberrypi kernel: 7e60: cadd7ec4 00000009 9dddb064 768c4c4f 00000001 cb9f5080 caeac000 cadf0de0 Apr 16 17:35:41 raspberrypi kernel: 7e80: caead008 cb81efa0 caeaaf60 cb6020e0 00000000 00000005 00000000 00000000 Apr 16 17:35:41 raspberrypi kernel: 7ea0: cadd7f44 cadd7eb0 c00dda64 c00ebe68 cadd7ecc cadd7ec0 c003cac0 c0197e34 Apr 16 17:35:41 raspberrypi kernel: 7ec0: cadd7f04 cadd7ed0 c00145e4 c003cabc cb80d260 00000000 00000000 00000007 Apr 16 17:35:41 raspberrypi kernel: 7ee0: c039d644 c008e494 cadd7f78 be9f7bf0 cb9f5200 00000000 cadd7fac cadd7f08 Apr 16 17:35:41 raspberrypi kernel: 7f00: c00083c4 c0014450 400e6524 cba9ee40 caeaaf68 00000001 cb6020e0 caeaaf60 Apr 16 17:35:41 raspberrypi kernel: 7f20: c008e494 cb602144 00000000 cb6020e0 cadd6000 00000000 cadd7f74 cadd7f48 Apr 16 17:35:41 raspberrypi kernel: 7f40: c008e88c c00dd90c cadd7f94 cadd7f78 c007e590 00000000 0133ee38 00008000 Apr 16 17:35:41 raspberrypi kernel: 7f60: caeaaf60 c000e3c8 cadd7fa4 cadd7f78 c008ea3c c008e800 0133ee38 00000000 Apr 16 17:35:41 raspberrypi kernel: 7f80: 00008000 00000000 0133ee38 00000000 400e6524 000000d9 00000000 cadd7fa8 Apr 16 17:35:41 raspberrypi kernel: 7fa0: c000e220 c008e9d4 0133ee38 00000000 00000003 0133ee38 00008000 00000000 Apr 16 17:35:41 raspberrypi kernel: 7fc0: 0133ee38 00000000 400e6524 000000d9 0133ee24 0133ee20 00000000 000271f8 Apr 16 17:35:41 raspberrypi kernel: 7fe0: 402d7700 be9f7838 402d77a4 402d76c8 60000010 00000003 00000000 00000000 Apr 16 17:35:41 raspberrypi kernel: Backtrace: Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c0197514>] from [<c00de17c>] Apr 16 17:35:41 raspberrypi kernel: r8:768c4c4f r7:cb81efa0 r6:00000000 r5:cba67520 r4:caea9f6c Apr 16 17:35:41 raspberrypi kernel: r3:caea9f68 Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c00de0a8>] from [<c00ea4bc>] Apr 16 17:35:41 raspberrypi kernel: r8:ca9c7ff8 r7:cb6020e0 r6:cb5fce48 r5:cadd7e68 r4:ca9c7074 Apr 16 17:35:41 raspberrypi kernel: r3:ca9c7074 Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c00ea398>] from [<c00ebecc>] Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c00ebe5c>] from [<c00dda64>] Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c00dd900>] from [<c008e88c>] Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c008e7f4>] from [<c008ea3c>] Apr 16 17:35:41 raspberrypi kernel: r8:c000e3c8 r7:caeaaf60 r6:00008000 r5:0133ee38 r4:00000000 Apr 16 17:35:41 raspberrypi kernel: Function entered at [<c008e9c8>] from [<c000e220>] Apr 16 17:35:41 raspberrypi kernel: r7:000000d9 r6:400e6524 r5:00000000 r4:0133ee38 Apr 16 17:35:41 raspberrypi kernel: Code: e5953000 e3130001 1a000013 e3c34003 (e5946008) Apr 16 17:35:41 raspberrypi kernel: ---[ end trace a9b5ab6077246e40 ]---
Reply to this email directly or view it on GitHub: https://github.com/raspberrypi/firmware/issues/2
benosteen
commented
12 years ago @popcornmix aplay fails with a kernel oops as well -> https://gist.github.com/2400868 - I'll try from a freshly applied image
@raspberrypi So as not to confuse this issue, I'll msg you the details.
popcornmix
commented
12 years ago Can you try the start.elf from here: https://github.com/raspberrypi/firmware/blob/master/boot/start.elf
benosteen
commented
12 years ago Oops is repeatable with mp3's, but ogg files just fail to play.
Fresh image (13/04/2012 debian6) modprobe snd_bcm2835 apt-get install alsa-base
root@raspberrypi:/mnt/foo# aplay themetal.ogg aplay: main:654: audio open error: Operation not permitted
root@raspberrypi:/mnt/foo# aplay 11_Everlong_Foo\ Fighters_The\ Colour\ And\ The\ Shape.mp3
Message from syslogd@raspberrypi at Apr 13 09:02:12 ... kernel:Internal error: Oops: 805 [#1]
etc...
Then, attempting to play anything will hang the process (as you might expect)
benosteen
commented
12 years ago Booted fine with new start.elf file
modprobe worked
aplay an ogg generated a lot of noise (aplay interpreted it as a raw file) - this was through the HDMI audio as I was using HDMI at the time.
apt-get'd mplayer and mpd
mplayer same ogg - found audio out, looked promising, but stalled when it came to play the file. Wouldn't let me Ctrl-C or Z out of it.
Raw console log of the above here: https://gist.github.com/2402267
benosteen
commented
12 years ago aplay works fine playing raw files (interpreting them as .wav files) - when given a .wav, it plays back without distortion :)
Yay, progress!
I've tried .wav playback with aplay with the new start.elf with both HDMI a/v and composite video + 3.5mm audio jack out - both work.
Are there any diagnostics that I could run to help work out why compressed streams seem to hang?
popcornmix
commented
12 years ago I see the same hang with mplayer. We were not supporting silence correctly, so I've fixed that. However when running mplayer I'm getting asked to output silence a couple of times a second, which makes the audio slow and stuttery. As a hack, I pass through the silence request, but don't output it. This sounds much better, but I still sometimes find it stalls. Need to understand why silence is being requested. I assume it is unhappy with the read pointer updates coming back.
Anyway, update start.elf and snd-bcm2835.ko (you'll possibly need the other changed files updated) from https://github.com/raspberrypi/firmware and it should be a little better.
benosteen
commented
12 years ago Passing silent output every so often is a symptom that the decoding thread can't keep up. For example, mplayer does this for buffer underruns: http://mailman.alsa-project.org/pipermail/alsa-devel/2011-February/037231.html
Is snd_pcm_forward being called or is it actually passing silent data? Mplayer and other apps use get_delay heavily to work out the latency of playback - is this giving them numbers they expect (which might be different from accurate ones ;))
benosteen
commented
12 years ago Swapped over the new start.elf and snd_bcm2835 module - everything works as before and decoded music plays via mplayer for a while before it had an issue. Excellent :) I need to pick a higher quality audio file, but it sounded decent before it stopped.
root@raspberrypi:/home/pi# mplayer /home/pi/Music/1.I.Allegro.ogg
Creating config file: /root/.mplayer/config
MPlayer 1.0rc3-4.4.4 (C) 2000-2009 MPlayer Team
mplayer: could not connect to socket
mplayer: No such file or directory
Failed to open LIRC support. You will not be able to use your remote control.
Playing /home/pi/Music/1.I.Allegro.ogg.
[Ogg] stream 0: audio (Vorbis), -aid 0
Ogg : Page out not synced, we skip some bytes
Ogg file format detected.
Clip info:
Name: 1. I. Allegro
Comments: http://www.archive.org/details/BeethovenPianoConcertoNo.5emperormoiseivitch
==========================================================================
Opening audio decoder: [ffmpeg] FFmpeg/libavcodec audio decoders
Ogg : Page out not synced, we skip some bytes
Ogg : Page out not synced, we skip some bytes
AUDIO: 22050 Hz, 2 ch, s16le, 56.0 kbit/7.94% (ratio: 7000->88200)
Selected audio codec: [ffvorbis] afm: ffmpeg (FFmpeg Vorbis)
==========================================================================
socket(): Address family not supported by protocol
AO: [pulse] Init failed: Connection refused
Failed to initialize audio driver 'pulse'
AO: [alsa] 22050Hz 2ch s16le (2 bytes per sample)
Video: no video
Starting playback...
A: 23.5 (23.5) of 1209.1 (20:09.0) 2.7%
MPlayer interrupted by signal 2 in module: play_audio
[AO_ALSA] Write error: Operation not permitted
[AO_ALSA] Trying to reset soundcard.
[AO_ALSA] alsa-lib: pcm_hw.c:558:(snd_pcm_hw_prepare) SNDRV_PCM_IOCTL_PREPARE failed (-16): Device or resource busy
[AO_ALSA] pcm prepare error: Device or resource busy
A: 23.9 (23.8) of 1209.1 (20:09.0) 2.7%
Exiting... (Quit)
I don't believe mplayer is not keeping up. When I discard the silence requests, it sounds correct and arm is only 20% busy. It may think it is running behind due to it thinking we are underflowing/overflowing.
Basically we have a message passing interface to GPU (vchiq) where blocks of audio are sent (copied to GPU memory space). The GPU adds these to an audio output fifo (with resampling/mixing/volume scaling). However ARM wants to know progress. On GPU we can measure the latency between a sample being submitted and it being heard, so we periodically (100 Hz) read that, and work out how much audio has been consumed, and that (as the number of bytes) comes back in VC_AUDIO_MSG_TYPE_COMPLETE message.
I then call what I'm guessing are the right functions to update the ALSA concept of the read pointer, but I'm guessing this isn't quite right. If anyone knows about ALSA feel free to inspect the code.
benosteen
commented
12 years ago Thanks - I'll have a poke around the code and try to encourage others to do the same. I don't think it is a question of sending accurate timing info back to clients, just values that they would believe to be the correct ones :)
Module Code: https://github.com/raspberrypi/linux/tree/rpi-patches/sound/arm
benosteen
commented
12 years ago Further info:
Running mplayer through strace shows that when it does hang, it hangs halfway through displaying an ioctl call:
...
gettimeofday({1334703840, 146324}, NULL) = 0
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
nanosleep({0, 46000000}, NULL) = 0
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
gettimeofday({1334703840, 196926}, NULL) = 0
gettimeofday({1334703840, 199833}, NULL) = 0
ioctl(5, 0x400c4150, 0xbe835b24) = 0
ioctl(5, 0xc0844123, 0x11729a8) = 0
ioctl(5, 0x80044121, 0xbe835b54) = 0
ioctl(0, TIOCGWINSZ, {ws_row=29, ws_col=238, ws_xpixel=0, ws_ypixel=0}) = 0
) = 461, "A: 55.6 (55.5) of 1209.1 (20:09"..., 46A: 55.6 (55.5) of 1209.1 (20:09.0) 4.6%
gettimeofday({1334703840, 204753}, NULL) = 0
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
nanosleep({0, 46000000}, NULL) = 0
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
gettimeofday({1334703840, 254069}, NULL) = 0
gettimeofday({1334703840, 256228}, NULL) = 0
ioctl(5, 0x400c4150, 0xbe835b24) = 0
ioctl(5, 0xc0844123, 0x11729a8) = 0
ioctl(5, 0x80044121, 0xbe835b54) = 0
ioctl(0, TIOCGWINSZ, {ws_row=29, ws_col=238, ws_xpixel=0, ws_ypixel=0}) = 0
) = 461, "A: 55.6 (55.6) of 1209.1 (20:09"..., 46A: 55.6 (55.6) of 1209.1 (20:09.0) 4.6%
gettimeofday({1334703840, 262611}, NULL) = 0
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
nanosleep({0, 36000000}, NULL) = 0
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
nanosleep({0, 10000000}, NULL) = 0
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
gettimeofday({1334703840, 312049}, NULL) = 0
gettimeofday({1334703840, 313683}, NULL) = 0
ioctl(5, 0x400c4150, 0xbe835b24) = 0
ioctl(5, 0xc0844123, 0x11729a8) = 0
ioctl(5, 0x80044121, 0xbe835b54) = 0
ioctl(0, TIOCGWINSZ, {ws_row=29, ws_col=238, ws_xpixel=0, ws_ypixel=0}) = 0
) = 461, "A: 55.7 (55.6) of 1209.1 (20:09"..., 46A: 55.7 (55.6) of 1209.1 (20:09.0) 4.6%
gettimeofday({1334703840, 318841}, NULL) = 0
select(1, [0], NULL, NULL, {0, 0}) = 0 (Timeout)
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
nanosleep({0, 46000000}, NULL) = 0
ioctl(5, 0x806c4120, 0xbe835ae8) = 0
gettimeofday({1334703840, 368473}, NULL) = 0
gettimeofday({1334703840, 370169}, NULL) = 0
ioctl(5, 0x400c4150 <unfinished ...>It hangs just before "<unfinished...>", only outputing that to the terminal after Ctrl-C is pressed. If Ctrl-C is not pressed it seems like it would hang there, no sound, no movement, for as long as it is left.
Running mplayer through gdb, it replicates the same hang, but curiously if the program execution is stopped (either Ctrl-C or -Z in gdb) and then restarted (continue or fg respectively), the sound will often resume playing for a short, indeterminate time afterwards.
Just to confirm what you said earlier about the read pointer callbacks, running a simpler, dumber program such as ogg123 to output the sound through the ALSA driver seems to be able to play without hanging. Likewise with a simple hello_alsa style program - I can push a dodgy sine wave through the interface for as long as I please :)
Also: http://www.alsa-project.org/~tiwai/writing-an-alsa-driver/ch05.html
This looks to be a helpful (if old) guide to writing an ALSA driver.
Thanks for the work you are doing on this, I know what a complete nightmare it is to work with the linux sound... ecosystem. I asked a friend about writing alsa drivers: "oh hell no! Run, save yourself. I've done that once and never again."
arthurbennis
commented
12 years ago I compiled pyo (Python digital signal processing module) for the Rpi with portaudio as its backend. Sound is generated nicely, but after 10 seconds or so the sound drops away and this error is shown in dmesg:
vcos: [1213]: bcm2835_audio_write:778 bcm2835_audio_write: failed on vchi_bulk_queue_transmit (status=-1)I'm certainly not an expert but I though this one was in line with the above...
benosteen
commented
12 years ago I get the same vcos based error myself when the audio goes - however wrapping the transmit code with some in and out debug printk's shows that the blocking call completes.
(wrapping line 767 in sound/arm/bcm2835-vchiq.c in function bcm2835_audio_write)
Eg paraphrasing the kern log:
vchi_bulk_queue_transmit IN vchi_bulk_queue_transmit OUT vchi_bulk_queue_transmit IN vchi_bulk_queue_transmit OUT vchi_bulk_queue_transmit IN vchi_bulk_queue_transmit OUT (hang/fail -> kill/stall process) vcos: [1213]: bcm2835_audio_write:778 bcm2835_audio_write: faile.....
popcornmix
commented
12 years ago I believe the "bcm2835_audio_write: failed on vchi_bulk_queue_transmit" only occurs after kill/control-c which is expected - we close the vchiq connection when the launching (userland) app is killed, and all the blocking calls will return with error.
popcornmix
commented
12 years ago Here is a log from running ogg123 which hangs for me.
The key thing is I get one write with 30240 bytes. Then I get a start trigger which I have to process from a worker thread, as triggers can come from interrupt context. Before the start messages has been sent from worker thread, I get a silence call.
Basically it's already failed at this point, after 1ms. If I play the silence, then it will sound glitchy. Why did ogg123 choose to play silence?
[ 103.414369] snd_bcm2835_pcm_prepare:245 .. IN [ 103.414406] snd_bcm2835_pcm_prepare:253 buffer_size=31744, period_size=1024 pos=0 frame_bits=32 [ 103.414425] snd_bcm2835_pcm_prepare:255 .. OUT [ 103.414447] snd_bcm2835_pcm_lib_ioctl:376 .. substream=c79ada80, cmd=0, arg= (null) (0) ret=0 [ 103.415835] snd_bcm2835_pcm_copy:333 .. IN [ 103.415864] snd_bcm2835_pcm_copy:340 copy.......... (30240) hwptr=0 appl=0 pos=0 [ 103.415898] vcos: [1174]: bcm2835_audio_write:739 .. IN [ 103.415917] vcos: [1174]: bcm2835_audio_write:741 Writing 30240 bytes from 40ecb0cc [ 103.415960] vcos: [1174]: bcm2835_audio_write:764 ... sent header [ 103.416372] vcos: [1174]: bcm2835_audio_write:789 .. OUT [ 103.416422] snd_bcm2835_pcm_copy:344 .. OUT [ 103.416445] snd_bcm2835_pcm_trigger:266 .. IN [ 103.416461] snd_bcm2835_pcm_trigger:271 bcm2835_AUDIO_TRIGGER_START running=0 [ 103.416480] vcos: [1174]: bcm2835_audio_start:103 .. IN [ 103.416519] vcos: [1174]: bcm2835_audio_start:117 .. OUT 0 [ 103.416540] snd_bcm2835_pcm_trigger:303 .. OUT [ 103.416564] snd_bcm2835_pcm_silence:356 .. IN [ 103.416582] snd_bcm2835_pcm_silence:363 silence....... (1504) hwptr=0 appl=30240 pos=0 [ 103.416600] vcos: [1174]: bcm2835_audio_write:739 .. IN [ 103.416619] vcos: [1174]: bcm2835_audio_write:741 Writing 1504 bytes from (null) [ 103.416657] vcos: [1174]: bcm2835_audio_write:764 ... sent header [ 103.416677] vcos: [1174]: bcm2835_audio_write:789 .. OUT [ 103.416694] snd_bcm2835_pcm_silence:367 .. OUT [ 103.416773] vcos: [307]: my_wq_function:84 .. IN c6c43f20:1 [ 103.416801] vcos: [307]: bcm2835_audio_start_worker:607 .. IN [ 103.416830] vcos: [307]: bcm2835_audio_start_worker:632 .. OUT [ 103.416850] vcos: [307]: my_wq_function:97 .. OUT 0 [ 103.416980] snd_bcm2835_pcm_pointer:314 .. IN [ 103.417003] snd_bcm2835_pcm_pointer:319 pcm_pointer... (0) hwptr=0 appl=30240 pos=0 [ 103.417020] snd_bcm2835_pcm_pointer:321 .. OUT [ 103.417065] snd_bcm2835_pcm_copy:333 .. IN [ 103.417084] snd_bcm2835_pcm_copy:340 copy.......... (1504) hwptr=0 appl=30240 pos=0 [ 103.417102] vcos: [1174]: bcm2835_audio_write:739 .. IN [ 103.417120] vcos: [1174]: bcm2835_audio_write:741 Writing 1504 bytes from 40ed26ec [ 103.417163] vcos: [1174]: bcm2835_audio_write:764 ... sent header [ 103.421907] vcos: [391]: audio_vchi_callback:166 .. IN instance=c6c430f0, param=c6c430f0, reason=1, handle= (null) [ 103.421968] vcos: [391]: audio_vchi_callback:186 .. instance=c6c430f0, m.type=VC_AUDIO_MSG_TYPE_COMPLETE, complete=1504 [ 103.421997] bcm2835_playback_fifo_irq:50 .. IN [ 103.422024] bcm2835_playback_fifo_irq:53 alsa_stream=c6c43f20 substream=c79ada80 [ 103.422048] bcm2835_playback_fifo_irq:70 updating pos cur: 0 + 1504 max:31744 new_period:1 [ 103.422070] snd_bcm2835_pcm_pointer:314 .. IN [ 103.422087] snd_bcm2835_pcm_pointer:319 pcm_pointer... (0) hwptr=0 appl=30240 pos=1504 [ 103.422103] snd_bcm2835_pcm_pointer:321 .. OUT [ 103.422120] snd_bcm2835_pcm_silence:356 .. IN [ 103.422138] snd_bcm2835_pcm_silence:363 silence....... (1504) hwptr=0 appl=30240 pos=1504 [ 103.422157] vcos: [391]: bcm2835_audio_write:739 .. IN [ 103.422174] vcos: [391]: bcm2835_audio_write:741 Writing 1504 bytes from (null)
benosteen
commented
12 years ago I don't think the silence comes from ogg123 directly - I am still trying to understand the chain of functions between what the client does and what is received by the driver.
I'm using mplayer, as that has a reasonably well-isolated alsa plugin. Their subversion isn't HTTP browsable, so I've put up the key file to a gist: https://gist.github.com/2465839 it's libao2/ao_alsa.c within their sources.
The one thing it does very regularly is call 'get_delay' which in turn calls 'snd_pcm_delay(alsa_handler, &delay) < 0)'
Only if delay is below 0, '/* underrun - move the application pointer forward to catch up */' it calls 'snd_pcm_forward(alsa_handler, -delay);' - now, does this cause the silence to be added? Need to get a version of mplayer built from source to start debugging.
There is also this:
#if SND_LIB_VERSION >= 0x000901
/* play silence when there is an underrun */
if ((err = snd_pcm_sw_params_set_silence_size(alsa_handler, alsa_swparams, boundary)) < 0) {
mp_msg(MSGT_AO,MSGL_ERR,MSGTR_AO_ALSA_UnableToSetSilenceSize,
snd_strerror(err));
return 0;
}
#endifSo, this again points to the silence calls coming from ALSA itself, when the player signals that an xrun has occurred.
benosteen
commented
12 years ago I've had another look at this today (there's only so much ALSA anyone can stomach) and have got somewhere:
Changing the bulk transfer flag back to BLOCKED_UNTIL_QUEUED https://github.com/benosteen/linux/commit/00c6ae44673f4dd39f0db61b1459abfda95d0374
Then, altering the pointer callback to recalc the 'pos' anew: https://github.com/benosteen/linux/commit/dc9999ada3834c87a399055e37bf1099c65040bd
This seems to get a nice smooth playback with many of the things I have tried (ogg123, mpg123, timidity, scummvm and so on) but still has a crackling issue with mplayer.
Key thing is that it hasn't yet hung on me yet!
This also seems to address issue#6 but I haven't tested that extensively at all.
popcornmix
commented
12 years ago Thanks for looking. Is alsa_stream->retrieved ever non-zero in snd_bcm2835_pcm_pointer ? Looking at the code, it is only non-zero during audio_vchi_callback (which I believe is called from interrupt context). But I may well be wrong.
Just for your information VCHI_FLAGS_BLOCK_UNTIL_QUEUED for a bulk message means the data must remain valid until it gets sent. VCHI_FLAGS_BLOCK_UNTIL_DATA_READ means the data has been sent (so can be overwritten).
So possibly the unhappiness in ogg123 etc was because the bulk message was blocking the user task for too long. But now mplayer is crackling, possibly because the buffer is being reused before it has been sent. I would have thought it wouldn't get overwritten until we've indicated it's been played through the pointer callback.
benosteen
commented
12 years ago I don't think so - I had added in a fake lag into the pointer callback as an experiment earlier and that seemed to improve things, which led me to doing this. At what rate is the audio_vchi_callback meant to occur? turning on a few of those audio_debugs showed that the pos update seemed to happen at a slow rate - eg it would hop 3-4k after a period of time.
The hangs certainly only occur when the blocking til read flag is on, as so far it's been stable playing music, and running games via SDL (compiled the Fuse spectrum emulator for it).
popcornmix
commented
12 years ago audio_vchi_callback is called every 10ms
raspberrypi
commented
12 years ago I wonder if we need to either have a pool of buffers and take a private copy of the data, or use the control channel (might even be more efficient than bulk if the buffers are small enough).
Eben
On Sun, Apr 29, 2012 at 12:55 PM, popcornmix reply@reply.github.com wrote:
audio_vchi_callback is called every 10ms
Reply to this email directly or view it on GitHub: https://github.com/raspberrypi/firmware/issues/2#issuecomment-5408075
benosteen
commented
12 years ago So far, all I've been trying to do is take the code (which should work) and ahem kludge it so that ALSA gets the numbers it seems to want.
I've found this diagram helpful when talking about ALSA: http://0pointer.de/public/fragments.png
Most of the following is for my benefit and for anyone following along, just talking through how I think things hang together. Please correct me!
We've got three sequencial buffers between the alsa client and the playback: 1) the normal alsa ringbuffer as diagrammed above 2) the hidden vchiq queue 'buffer' 3) the audio fifo playback queue on the core
alsa maintains 1), and it is passed the location of the hardware read pointer (hw_ptr) in the pointer callback.
2) can be truly hidden if the transmit code blocks until the buffer is safely passed on to the core (VCHI_FLAGS_BLOCK_UNTIL_DATA_READ) but this leads to hangs, likely due to apps using/abusing some quirks of alsa that aren't clear to me atm. The 'silence' calls in particular.
Anecdotally of course, I've had hang-free playback by switching to the VCHI_FLAGS_BLOCK_UNTIL_QUEUED but this reuses the ringbuffer and I've not had much luck fudging a fake hw_ptr to avoid overwriting by certain apps (same ones that seem to exacerbate the hang issue previously too but more testing required.)
For 3) We could measure bytes in, and every 10ms there is a callback to bcm2835-vchiq.c:audio_vchi_callback with the number of bytes consumed by playback.
The overwriting of the queued buffer suggests that certain apps are filling up the buffer too fast - are those spurious silence calls adding bytes to the playback tally on the audio_vchi_callback?
benosteen
commented
12 years ago Added a few atomic counters to the alsa_stream to tally up no of sent, retrieved and silence requested bytes to try to confirm the silence problem. (Sent and silence bytes were tallied up in bcm2835-vchiq.c:bcm2835_audio_write and the total retrieved added to audio_vchi_callback) Sent bytes is a count of the bytes of audio sent that are not 'silence'.
Difference is clear: Apps that sound fine = No silence calls. Apps that jitter = silence calls.
https://gist.github.com/2563242 (First half is mplayer, second half is mpg123. Playing the same mp3 for ~10secs each. Note how the silence bytes (3rd col) matches the total bytes retrieved (2nd col) but lagging behind it by one or two updates. )
after ~10 seconds, mplayer has sent 1744896 bytes, vchiq callback has noted 1718480 retrieved, and there has been 1716704 bytes of silence called!
mpg123 has similar sent/received for the same timespan, but no silence.
This is with the code (I assume) sending a header to the vchiq instance saying to play 'count' bytes of silence (m.u.silence) but with the actual bulk_transmit part skipped.
Changing the silence callback to do nothing (bcm2835-pcm.c:snd_bcm2835_pcm_silence) had no effect on the sound quality.
Both mplayer and mpg123 write interleaved (writei) but have differing tactics to an xrun - mplayer calls snd_pcm_forward and mpg123 just has another go ("written = snd_pcm_writei(pcm, buf, frames);")
By altering the callbacks for silence and copy, I have got a working mplayer (and other apps that use this mode) at the expense of the other apps...
/* pointer callback */
static snd_pcm_uframes_t
snd_bcm2835_pcm_pointer(struct snd_pcm_substream *substream)
{
struct snd_pcm_runtime *runtime = substream->runtime;
bcm2835_alsa_stream_t *alsa_stream = runtime->private_data;
audio_info(" .. IN\n");
audio_debug("pcm_pointer... (%d) hwptr=%d appl=%d pos=%d\n", 0,
frames_to_bytes(runtime, runtime->status->hw_ptr),
frames_to_bytes(runtime, runtime->control->appl_ptr),
alsa_stream->pos);
audio_info(" .. OUT\n");
return bytes_to_frames(runtime, alsa_stream->pos);
}
static int snd_bcm2835_pcm_copy(struct snd_pcm_substream *substream,
int channel, snd_pcm_uframes_t pos, void *src,
snd_pcm_uframes_t count)
{
int ret;
struct snd_pcm_runtime *runtime = substream->runtime;
bcm2835_alsa_stream_t *alsa_stream = runtime->private_data;
audio_info(" .. IN\n");
audio_debug("copy.......... (%d) hwptr=%d appl=%d pos=%d\n",
frames_to_bytes(runtime, count), frames_to_bytes(runtime,
runtime->
status->
hw_ptr),
frames_to_bytes(runtime, runtime->control->appl_ptr),
alsa_stream->pos);
/*
.... -> you copy the given amount of
data (count) at the specified pointer (src) to the specified offset (pos)
on the hardware buffer.
When coded like memcpy-like way, the copy would be like:
my_memcpy(my_buffer + frames_to_bytes(runtime, pos), src,
frames_to_bytes(runtime, count));
*/
ret =
bcm2835_audio_write(alsa_stream, frames_to_bytes(runtime, count),
src);
// Update the "pointer"
alsa_stream->pos += frames_to_bytes(runtime, count);
alsa_stream->pos %= alsa_stream->buffer_size;
audio_info(" .. OUT\n");
return ret;
}
static int snd_bcm2835_pcm_silence(struct snd_pcm_substream *substream,
int channel, snd_pcm_uframes_t post,
snd_pcm_uframes_t count)
{
// int ret;
struct snd_pcm_runtime *runtime = substream->runtime;
bcm2835_alsa_stream_t *alsa_stream = runtime->private_data;
audio_info(" .. IN\n");
audio_debug("silence....... (%d) hwptr=%d appl=%d pos=%d\n",
frames_to_bytes(runtime, count), frames_to_bytes(runtime,
runtime->
status->
hw_ptr),
frames_to_bytes(runtime, runtime->control->appl_ptr),
alsa_stream->pos);
/*
The role of silence callback is to set the given amount (count) of silence
data at the specified offset (pos) on the hardware buffer. Suppose that the
data format is signed (that is, the silent-data is 0), and the
implementation using a memset-like function would be like:
my_memcpy(my_buffer + frames_to_bytes(runtime, pos), 0,
frames_to_bytes(runtime, count));
*/
//ret =
// bcm2835_audio_write(alsa_stream, frames_to_bytes(runtime, post),
// NULL);
alsa_stream->pos += frames_to_bytes(runtime, count);
alsa_stream->pos %= alsa_stream->buffer_size;
audio_info(" .. OUT\n");
return 0;
}Thanks for the investagation benosteen. Rather that fixing the calls to pcm_silence, I'd like to know why pcm_silence is getting called. I'm guessing if you run with a working ALSA driver pcm_silence does not get called. Might be worth looking at snd-dummy and see if mplayer behaves differently with respect to pcm_silence calls.
benosteen
commented
12 years ago What I discovered last night was that snd_pcm_silence did not mean play silence or catch up as I had thought, but was a command to erase part of the fake ring buffer.
Take a look at how sound/soc/blackfin/bf5xx-tdm-pcm.c does its silence and copy ops. From logging the data about what the offsets are (pos/post params passed to the bcm driver), the silence offset lags behind the alsa_stream->pos ptr and effectively ask for the buffer that was just played to be memset to zero.
In this case, where there is no hw ring buffer to clear indirectly but a fifo queue, you can change the pcm_silence call to just return 0 and do nothing else.
This still leaves the pointer callback - the blackfin driver above is also interesting in this respect too.
singpolyma
commented
12 years ago Is there a way to tell if the silence problem is affecting a program? I'm trying to get pianobar working, but the sound is very choppy and I'm wondering if it might be related to this. mpd works fine for me
popcornmix
commented
12 years ago There's been a firmware update that could help ALSA issues. Please update and test.
singpolyma
commented
12 years ago @popcornmix Ah, cool. Do you know if that firmware update is included in the Debian wheeze image that's currently being tested, or will I have to figure out how to install manually from here?
popcornmix
commented
12 years ago No, it's newer than the Wheezy image. You can update firmware with instructions here: http://elinux.org/R-Pi_Troubleshooting#Updating_firmware
singpolyma
commented
12 years ago pianobar no longer gets stuck during playback, and playback is significantly better. It's still very choppy, though, but that could be a different cause (pianobar goes to >90% CPU usage when playing... usually that's a sampling problem, but I'm not sure what it is in this case. Maybe unaccelerated AAC decode just takes that much juice? Also, I'm using tsocks to run over an SSH proxy, so maybe it's counting the encryption time as part of the process? I will poke some more.)
popcornmix
commented
12 years ago Closing as I believe the original oops issue is fixed.
positron96
commented
11 years ago Hello people! Can anyone tell me what to do to fix this issue in current raspbian (fresh 2013-02-09 with packages updated)? My mplayer fails to play anything exactly as described, while aplay does play wav files after modprobing.
positron96
commented
11 years ago Oh, sorry to mislead, it fails only under a regular user (aplay fails as well), everything works fine under root. Anyone knows if it's the desired effect?
licaon-kter
commented
11 years ago Try the updated stable branch ( 3.6.xx ) via sudo rpi-update or the testing branch ( 3.8.xx ) via sudo BRANCH=next rpi-update as ALSA fixes have been integrated last week. Remember to move (backup) /etc/asound.conf out of /etc as it's not needed anymore. To get back to the stable tree run: sudo rm /boot/.firmware_revision and sudo rpi-update.
positron96
commented
11 years ago Hello there and thanks for you answer!
Just updated via sudo rpi-update and moved away /etc/asound.conf. It's a pity, but mplayer did not start to work under regular user - it is now giving this output:
Failed to initialize audio driver 'pulse'
[AO_ALSA] alsa-lib: confmisc.c:768:(parse_card) cannot find card '0'
[AO_ALSA] alsa-lib: conf.c:4241:(_snd_config_evaluate) function snd_func_card_driver returned error: No such file or directory
[AO_ALSA] alsa-lib: confmisc.c:392:(snd_func_concat) error evaluating strings
[AO_ALSA] alsa-lib: conf.c:4241:(_snd_config_evaluate) function snd_func_concat returned error: No such file or directory
[AO_ALSA] alsa-lib: confmisc.c:1251:(snd_func_refer) error evaluating name
[AO_ALSA] alsa-lib: conf.c:4241:(_snd_config_evaluate) function snd_func_refer returned error: No such file or directory
[AO_ALSA] alsa-lib: conf.c:4720:(snd_config_expand) Evaluate error: No such file or directory
[AO_ALSA] alsa-lib: pcm.c:2217:(snd_pcm_open_noupdate) Unknown PCM default
[AO_ALSA] Playback open error: No such file or directory
Failed to initialize audio driver 'alsa'
[AO SDL] Samplerate: 44100Hz Channels: Stereo Format floatle
[AO SDL] using aalib audio driver.
[AO SDL] Unsupported audio format: 0x1d.
[AO SDL] Unable to open audio: No available audio device
Failed to initialize audio driver 'sdl:aalib'
Could not open/initialize audio device -> no sound.The output is different from yesterday's. It plays well under root though.
popcornmix
commented
11 years ago What does groups report?
groups
pi adm tty dialout cdrom sudo audio video plugdev games users netdev input indiecitymake sure it contains audio.
positron96
commented
11 years ago Huh, finally! The pi user has the required groups - and can play music well. However after a clean install I created a new user for myself, and it lacks all these groups - and fails to play music. Never saw that non-pi user would be the problem.
PS. How difficult is it to remove the need to add users to audio group for listening from the distro? And how is it done in other linuxes? I never seen a requirement to do anything with groups to play music in e.g. Ubuntu.
Ferroin
commented
11 years ago On Ubuntu, new users added through the graphical tools are in the 'audio' group by default (Unless you specifically prevent them from being added). While this does provide simplicity (eg, things work), it does so at the cost of security. Conventional *nix practice is to only add new users to the group 'users' by default, then add them to the appropriate groups for their privileges manually (ie. you have to give the user the priveleges, as opposed to needing to deny them).
positron96
commented
11 years ago Thanks for good explanation!
hello_audio builds and runs fine (alarmingly loud ;)) but modprobing the new alsa driver in and trying to play a song using mplayer causes a kernel oops:
Init:
Then, on SSH terminal or normal terminal:
modprobe snd_bcm2835
mplayer foo.mp3
(mplayer fails to find any audio hw to playback on)
then attempting to ls the mp3 directory will kick off the error.
console log: https://gist.github.com/2400335
On primary tty on the RPi, the main kernel oops is shown:
From /var/log/syslog: https://gist.github.com/2400347