Bug 248710

Summary:	Raspberry Pi audio stops working after a few hours
Product:	Base System	Reporter:	Harry NEWTON <hn>
Component:	arm	Assignee:	freebsd-arm (Nobody) <freebsd-arm>
Status:	New ---
Severity:	Affects Some People
Priority:	---
Version:	11.3-RELEASE
Hardware:	arm
OS:	Any
See Also:	https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=129604 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=208678 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=247978 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=205979 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=213687 https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=217434

Description Harry NEWTON 2020-08-17 19:47:18 UTC

Sound [through jack] works fine for a while then stops working after a few hours.  Reboot fixes, but problem recurs.


FreeBSD rpi2 11.3-RELEASE FreeBSD 11.3-RELEASE #0 r349754: Fri Jul  5 03:50:39 UTC 2019     root@releng2.nyi.freebsd.org:/usr/obj/arm.armv6/usr/src/sys/RPI2  arm


This is exactly the same as my bug #247978, but with different hardware [Raspberry PI 2 rather than Raspberry PI 1] and different version of FreeBSD [11.3-RELEASE rather than 12.1-STABLE].  Using 11-3.RELEASE on the RPI2 does not crash the machine however.

It appears to be the same as #129604 [dating back to 2012 and still extant] and #208678 [dating from 2016 and marked as closed].


Once audio has stopped working, it has stopped regardless of the file format [flac, mp3, ogg] and player [sox/play, mpg123, mplayer].


sox error message:  play FAIL sox: `default' Error writing to device: Invalid argument

mpg123 error message:  [src/libout123/libout123.c:722] error: Error in writing audio, wrote only -1 of 4608 (Invalid argument?)!
main: [src/mpg123.c:839] error: Deep trouble! Cannot flush to my output anymore!

mplayer error message:  Audio device got stuck!

/var/log/messages [with hw.snd.verbose=4]:

Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [131072] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[4096/128/32] limit=341
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[4096/128/32] limit=341
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [4096] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[8192/256/32] limit=682
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[8192/256/32] limit=682
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_setspeed(): Setting speed 0 failed, falling back to 8000
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[8192/256/32] limit=682
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[8192/256/32] limit=682
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [8192] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[4096/128/32] limit=341
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[4096/128/32] limit=341
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [4096] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[16384/512/32] limit=1365
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [16384] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[32768/1024/32] limit=2730
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:30 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [32768] NOCHANGE
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[131072/4096/32] limit=16384
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_start(): PCMDIR_PLAY (virtual) threshold i=4096 j=4
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_start(): VCHAN PARENT starting! (PCMDIR_PLAY/running) (ready=8192 force=1 i=1 j=0 intrtimeout=42 latency=208ms)
Aug 17 20:40:30 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=0, old=0 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_trigger() pcm0:play:dsp0.p0: calling go=0x00000001 , prev=0xffffffff
Aug 17 20:40:30 rpi2 kernel: pcm0: chn_trigger() pcm0:virtual:dsp0.vp0: calling go=0x00000001 , prev=0xffffffff
Aug 17 20:40:35 rpi2 kernel: pcm0: chn_write(): pcm0:virtual:dsp0.vp0: play interrupt timeout, channel dead
Aug 17 20:40:35 rpi2 kernel: pcm0: chn_trigger() pcm0:play:dsp0.p0: calling go=0xffffffff , prev=0x00000001
Aug 17 20:40:35 rpi2 kernel: pcm0: chn_trigger() pcm0:virtual:dsp0.vp0: calling go=0xffffffff , prev=0x00000001
Aug 17 20:40:35 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:40:36 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[131072/4096/32] limit=16384

Comment 1 Harry NEWTON 2020-08-17 19:59:16 UTC

Following reboot, _successful_ playing fills /var/log/messages with:

Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=0, old=0 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=4000, old=4000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=12000, old=12000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=16000, old=16000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 syslogd: last message repeated 1 times
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=24000, old=24000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 syslogd: last message repeated 1 times
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=32000, old=32000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 syslogd: last message repeated 2 times
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=0, old=0 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=4000, old=4000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 2656 bytes (count=4000 l=1344 feed=85372)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 2000 bytes (count=2000 l=0 feed=85373)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 1000 bytes (count=1000 l=0 feed=85374)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 496 bytes (count=496 l=0 feed=85375)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 248 bytes (count=248 l=0 feed=85376)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 128 bytes (count=128 l=0 feed=85377)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 64 bytes (count=64 l=0 feed=85378)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 32 bytes (count=32 l=0 feed=85379)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 16 bytes (count=16 l=0 feed=85380)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 8 bytes (count=8 l=0 feed=85381)
Aug 17 20:55:41 rpi2 kernel: feed_root: (virtual) appending 8 bytes (count=8 l=0 feed=85382)
Aug 17 20:55:41 rpi2 kernel: pcm0: chn_sync(): timeout=42 count=18 hcount=18 resid=0 residp=0 minflush=0 ret=35
Aug 17 20:55:41 rpi2 kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=8000, old=8000 delta=0 amt=0 ready=8192 free=31808
Aug 17 20:55:41 rpi2 kernel: pcm0: chn_trigger() pcm0:play:dsp0.p0: calling go=0xffffffff , prev=0x00000001
Aug 17 20:55:41 rpi2 kernel: pcm0: chn_trigger() pcm0:virtual:dsp0.vp0: calling go=0xffffffff , prev=0x00000001
Aug 17 20:55:41 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Aug 17 20:55:41 rpi2 kernel: sndbuf_remalloc(): b=0xc3d73b00 131072 [65536] NOCHANGE
Aug 17 20:55:41 rpi2 kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[131072/4096/32] limit=16384

Comment 2 Harry NEWTON 2020-08-22 10:21:49 UTC

Bug appears regardless of output type [HDMI or audio jack].

Comment 3 Harry NEWTON 2020-09-11 21:11:50 UTC

The failure is intermittent.  After ~ 2 weeks the channel has [briefly] come alive again and could play sound.  The resolution did not last and it died again.