Bug 247978 - Raspberry Pi audio stops working after a few hours
Summary: Raspberry Pi audio stops working after a few hours
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: arm (show other bugs)
Version: 12.1-STABLE
Hardware: Any Any
: --- Affects Only Me
Assignee: freebsd-arm (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-07-14 19:58 UTC by Harry NEWTON
Modified: 2020-07-15 17:52 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Harry NEWTON 2020-07-14 19:58:22 UTC
Sound [through jack] works fine for a while then stops working after a few hours.  Reboot fixes, but problem recurs.

Firmware [pkg install rpi-firmware] updated.

Raspberry Pi Model B Revision 2.0 / FreeBSD rpi-b 12.1-STABLE FreeBSD 12.1-STABLE r361761 RPI-B  arm

# cat /var/log/messages
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 65536 -> 4096 [512]
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[512/64/8] limit=341
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[512/64/8] limit=341
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 4096 [512] NOCHANGE
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[1024/128/8] limit=682
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[1024/128/8] limit=682
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_setspeed(): Setting speed 0 failed, falling back to 8000
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[1024/128/8] limit=682
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[1024/128/8] limit=682
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 4096 [1024] NOCHANGE
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[512/64/8] limit=341
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[512/64/8] limit=341
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 4096 [512] NOCHANGE
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[2048/256/8] limit=1365
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 4096 [2048] NOCHANGE
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[4096/512/8] limit=2730
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:45:59 rpi-b kernel: sndbuf_remalloc(): b=0xc170a700 4096 -> 16384 [16384]
Jul 14 20:45:59 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[16384/2048/8] limit=16384
Jul 14 20:46:00 rpi-b kernel: pcm0: chn_start(): PCMDIR_PLAY (virtual) threshold i=4096 j=4
Jul 14 20:46:00 rpi-b kernel: pcm0: chn_start(): VCHAN PARENT starting! (PCMDIR_PLAY/running) (ready=8192 force=1 i=1 j=0 intrtimeout=42 latency=208ms)
Jul 14 20:46:00 rpi-b kernel: pcm0: WARNING: PCMDIR_PLAY DMA completion too fast/slow ! hwptr=0, old=0 delta=0 amt=0 ready=8192 free=31808
Jul 14 20:46:00 rpi-b kernel: pcm0: chn_trigger() pcm0:play:dsp0.p0: calling go=0x00000001 , prev=0xffffffff
Jul 14 20:46:00 rpi-b kernel: pcm0: chn_trigger() pcm0:virtual:dsp0.vp0: calling go=0x00000001 , prev=0xffffffff
Jul 14 20:46:05 rpi-b kernel: pcm0: chn_write(): pcm0:virtual:dsp0.vp0: play interrupt timeout, channel dead
Jul 14 20:46:05 rpi-b kernel: pcm0: chn_trigger() pcm0:play:dsp0.p0: calling go=0xffffffff , prev=0x00000001
Jul 14 20:46:05 rpi-b kernel: pcm0: chn_trigger() pcm0:virtual:dsp0.vp0: calling go=0xffffffff , prev=0x00000001
Jul 14 20:46:05 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (hardware) timeout=42 b[40000/4000/2] bs[8192/4096/2] limit=0
Jul 14 20:46:05 rpi-b kernel: pcm0: chn_resizebuf(): PCMDIR_PLAY (virtual) timeout=42 b[0/0/0] bs[16384/2048/8] limit=16384
# sysctl -a | grep -i dev.pcm
dev.pcm.0.starved: 0
dev.pcm.0.freebuffer: 40000
dev.pcm.0.underruns: 6
dev.pcm.0.retrieved: 0
dev.pcm.0.submitted: 40000
dev.pcm.0.callbacks: 136300
dev.pcm.0.dest: 0
dev.pcm.0.bitperfect: 0
dev.pcm.0.buffersize: 0
dev.pcm.0.play.vchanformat: s16le:2.0
dev.pcm.0.play.vchanrate: 48000
dev.pcm.0.play.vchanmode: fixed
dev.pcm.0.play.vchans: 1
dev.pcm.0.%parent: vchiq0
dev.pcm.0.%pnpinfo:
dev.pcm.0.%location:
dev.pcm.0.%driver: pcm
dev.pcm.0.%desc: VCHIQ audio
dev.pcm.%parent:
# sysctl hw.snd
hw.snd.maxautovchans: 16
hw.snd.default_unit: 0
hw.snd.version: 2009061500/armv6
hw.snd.default_auto: 1
hw.snd.verbose: 4
hw.snd.vpc_mixer_bypass: 1
hw.snd.feeder_rate_quality: 1
hw.snd.feeder_rate_round: 25
hw.snd.feeder_rate_max: 2016000
hw.snd.feeder_rate_min: 1
hw.snd.feeder_rate_polyphase_max: 183040
hw.snd.feeder_rate_presets: 100:8:0.85 100:36:0.92 100:164:0.97
hw.snd.feeder_eq_exact_rate: 0
hw.snd.feeder_eq_presets: PEQ:16000,0.2500,62,0.2500:-9,9,1.0:44100,48000,88200,96000,176400,192000
hw.snd.basename_clone: 1
hw.snd.compat_linux_mmap: 0
hw.snd.syncdelay: -1
hw.snd.usefrags: 0
hw.snd.vpc_reset: 0
hw.snd.vpc_0db: 45
hw.snd.vpc_autoreset: 1
hw.snd.timeout: 5
hw.snd.latency_profile: 1
hw.snd.latency: 2
hw.snd.report_soft_matrix: 1
hw.snd.report_soft_formats: 1
# cat /dev/sndstat
FreeBSD Audio Driver (32bit 2009061500/armv6)
Installed devices:
pcm0: <VCHIQ audio> at VCHIQ (1p:1v/0r:0v) default
        snddev flags=0x2a3<SIMPLEX,AUTOVCHAN,BUSY,REGISTERED,VPC>
        [pcm0:play:dsp0.p0]: spd 48000, fmt 0x00200010, flags 0x00002100, 0x00000004
        interrupts 1, underruns 0, feed 0, ready 0 [b:40000/4000/2|bs:8192/4096/2]
        channel flags=0x2100<BUSY,HAS_VCHAN>
        {userland} -> feeder_mixer(0x00200010) -> {hardware}
        pcm0:play:dsp0.p0[pcm0:virtual:dsp0.vp0]: spd 48000, fmt 0x00201000/0x00200010, flags 0x10000000, 0x00000023
        interrupts 0, underruns 0, feed 0, ready 0 [b:0/0/0|bs:16384/2048/8]
        channel flags=0x10000000<VIRTUAL>
        {userland} -> feeder_root(0x00201000) -> feeder_format(0x00201000 -> 0x00200010) -> feeder_volume(0x00200010) -> {hardware}
No devices installed from userspace.

File Versions:
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_chain.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_eq.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_format.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_matrix.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_mixer.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_rate.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder_volume.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/mixer.c 359885 2020-04-13 16:31:13Z hselasky $
$FreeBSD: stable/12/sys/dev/sound/pcm/sndstat.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/sound.c 358877 2020-03-11 08:24:50Z hselasky $
$FreeBSD: stable/12/sys/dev/sound/pcm/vchan.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/ac97.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/ac97_patch.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/buffer.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/channel.c 326255 2017-11-27 14:52:40Z pfg $
$FreeBSD: stable/12/sys/dev/sound/pcm/dsp.c 361174 2020-05-18 09:07:14Z hselasky $
$FreeBSD: stable/12/sys/arm/broadcom/bcm2835/bcm2835_audio.c 310636 2016-12-27 19:08:08Z gonzo $
$FreeBSD: stable/12/sys/dev/sound/pcm/feeder.c 326255 2017-11-27 14:52:40Z pfg $
#
Comment 1 Harry NEWTON 2020-07-14 20:16:06 UTC
Machine doesn't hang: but not audio out.  Example message from play:

In:0.00% 00:00:00.00 [00:02:41.44] Out:0     [      |      ]        Clip:0    play FAIL sox: `default' Error writing to device: Invalid argument
Comment 2 Harry NEWTON 2020-07-15 17:52:24 UTC
(In reply to Harry NEWTON from comment #1)

But after a series of attempted plays failing, last attempt caused hang.  No messages in /var/log/messages.