Closed hailfinger closed 3 years ago
Note: Trying to reboot the Pi in this state was a bad idea. The Pi now hangs somewhere, and I can't even ping it. This is somewhat unfortunate since the Pi is in a locked building half an hour away from me.
Since it was mentioned on the forums that the error is caused by an old GStreamer version, I upgraded GStreamer to latest git (1.19). The problem persists.
This might also be related to bug #3791 .
@6by9 With Linux kernel 5.10.17-v7l+ but firmware from rpi-update this issue is not reproducible anymore. I'll do some stress tests and will close this report once I can confirm the bugfix works for heavy usage as well.
Mar 26 2021 16:34:17 Copyright (c) 2012 Broadcom version edf2e9c318863999c97c50cdb74eee235ede3af5 (clean) (release) (start_x)
With firmware edf2e9c318863999c97c50cdb74eee235ede3af5 and Linux kernel 5.10.17-v7l+, the issue is fixed. Thank you for the bugfix!
Describe the bug I'm using GStreamer to get 720p25 input from the official HQ Camera, then the video is processed and finally encoded with omxh264enc. Stopping the stream sometimes causes the kernel message "stop_streaming: Timeout waiting for buffers to be returned - 2 outstanding" together with a backtrace. Subsequent stops/starts of the stream cause similar backtraces with a growing number of outstanding buffers. Eventually the GStreamer process will hang in "Ds" state and three kworker/events processes will hang in "D" state. Unmodified Linux kernel 5.10.17-v7l+ from Raspberry Pi OS. GStreamer 1.14.4 from Raspberry Pi OS.
To reproduce Attach a Raspberry Pi HQ Camera to a Pi 4B. Run latest Raspberry Pi OS. Use the following GStreamer pipe:
Video source is /dev/video0 (Pi HQ Camera), audio source is hw:2 (USB audio device), these are set from python code starting the GStreamer pipeline.
Expected behaviour No hang.
Actual behaviour Stopping and restarting the stream caused the following error messages:
stop_streaming: Timeout waiting for buffers to be returned - <N> outstanding
with N (integer) strictly monotonically increasing each time the stream was restarted. This time the sequence for N was 2 8 13 18 23 28. After that, a backtrace is logged. After the backtrace, there is a varying number of messagesvideobuf2_common: driver bug: stop_streaming operation is leaving buf <addr> in active state
with addr being a 32 bit value varying each time.System System Information
Raspberry Pi 4 Model B Rev 1.1 PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)"
Raspberry Pi reference 2020-08-20 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 9a3a10bf1019ebb2d59053564dc6b90068bad27d, stage2
Linux pi-bonn-mitte 5.10.17-v7l+ #1403 SMP Mon Feb 22 11:33:35 GMT 2021 armv7l GNU/Linux Revision : c03111 Serial : 100000009180a974 Model : Raspberry Pi 4 Model B Rev 1.1 Throttled flag : throttled=0x0 Camera : supported=1 detected=1
Videocore information
Feb 25 2021 12:11:39 Copyright (c) 2012 Broadcom version 564e5f9b852b23a330b1764bcf0b2d022a20afd0 (clean) (release) (start_x)
alloc failures: 0 compactions: 0 legacy block fails: 0
Filesystem information
Filesystem 1K-blocks Used Available Use% Mounted on /dev/root 30485636 3289420 25910424 12% / devtmpfs 1607044 0 1607044 0% /dev tmpfs 1739140 560 1738580 1% /dev/shm tmpfs 1739140 16920 1722220 1% /run tmpfs 5120 0 5120 0% /run/lock tmpfs 1739140 0 1739140 0% /sys/fs/cgroup /dev/mmcblk0p1 258095 48784 209311 19% /boot tmpfs 347828 0 347828 0% /run/user/0
Filename Type Size Used Priority /var/swap file 102396 0 -2
Package version information
raspberrypi-ui-mods: Installed: (none) raspberrypi-sys-mods: Installed: 20210208 openbox: Installed: (none) lxpanel: Installed: (none) pcmanfm: Installed: (none) rpd-plym-splash: Installed: (none)
Networking Information
eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500 inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x inet6 y::y.y.y.y prefixlen 64 scopeid 0x20 inet6 y.y.y.y.y.y.y.y prefixlen 64 scopeid 0x0
ether m.m.m.m txqueuelen 1000 (Ethernet)
RX packets 11923789 bytes 801859900 (764.7 MiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 31823105 bytes 17993178 (17.1 MiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
lo: flags=73<UP,LOOPBACK,RUNNING> mtu 65536 inet x.x.x.x netmask x.x.x.x inet6 ::1 prefixlen 128 scopeid 0x10
loop txqueuelen 1000 (Local Loopback)
RX packets 6681857 bytes 4995494794 (4.6 GiB)
RX errors 0 dropped 0 overruns 0 frame 0
TX packets 6681857 bytes 4995494794 (4.6 GiB)
TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
wlan0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST> mtu 1500 inet x.x.x.x netmask x.x.x.x broadcast x.x.x.x inet6 y::y.y.y.y prefixlen 64 scopeid 0x20 ether m.m.m.m txqueuelen 1000 (Ethernet) RX packets 0 bytes 0 (0.0 B) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 150 bytes 18524 (18.0 KiB) TX errors 0 dropped 0 overruns 0 carrier 0 collisions 0
USB Information
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/4p, 5000M /: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/1p, 480M | Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M | Port 4: Dev 3, If 0, Class=Audio, Driver=snd-usb-audio, 12M | Port 4: Dev 3, If 1, Class=Audio, Driver=snd-usb-audio, 12M | Port 4: Dev 3, If 2, Class=Audio, Driver=snd-usb-audio, 12M |__ Port 4: Dev 3, If 3, Class=Human Interface Device, Driver=usbhid, 12M
config.txt
arm_freq=1500 audio_pwm_mode=514 config_hdmi_boost=5 core_freq=500 core_freq_min=200 disable_commandline_tags=2 disable_l2cache=1 display_hdmi_rotate=-1 display_lcd_rotate=-1 dvfs=2 enable_gic=1 enable_uart=1 force_eeprom_read=1 force_pwm_open=1 framebuffer_height=720 framebuffer_ignore_alpha=1 framebuffer_swap=1 framebuffer_width=1280 gpu_freq=500 gpu_freq_min=250 init_uart_clock=0x2dc6c00 lcd_framerate=60 mask_gpu_interrupt0=1024 mask_gpu_interrupt1=0x10000 max_framebuffers=2 over_voltage_avs=-30000 pause_burst_frames=1 program_serial_random=1 total_mem=4096 hdmi_force_cec_address:0=65535 hdmi_force_cec_address:1=65535 hdmi_force_hotplug:0=1 hdmi_group:0=1 hdmi_mode:0=19 hdmi_pixel_freq_limit:0=0x11e1a300 hdmi_pixel_freq_limit:1=0x11e1a300 device_tree=- overlay_prefix=overlays/ hdmi_cvt:0= hdmi_cvt:1= hdmi_edid_filename:0= hdmi_edid_filename:1= hdmi_timings:0= hdmi_timings:1=
cmdline.txt
coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 video=HDMI-A-1:1280x720M@50,margin_left=48,margin_right=48,margin_top=48,margin_bottom=48 smsc95xx.macaddr=DC:A6:32:48:B9:FC vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=tty1 root=PARTUUID=e662039f-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
raspi-gpio settings
BANK0 (GPIO 0 to 27): GPIO 0: level=1 fsel=0 func=INPUT pull=UP GPIO 1: level=1 fsel=0 func=INPUT pull=UP GPIO 2: level=1 fsel=4 alt=0 func=SDA1 pull=UP GPIO 3: level=1 fsel=4 alt=0 func=SCL1 pull=UP GPIO 4: level=1 fsel=0 func=INPUT pull=UP GPIO 5: level=1 fsel=0 func=INPUT pull=UP GPIO 6: level=1 fsel=0 func=INPUT pull=UP GPIO 7: level=1 fsel=1 func=OUTPUT pull=UP GPIO 8: level=1 fsel=1 func=OUTPUT pull=UP GPIO 9: level=0 fsel=4 alt=0 func=SPI0_MISO pull=DOWN GPIO 10: level=0 fsel=4 alt=0 func=SPI0_MOSI pull=DOWN GPIO 11: level=0 fsel=4 alt=0 func=SPI0_SCLK pull=DOWN GPIO 12: level=0 fsel=0 func=INPUT pull=DOWN GPIO 13: level=0 fsel=0 func=INPUT pull=DOWN GPIO 14: level=1 fsel=2 alt=5 func=TXD1 pull=NONE GPIO 15: level=1 fsel=2 alt=5 func=RXD1 pull=UP GPIO 16: level=0 fsel=0 func=INPUT pull=DOWN GPIO 17: level=0 fsel=0 func=INPUT pull=DOWN GPIO 18: level=0 fsel=0 func=INPUT pull=DOWN GPIO 19: level=0 fsel=0 func=INPUT pull=DOWN GPIO 20: level=0 fsel=0 func=INPUT pull=DOWN GPIO 21: level=0 fsel=0 func=INPUT pull=DOWN GPIO 22: level=0 fsel=0 func=INPUT pull=DOWN GPIO 23: level=0 fsel=0 func=INPUT pull=DOWN GPIO 24: level=0 fsel=0 func=INPUT pull=DOWN GPIO 25: level=0 fsel=0 func=INPUT pull=DOWN GPIO 26: level=0 fsel=0 func=INPUT pull=DOWN GPIO 27: level=0 fsel=0 func=INPUT pull=DOWN BANK1 (GPIO 28 to 45): GPIO 28: level=1 fsel=2 alt=5 func=RGMII_MDIO pull=UP GPIO 29: level=0 fsel=2 alt=5 func=RGMII_MDC pull=DOWN GPIO 30: level=0 fsel=7 alt=3 func=CTS0 pull=UP GPIO 31: level=0 fsel=7 alt=3 func=RTS0 pull=NONE GPIO 32: level=1 fsel=7 alt=3 func=TXD0 pull=NONE GPIO 33: level=1 fsel=7 alt=3 func=RXD0 pull=UP GPIO 34: level=0 fsel=7 alt=3 func=SD1_CLK pull=NONE GPIO 35: level=1 fsel=7 alt=3 func=SD1_CMD pull=UP GPIO 36: level=1 fsel=7 alt=3 func=SD1_DAT0 pull=UP GPIO 37: level=1 fsel=7 alt=3 func=SD1_DAT1 pull=UP GPIO 38: level=1 fsel=7 alt=3 func=SD1_DAT2 pull=UP GPIO 39: level=1 fsel=7 alt=3 func=SD1_DAT3 pull=UP GPIO 40: level=0 fsel=4 alt=0 func=PWM1_0 pull=NONE GPIO 41: level=0 fsel=4 alt=0 func=PWM1_1 pull=NONE GPIO 42: level=0 fsel=1 func=OUTPUT pull=UP GPIO 43: level=1 fsel=0 func=INPUT pull=UP GPIO 44: level=1 fsel=0 func=INPUT pull=UP GPIO 45: level=1 fsel=0 func=INPUT pull=UP BANK2 (GPIO 46 to 53): GPIO 46: level=0 fsel=0 func=INPUT pull=UP GPIO 47: level=0 fsel=0 func=INPUT pull=UP GPIO 48: level=0 fsel=0 func=INPUT pull=DOWN GPIO 49: level=0 fsel=0 func=INPUT pull=DOWN GPIO 50: level=0 fsel=0 func=INPUT pull=DOWN GPIO 51: level=0 fsel=0 func=INPUT pull=DOWN GPIO 52: level=0 fsel=0 func=INPUT pull=DOWN GPIO 53: level=0 fsel=0 func=INPUT pull=DOWN
vcdbg log messages
005687.392: arasan: arasan_emmc_open 006121.371: brfs: File read: /mfs/sd/config.txt 006122.360: brfs: File read: 1906 bytes 006217.386: brfs: File read: /mfs/sd/config.txt 007289.417: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined 007291.917: *** Restart logging 007291.938: brfs: File read: 1906 bytes 007334.115: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 007334.132: HDMI0: hdmi_pixel_encoding: 300000000 007334.143: HDMI1: hdmi_pixel_encoding: 300000000 007339.093: dtb_file 'bcm2711-rpi-4-b.dtb' 007344.559: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb 007344.574: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xbfc2 007357.229: brfs: File read: 49090 bytes 007369.116: brfs: File read: /mfs/sd/overlays/overlay_map.dtb 007432.886: brfs: File read: 1523 bytes 007435.353: brfs: File read: /mfs/sd/config.txt 007435.815: dtparam: i2c_arm=on 007444.056: dtparam: i2c_vc=on 007457.066: dtparam: spi=on 007464.847: dtparam: audio=on 007474.718: brfs: File read: 1906 bytes 007487.688: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d.dtbo 007504.974: Loaded overlay 'vc4-fkms-v3d' 007581.809: brfs: File read: 1446 bytes 007584.143: brfs: File read: /mfs/sd/cmdline.txt 007584.201: Read command line from file 'cmdline.txt': 007584.222: 'console=tty1 root=PARTUUID=e662039f-02 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait' 008687.665: brfs: File read: 98 bytes 009245.431: brfs: File read: /mfs/sd/kernel7l.img 009245.452: Loading 'kernel7l.img' to 0x8000 size 0x662688 009245.479: Device tree loaded to 0x1ffe3a00 (size 0xc5c6) 009250.989: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined 012618.059: vchiq_core: vchiq_init_state: slot_zero = 0xcfd80000, is_master = 1 012620.128: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 012625.026: TV service:host side not connected, dropping notification 0x00000002, 0x00000001, 0x00000013 016392.394: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 016518.052: TV service:host side not connected, dropping notification 0x00000008, 0x00000004, 0x00000000 016693.007: camsubs: Camera not found 016693.078: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 016993.690: camsubs: Camera found OK 027635.354: imx477_open: read id 1143 succes 0! 027735.131: Using RPI AWB 028838.506: brfs: File read: 6694536 bytes 029526.073: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 029526.106: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3856429.230: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3856429.256: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3949123.074: imx477_open: read id 1143 succes 0! 3949132.674: Using RPI AWB 3950219.914: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3950219.948: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3950229.996: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3950230.024: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3950240.074: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3950240.099: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3950250.152: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3950250.179: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3950328.878: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3950328.915: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2129635.379: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2129635.403: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 255232.551: imx477_open: read id 1143 succes 0! 255242.157: Using RPI AWB 256248.520: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 256248.542: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 256258.580: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 256258.607: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 256272.798: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 256272.820: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 256282.861: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 256282.885: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 256293.556: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 256293.578: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 970288.066: imx477_open: read id 1143 succes 0! 970297.640: Using RPI AWB 971350.671: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 971350.696: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 971362.234: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 971362.255: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 971372.803: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 971372.826: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 971382.860: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 971382.881: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 971393.514: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 971393.563: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1277418.263: imx477_open: read id 1143 succes 0! 1277429.264: Using RPI AWB 1278510.933: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1278510.954: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1278520.990: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1278521.014: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1278531.047: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1278531.067: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1278542.808: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1278542.834: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1278552.878: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1278552.900: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1725759.645: imx477_open: read id 1143 succes 0! 1725769.256: Using RPI AWB 1726766.334: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1726766.360: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1726776.392: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1726776.411: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1726786.448: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1726786.475: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1726796.515: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1726796.537: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 1726806.572: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 1726806.596: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
dmesg log