hailfinger commented 2 years ago

Describe the bug (Very similar to #4592 , but different log messages from vcdbg, and pipeline includes audio)

Using the v4l2h264dec decoder in Raspberry Pi OS 64 bit with GStreamer 1.19, the video will reproducibly slow down extremely/hang after 20-80 minutes on some Raspberry Pi 4B 4GB machines. The machines exhibiting the hang will do so reproducibly, but the affected machines are only a small percentage of my 100+ devices pool of Raspberry PI 4B running 64-bit Raspberry Pi OS. GStreamer will start emitting QoS messages and a few seconds to minutes later the video will freeze (I haven't seen it continue, but maybe the frame rate is just extremely low). If you stop GStreamer in this state, the kernel will emit the timeout message in the logs down below.

To reproduce Launch an X server, configure for 720p50 on first HDMI output, then run GStreamer 1.19 with

gst-launch-1.0 -m souphttpsrc name=videosrc is-live=true location=https://stream.iptv.nak.org/teststream/high/index.m3u8 ! hlsdemux ! queue ! tsdemux name=mux ! tee name=vid ! queue ! h264parse ! queue min-threshold-buffers=3 ! v4l2h264dec ! queue min-threshold-buffers=3 ! glupload ! glcolorconvert ! glcolorscale ! video/x-raw(memory:GLMemory),width=1280,height=720 ! glimagesinkelement sync=true mux. ! queue ! aacparse ! avdec_aac ! tee name=audio ! queue ! audioconvert ! alsasink device=hw:0

Expected behaviour Video continues playing for hours (video is an endless loop).

Actual behaviour Video hangs after 10-40 minutes.

System System Information

Raspberry Pi 4 Model B Rev 1.2 PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)"

Raspberry Pi reference 2021-05-07 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 071d3956353f2be964d2d337d3b123f1872b7f53, stage2

Linux pi-gross-gerau 5.10.52-v8+ #1441 SMP PREEMPT Tue Aug 3 18:14:03 BST 2021 aarch64 GNU/Linux Revision : c03112 Serial : 10000000db051af0 Model : Raspberry Pi 4 Model B Rev 1.2 Throttled flag : throttled=0x0 Camera : supported=1 detected=0

Videocore information

alloc failures: 0 compactions: 0 legacy block fails: 0

Filesystem information

Filesystem 1K-blocks Used Available Use% Mounted on /dev/root 8191416 3251040 4504564 42% / devtmpfs 1685344 0 1685344 0% /dev tmpfs 1851072 420 1850652 1% /dev/shm tmpfs 1851072 16932 1834140 1% /run tmpfs 5120 0 5120 0% /run/lock tmpfs 1851072 0 1851072 0% /sys/fs/cgroup /dev/mmcblk0p3 258095 30302 227794 12% /boot tmpfs 370212 0 370212 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: 20210901 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 ether m.m.m.m txqueuelen 1000 (Ethernet) RX packets 447992 bytes 423277804 (403.6 MiB) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 222020 bytes 116601894 (111.2 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 704338 bytes 369120848 (352.0 MiB) RX errors 0 dropped 0 overruns 0 frame 0 TX packets 704338 bytes 369120848 (352.0 MiB) 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 | Port 1: Dev 2, If 0, Class=Video, Driver=uvcvideo, 5000M | Port 1: Dev 2, If 1, Class=Video, Driver=uvcvideo, 5000M | Port 1: Dev 2, If 2, Class=Human Interface Device, Driver=usbhid, 5000M | Port 1: Dev 2, If 3, Class=Audio, Driver=snd-usb-audio, 5000M | Port 1: Dev 2, If 4, Class=Audio, Driver=snd-usb-audio, 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_64bit=1 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 disable_overscan=1 disable_splash=1 display_hdmi_rotate=-1 display_lcd_rotate=-1 dvfs=3 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=-17500 pause_burst_frames=1 program_serial_random=1 second_boot=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 smsc95xx.macaddr=E4:5F:01:01:AE:05 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=tty1 root=PARTUUID=94644f4c-04 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=4 alt=0 func=TXD0 pull=NONE GPIO 15: level=1 fsel=4 alt=0 func=RXD0 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=1 fsel=0 func=INPUT pull=UP GPIO 31: level=1 fsel=0 func=INPUT pull=NONE GPIO 32: level=0 fsel=0 func=INPUT pull=DOWN GPIO 33: level=0 fsel=0 func=INPUT pull=DOWN GPIO 34: level=1 fsel=0 func=INPUT pull=UP GPIO 35: level=1 fsel=0 func=INPUT pull=UP GPIO 36: level=1 fsel=0 func=INPUT pull=UP GPIO 37: level=1 fsel=0 func=INPUT pull=UP GPIO 38: level=1 fsel=0 func=INPUT pull=UP GPIO 39: level=1 fsel=0 func=INPUT 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

005683.915: arasan: arasan_emmc_open 006121.846: brfs: File read: /mfs/sd/tryboot.txt 006122.802: brfs: File read: 1981 bytes 006173.009: HDMI0:EDID error reading EDID block 0 attempt 0 006179.034: HDMI0:EDID error reading EDID block 0 attempt 1 006185.057: HDMI0:EDID error reading EDID block 0 attempt 2 006191.082: HDMI0:EDID error reading EDID block 0 attempt 3 006197.104: HDMI0:EDID error reading EDID block 0 attempt 4 006203.128: HDMI0:EDID error reading EDID block 0 attempt 5 006209.151: HDMI0:EDID error reading EDID block 0 attempt 6 006215.176: HDMI0:EDID error reading EDID block 0 attempt 7 006221.198: HDMI0:EDID error reading EDID block 0 attempt 8 006227.223: HDMI0:EDID error reading EDID block 0 attempt 9 006228.237: HDMI0:EDID giving up on reading EDID block 0 006248.600: HDMI1:EDID error reading EDID block 0 attempt 0 006254.625: HDMI1:EDID error reading EDID block 0 attempt 1 006260.647: HDMI1:EDID error reading EDID block 0 attempt 2 006266.672: HDMI1:EDID error reading EDID block 0 attempt 3 006272.695: HDMI1:EDID error reading EDID block 0 attempt 4 006278.719: HDMI1:EDID error reading EDID block 0 attempt 5 006284.741: HDMI1:EDID error reading EDID block 0 attempt 6 006290.766: HDMI1:EDID error reading EDID block 0 attempt 7 006296.789: HDMI1:EDID error reading EDID block 0 attempt 8 006302.813: HDMI1:EDID error reading EDID block 0 attempt 9 006303.826: HDMI1:EDID giving up on reading EDID block 0 006305.725: brfs: File read: /mfs/sd/tryboot.txt 007379.564: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined 007382.085: *** Restart logging 007382.106: brfs: File read: 1981 bytes 007387.475: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 007393.502: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 007399.526: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 007405.553: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 007411.578: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 007417.605: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 007423.629: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 007429.655: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 007435.680: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 007441.707: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 007442.722: hdmi: HDMI0:EDID giving up on reading EDID block 0 007447.767: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 007453.794: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 007459.818: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 007465.845: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 007471.869: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 007477.896: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 007483.920: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 007489.946: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 007495.971: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 007501.998: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 007503.012: hdmi: HDMI0:EDID giving up on reading EDID block 0 007514.470: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0 007520.498: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1 007526.522: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2 007538.925: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3 007544.978: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4 007551.032: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5 007557.081: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6 007563.135: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7 007569.186: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8 007575.240: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9 007576.272: hdmi: HDMI1:EDID giving up on reading EDID block 0 007581.366: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0 007587.419: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1 007593.470: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2 007599.523: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3 007605.575: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4 007611.630: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5 007617.679: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6 007623.732: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7 007629.785: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8 007635.837: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9 007636.869: hdmi: HDMI1:EDID giving up on reading EDID block 0 007636.907: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 007636.937: HDMI0: hdmi_pixel_encoding: 300000000 007636.963: HDMI1: hdmi_pixel_encoding: 300000000 007642.658: dtb_file 'bcm2711-rpi-4-b.dtb' 007653.520: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb 007653.552: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xc2a1 007685.277: brfs: File read: 49825 bytes 007700.069: brfs: File read: /mfs/sd/overlays/overlay_map.dtb 007857.429: brfs: File read: 1667 bytes 007861.089: brfs: File read: /mfs/sd/tryboot.txt 007861.806: dtparam: i2c_arm=on 007882.551: dtparam: i2c_vc=on 007915.192: dtparam: spi=on 007934.907: dtparam: audio=on 007959.594: brfs: File read: 1981 bytes 007977.021: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d-pi4.dtbo 008019.675: Loaded overlay 'vc4-fkms-v3d' 008105.696: brfs: File read: 1446 bytes 008111.650: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo 008146.978: Loaded overlay 'disable-bt' 008227.315: brfs: File read: 1073 bytes 008232.717: brfs: File read: /mfs/sd/overlays/disable-wifi.dtbo 008255.578: Loaded overlay 'disable-wifi' 008306.002: brfs: File read: 387 bytes 008307.431: brfs: File read: /mfs/sd/cmdline.txt 008307.488: Read command line from file 'cmdline.txt': 008307.510: 'console=tty1 root=PARTUUID=94644f4c-04 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait' 008608.452: brfs: File read: 98 bytes 010141.999: brfs: File read: /mfs/sd/kernel8.img 010142.035: Loading 'kernel8.img' to 0x80000 size 0x789ef5 012812.234: Kernel relocated to 0x200000 012812.257: Device tree loaded to 0x2eff3700 (size 0xc88e) 012834.513: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined 014903.271: vchiq_core: vchiq_init_state: slot_zero = 0xdb000000, is_master = 1 014906.533: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 014913.980: TV service:host side not connected, dropping notification 0x00000002, 0x00000001, 0x00000013 018234.200: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018441.037: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 018447.092: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 018453.146: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 018459.202: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 018465.253: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 018471.310: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 018477.364: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 018483.419: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 018489.472: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 018495.528: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 018496.564: hdmi: HDMI0:EDID giving up on reading EDID block 0 018534.941: camsubs: Camera not found 018535.109: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018622.470: TV service:host side not connected, dropping notification 0x00000004, 0x00000004, 0x00000000 018835.843: camsubs: Camera not found 018836.006: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018836.725: camsubs: Camera not found 018836.872: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018837.591: camsubs: Camera not found 018837.738: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018837.949: camsubs: Camera not found 024138.838: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 024144.865: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 024150.893: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 024156.917: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 024162.944: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 024168.970: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 024174.997: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 024181.022: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 024187.049: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 024193.075: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 024194.093: hdmi: HDMI0:EDID giving up on reading EDID block 0 024200.570: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 024206.596: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 024212.624: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 024218.649: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 024224.676: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 024230.702: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 024236.730: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 024242.755: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 024248.782: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 024254.808: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 024255.825: hdmi: HDMI0:EDID giving up on reading EDID block 0 025458.762: TV service:host side not connected, dropping notification 0x00000004, 0x00000004, 0x00000000 028682.422: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 028688.477: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 028694.532: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 028700.586: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 028706.643: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 028712.696: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 028718.762: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 028724.813: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 028730.866: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 028736.918: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 028737.954: hdmi: HDMI0:EDID giving up on reading EDID block 0 028743.483: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0 028749.534: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1 028755.587: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2 028761.639: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3 028767.692: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4 028773.742: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5 028779.798: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6 028785.848: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7 028791.902: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8 028797.954: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9 028798.990: hdmi: HDMI0:EDID giving up on reading EDID block 0 3824707.105: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3824707.127: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3824747.151: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3824747.175: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3824787.144: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3824787.165: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 3824827.073: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 3824827.096: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 4220813.201: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 4220813.241: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 4220823.289: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 4220823.328: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 4224886.334: mmal: fail_destroy: Timed out waiting to destroy ril.video_decode

dmesg log

[ 0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083] [ 0.000000] Linux version 5.10.52-v8+ (dom@buildbot) (aarch64-linux-gnu-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1441 SMP PREEMPT Tue Aug 3 18:14:03 BST 2021 [ 0.000000] random: fast init done [ 0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.2 [ 0.000000] efi: UEFI not found. [ 0.000000] Reserved memory: created CMA memory pool at 0x000000001ac00000, size 320 MiB [ 0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000000000-0x000000003fffffff] [ 0.000000] DMA32 [mem 0x0000000040000000-0x00000000fbffffff] [ 0.000000] Normal empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000000000-0x000000002fffffff] [ 0.000000] node 0: [mem 0x0000000040000000-0x00000000fbffffff] [ 0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff] [ 0.000000] On node 0 totalpages: 966656 [ 0.000000] DMA zone: 3072 pages used for memmap [ 0.000000] DMA zone: 0 pages reserved [ 0.000000] DMA zone: 196608 pages, LIFO batch:63 [ 0.000000] DMA32 zone: 12032 pages used for memmap [ 0.000000] DMA32 zone: 770048 pages, LIFO batch:63 [ 0.000000] percpu: Embedded 32 pages/cpu s91224 r8192 d31656 u131072 [ 0.000000] pcpu-alloc: s91224 r8192 d31656 u131072 alloc=32*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [ 0.000000] Detected PIPT I-cache on CPU0 [ 0.000000] CPU features: detected: Spectre-v2 [ 0.000000] CPU features: detected: Spectre-v4 [ 0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923 [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 951552 [ 0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 video=HDMI-A-1:1280x720M@50 smsc95xx.macaddr=m.m.m.m vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000 console=tty1 root=PARTUUID=94644f4c-04 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait [ 0.000000] Kernel parameter elevator= does not have any effect anymore. Please use sysfs to set IO scheduler for individual devices. [ 0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear) [ 0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear) [ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off [ 0.000000] software IO TLB: mapped [mem 0x0000000016c00000-0x000000001ac00000] (64MB) [ 0.000000] Memory: 3370688K/3866624K available (11136K kernel code, 1946K rwdata, 3984K rodata, 3776K init, 1260K bss, 168256K reserved, 327680K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] ftrace: allocating 36745 entries in 144 pages [ 0.000000] ftrace: allocated 144 pages with 2 groups [ 0.000000] rcu: Preemptible hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4. [ 0.000000] Trampoline variant of Tasks RCU enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0 [ 0.000000] GIC: Using split EOI/Deactivate mode [ 0.000000] random: get_random_bytes called from start_kernel+0x3b0/0x570 with crng_init=1 [ 0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns [ 0.000006] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns [ 0.000260] Console: colour dummy device 80x25 [ 0.000800] printk: console [tty1] enabled [ 0.000866] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000) [ 0.000905] pid_max: default: 32768 minimum: 301 [ 0.001062] LSM: Security Framework initializing [ 0.001306] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) [ 0.001383] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear) [ 0.002695] cgroup: Disabling memory control group subsystem [ 0.005106] rcu: Hierarchical SRCU implementation. [ 0.006162] EFI services will not be available. [ 0.006694] smp: Bringing up secondary CPUs ... [ 0.007687] Detected PIPT I-cache on CPU1 [ 0.007766] CPU1: Booted secondary processor 0x0000000001 [0x410fd083] [ 0.008872] Detected PIPT I-cache on CPU2 [ 0.008919] CPU2: Booted secondary processor 0x0000000002 [0x410fd083] [ 0.010007] Detected PIPT I-cache on CPU3 [ 0.010055] CPU3: Booted secondary processor 0x0000000003 [0x410fd083] [ 0.010203] smp: Brought up 1 node, 4 CPUs [ 0.010293] SMP: Total of 4 processors activated. [ 0.010316] CPU features: detected: 32-bit EL0 Support [ 0.010338] CPU features: detected: CRC32 instructions [ 0.010360] CPU features: detected: 32-bit EL1 Support [ 0.043962] CPU: All CPU(s) started at EL2 [ 0.044058] alternatives: patching kernel code [ 0.045650] devtmpfs: initialized [ 0.056530] Enabled cp15_barrier support [ 0.056595] Enabled setend support [ 0.056818] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns [ 0.056861] futex hash table entries: 1024 (order: 4, 65536 bytes, linear) [ 0.065688] pinctrl core: initialized pinctrl subsystem [ 0.066475] DMI not present or invalid. [ 0.066862] NET: Registered protocol family 16 [ 0.070008] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations [ 0.070294] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.071228] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.071338] audit: initializing netlink subsys (disabled) [ 0.071744] audit: type=2000 audit(0.068:1): state=initialized audit_enabled=0 res=1 [ 0.072261] thermal_sys: Registered thermal governor 'step_wise' [ 0.072725] cpuidle: using governor menu [ 0.073092] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers. [ 0.073281] ASID allocator initialised with 65536 entries [ 0.073438] Serial: AMBA PL011 UART driver [ 0.104850] bcm2835-mbox fe00b880.mailbox: mailbox enabled [ 0.112373] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-08-03T18:16:37, variant start_x [ 0.116381] raspberrypi-firmware soc:firmware: Firmware hash is 40787ee5905644f639a2a0f6e00ae12e517a2211 [ 0.150376] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1 [ 0.154279] vgaarb: loaded [ 0.154718] SCSI subsystem initialized [ 0.154940] usbcore: registered new interface driver usbfs [ 0.155005] usbcore: registered new interface driver hub [ 0.155094] usbcore: registered new device driver usb [ 0.155428] usb_phy_generic phy: supply vcc not found, using dummy regulator [ 0.157314] clocksource: Switched to clocksource arch_sys_counter [ 1.176678] VFS: Disk quotas dquot_6.6.0 [ 1.176802] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.176980] FS-Cache: Loaded [ 1.177232] CacheFiles: Loaded [ 1.178374] simple-framebuffer 3e843000.framebuffer: framebuffer at 0x3e843000, 0x384000 bytes, mapped to 0x(ptrval) [ 1.178410] simple-framebuffer 3e843000.framebuffer: format=a8r8g8b8, mode=1280x720x32, linelength=5120 [ 1.183827] Console: switching to colour frame buffer device 160x45 [ 1.188557] simple-framebuffer 3e843000.framebuffer: fb0: simplefb registered! [ 1.198998] NET: Registered protocol family 2 [ 1.199561] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear) [ 1.203147] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear) [ 1.203292] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear) [ 1.203580] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear) [ 1.204163] TCP: Hash tables configured (established 32768 bind 32768) [ 1.204472] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear) [ 1.204612] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear) [ 1.205005] NET: Registered protocol family 1 [ 1.206003] RPC: Registered named UNIX socket transport module. [ 1.206082] RPC: Registered udp transport module. [ 1.206141] RPC: Registered tcp transport module. [ 1.206200] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.206286] PCI: CLS 0 bytes, default 64 [ 1.210512] hw perfevents: enabled with armv8_cortex_a72 PMU driver, 7 counters available [ 1.212700] kvm [1]: IPA Size Limit: 44 bits [ 1.215759] kvm [1]: vgic interrupt IRQ9 [ 1.217961] kvm [1]: Hyp mode initialized successfully [ 1.222045] Initialise system trusted keyrings [ 1.224214] workingset: timestamp_bits=46 max_order=20 bucket_order=0 [ 1.232378] zbud: loaded [ 1.235925] FS-Cache: Netfs 'nfs' registered for caching [ 1.238414] NFS: Registering the id_resolver key type [ 1.240207] Key type id_resolver registered [ 1.242046] Key type id_legacy registered [ 1.243897] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 1.245717] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering... [ 1.248680] Key type asymmetric registered [ 1.250526] Asymmetric key parser 'x509' registered [ 1.252372] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249) [ 1.254493] io scheduler mq-deadline registered [ 1.256316] io scheduler kyber registered [ 1.262188] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges: [ 1.264065] brcm-pcie fd500000.pcie: No bus range found for /scb/pcie@7d500000, using [bus 00-ff] [ 1.265998] brcm-pcie fd500000.pcie: MEM 0x0600000000..0x063fffffff -> 0x00c0000000 [ 1.267904] brcm-pcie fd500000.pcie: IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000 [ 1.319411] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC) [ 1.321574] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00 [ 1.323328] pci_bus 0000:00: root bus resource [bus 00-ff] [ 1.325060] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff]) [ 1.326979] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400 [ 1.328970] pci 0000:00:00.0: PME# supported from D0 D3hot [ 1.334851] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330 [ 1.336660] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit] [ 1.338785] pci 0000:01:00.0: PME# supported from D0 D3cold [ 1.344345] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff] [ 1.346024] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit] [ 1.347685] pci 0000:00:00.0: PCI bridge to [bus 01] [ 1.349309] pci 0000:00:00.0: bridge window [mem 0x600000000-0x6000fffff] [ 1.356656] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled [ 1.361125] iproc-rng200 fe104000.rng: hwrng registered [ 1.363205] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB) [ 1.365823] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000 [ 1.367964] cacheinfo: Unable to detect cache hierarchy for CPU 0 [ 1.380967] brd: module loaded [ 1.395070] loop: module loaded [ 1.398854] Loading iSCSI transport class v2.0-870. [ 1.403701] libphy: Fixed MDIO Bus: probed [ 1.407016] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000 [ 1.421343] libphy: bcmgenet MII bus: probed [ 1.469478] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus [ 1.472291] usbcore: registered new interface driver r8152 [ 1.474094] usbcore: registered new interface driver lan78xx [ 1.475818] usbcore: registered new interface driver smsc95xx [ 1.479161] pci 0000:00:00.0: enabling device (0000 -> 0002) [ 1.480848] xhci_hcd 0000:01:00.0: enabling device (0000 -> 0002) [ 1.482641] xhci_hcd 0000:01:00.0: xHCI Host Controller [ 1.484289] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1 [ 1.486740] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000060000000890 [ 1.489697] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10 [ 1.491371] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 1.493044] usb usb1: Product: xHCI Host Controller [ 1.494713] usb usb1: Manufacturer: Linux 5.10.52-v8+ xhci-hcd [ 1.496356] usb usb1: SerialNumber: 0000:01:00.0 [ 1.498684] hub 1-0:1.0: USB hub found [ 1.500404] hub 1-0:1.0: 1 port detected [ 1.502696] xhci_hcd 0000:01:00.0: xHCI Host Controller [ 1.504336] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2 [ 1.505999] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed [ 1.508026] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10 [ 1.509711] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 1.511329] usb usb2: Product: xHCI Host Controller [ 1.512938] usb usb2: Manufacturer: Linux 5.10.52-v8+ xhci-hcd [ 1.514591] usb usb2: SerialNumber: 0000:01:00.0 [ 1.516859] hub 2-0:1.0: USB hub found [ 1.518599] hub 2-0:1.0: 4 ports detected [ 1.521810] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) [ 1.523698] dwc_otg: FIQ enabled [ 1.523709] dwc_otg: NAK holdoff enabled [ 1.523720] dwc_otg: FIQ split-transaction FSM enabled [ 1.523733] Module dwc_common_port init [ 1.524282] usbcore: registered new interface driver uas [ 1.526230] usbcore: registered new interface driver usb-storage [ 1.528023] mousedev: PS/2 mouse device common for all mice [ 1.531598] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer [ 1.536385] sdhci: Secure Digital Host Controller Interface driver [ 1.538030] sdhci: Copyright(c) Pierre Ossman [ 1.540108] sdhci-pltfm: SDHCI platform and OF driver helper [ 1.545908] ledtrig-cpu: registered to indicate activity on CPUs [ 1.547831] hid: raw HID events driver (C) Jiri Kosina [ 1.549634] usbcore: registered new interface driver usbhid [ 1.551187] usbhid: USB HID core driver [ 1.553053] ashmem: initialized [ 1.563055] Initializing XFRM netlink socket [ 1.564647] NET: Registered protocol family 17 [ 1.566306] Key type dns_resolver registered [ 1.568527] registered taskstats version 1 [ 1.570107] Loading compiled-in X.509 certificates [ 1.572134] Key type ._fscrypt registered [ 1.573690] Key type .fscrypt registered [ 1.575190] Key type fscrypt-provisioning registered [ 1.587788] uart-pl011 fe201000.serial: there is not valid maps for state default [ 1.589609] uart-pl011 fe201000.serial: cts_event_workaround enabled [ 1.591201] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 21, base_baud = 0) is a PL011 rev2 [ 1.599625] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver [ 1.604200] of_cfs_init [ 1.605892] of_cfs_init: OK [ 1.640138] mmc0: SDHCI controller on fe340000.emmc2 [fe340000.emmc2] using ADMA [ 1.642425] Waiting for root device PARTUUID=94644f4c-04... [ 1.673596] usb 2-1: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd [ 1.694301] usb 2-1: LPM exit latency is zeroed, disabling LPM. [ 1.697082] usb 2-1: New USB device found, idVendor=0fd9, idProduct=0066, bcdDevice= 0.00 [ 1.698750] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=4 [ 1.700361] usb 2-1: Product: Cam Link 4K [ 1.701968] usb 2-1: Manufacturer: Elgato [ 1.703525] usb 2-1: SerialNumber: 000547D758000 [ 1.724927] hid-generic 0003:0FD9:0066.0001: hiddev96,hidraw0: USB HID v1.01 Device [Elgato Cam Link 4K] on usb-0000:01:00.0-1/input2 [ 1.754766] mmc0: new ultra high speed DDR50 SDHC card at address 0001 [ 1.757486] mmcblk0: mmc0:0001 JB1RT 29.8 GiB [ 1.761633] mmcblk0: p1 p2 p3 p4 [ 1.782244] EXT4-fs (mmcblk0p4): mounted filesystem with ordered data mode. Opts: (null) [ 1.784121] VFS: Mounted root (ext4 filesystem) readonly on device 179:4. [ 1.791442] devtmpfs: mounted [ 1.802895] Freeing unused kernel memory: 3776K [ 1.804840] Run /sbin/init as init process [ 1.806594] with arguments: [ 1.806605] /sbin/init [ 1.806614] with environment: [ 1.806624] HOME=/ [ 1.806634] TERM=linux [ 1.821371] usb 1-1: new high-speed USB device number 2 using xhci_hcd [ 1.975963] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21 [ 1.977919] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0 [ 1.979694] usb 1-1: Product: USB2.0 Hub [ 1.983243] hub 1-1:1.0: USB hub found [ 1.985269] hub 1-1:1.0: 4 ports detected [ 2.229680] systemd[1]: System time before build time, advancing clock. [ 2.281405] usb 1-1.4: new full-speed USB device number 3 using xhci_hcd [ 2.314128] NET: Registered protocol family 10 [ 2.317734] Segment Routing with IPv6 [ 2.374160] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid) [ 2.378951] systemd[1]: Detected architecture arm64. [ 2.418657] systemd[1]: Set hostname to . [ 2.426752] usb 1-1.4: New USB device found, idVendor=08bb, idProduct=2902, bcdDevice= 1.00 [ 2.428878] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0 [ 2.428890] usb 1-1.4: Product: USB Audio CODEC [ 2.428903] usb 1-1.4: Manufacturer: Burr-Brown from TI
[ 2.442781] input: Burr-Brown from TI USB Audio CODEC as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4/1-1.4:1.3/0003:08BB:2902.0002/input/input0 [ 2.505894] hid-generic 0003:08BB:2902.0002: input,hidraw1: USB HID v1.00 Device [Burr-Brown from TI USB Audio CODEC ] on usb-0000:01:00.0-1.4/input3 [ 2.983940] random: systemd: uninitialized urandom read (16 bytes read) [ 2.993794] random: systemd: uninitialized urandom read (16 bytes read) [ 2.996829] systemd[1]: Listening on Syslog Socket. [ 3.002011] random: systemd: uninitialized urandom read (16 bytes read) [ 3.004904] systemd[1]: Listening on fsck to fsckd communication Socket. [ 3.010840] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point. [ 3.016153] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ 3.024173] systemd[1]: Created slice system-systemd\x2dfsck.slice. [ 3.029507] systemd[1]: Listening on initctl Compatibility Named Pipe. [ 3.039888] systemd[1]: Listening on udev Control Socket. [ 3.214263] cryptd: max_cpu_qlen set to 1000 [ 3.398708] i2c /dev entries driver [ 3.722107] EXT4-fs (mmcblk0p4): re-mounted. Opts: (null) [ 3.786949] systemd-journald[131]: Received request to flush runtime journal from PID 1 [ 4.324264] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000 [ 4.325186] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000 [ 4.326167] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000 [ 4.326697] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000 [ 4.399784] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. [ 4.402132] bcm2835_vc_sm_cma_probe: Videocore shared memory driver

[ 4.405141] mc: Linux media interface: v0.10 [ 4.433483] [vc_sm_connected_init]: installed successfully [ 4.658464] videodev: Linux video capture interface: v2.00 [ 4.830493] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. [ 4.831815] i2c i2c-22: Added multiplexed i2c bus 0 [ 4.836865] i2c i2c-22: Added multiplexed i2c bus 10 [ 4.838629] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. [ 4.838779] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. [ 4.846519] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. [ 4.867460] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0 [ 4.880590] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. [ 4.889124] uvcvideo: Found UVC 1.10 device Cam Link 4K (0fd9:0066) [ 4.903535] bcm2835_audio bcm2835_audio: card created with 4 channels [ 4.910768] uvcvideo 2-1:1.0: Entity type for entity Input 1 was not initialized! [ 4.911286] input: Cam Link 4K: Cam Link 4K as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb2/2-1/2-1:1.0/input/input1 [ 4.911847] usbcore: registered new interface driver uvcvideo [ 4.911915] USB Video Class driver (1.1.1) [ 4.924259] bcm2835_audio bcm2835_audio: card created with 4 channels [ 5.072713] checking generic (3e843000 384000) vs hw (0 ffffffffffffffff) [ 5.072737] fb0: switching to vc4drmfb from simple [ 5.074982] Console: switching to colour dummy device 80x25 [ 5.083193] vc4-drm gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4]) [ 5.090859] [drm] Initialized vc4 0.0.0 20140616 for gpu on minor 1 [ 5.152683] vc4-drm gpu: [drm] HDMI-A-1: EDID is invalid: [ 5.152712] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152724] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152735] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152746] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152756] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152766] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152777] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.152787] [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 [ 5.263148] usbcore: registered new interface driver snd-usb-audio [ 5.298468] Console: switching to colour frame buffer device 160x45 [ 5.323502] vc4-drm gpu: [drm] fb0: vc4drmfb frame buffer device [ 5.499490] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 [ 5.500255] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 [ 5.500365] bcm2835-codec bcm2835-codec: Device registered as /dev/video10 [ 5.500421] bcm2835-codec bcm2835-codec: Loaded V4L2 decode [ 5.500740] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 [ 5.502253] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 [ 5.502287] bcm2835-isp bcm2835-isp: Register output node 0 with media controller [ 5.502310] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller [ 5.502327] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller [ 5.502343] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller [ 5.502587] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp [ 5.505615] bcm2835-codec bcm2835-codec: Device registered as /dev/video11 [ 5.505670] bcm2835-codec bcm2835-codec: Loaded V4L2 encode [ 5.510902] bcm2835-codec bcm2835-codec: Device registered as /dev/video12 [ 5.510950] bcm2835-codec bcm2835-codec: Loaded V4L2 isp [ 7.175661] random: crng init done [ 7.175680] random: 7 urandom warning(s) missed due to ratelimiting [ 7.525411] Adding 102396k swap on /var/swap. Priority:-2 extents:1 across:102396k SSFS [ 7.618683] 8021q: 802.1Q VLAN Support v1.8 [ 7.842968] cfg80211: Loading compiled-in X.509 certificates for regulatory database [ 7.864120] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' [ 8.013058] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) [ 8.014328] bcmgenet fd580000.ethernet eth0: Link is Down [ 10.789710] broken atomic modeset userspace detected, disabling atomic [ 11.069553] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx [ 11.069619] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 20.681578] sctp: Hash tables configured (bind 256/256) [ 20.960039] NET: Registered protocol family 15 [ 21.298438] NET: Registered protocol family 38 [72928.976828] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 6 outstanding [72928.977010] ------------[ cut here ]------------ [72928.977031] WARNING: CPU: 1 PID: 635 at drivers/media/common/videobuf2/videobuf2-core.c:1945 vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [72928.977034] Modules linked in: tcp_diag inet_diag jitterentropy_rng drbg authenc echainiv cast5_generic cast_common ctr algif_skcipher xcbc md4 algif_hash af_alg xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key md5 sctp cfg80211 rfkill 8021q garp stp llc spidev vc4 cec snd_usb_audio drm_kms_helper bcm2835_codec(C) snd_hwdep uvcvideo nft_nat snd_usbmidi_lib bcm2835_v4l2(C) snd_soc_core bcm2835_isp(C) snd_bcm2835(C) v4l2_mem2mem snd_rawmidi bcm2835_mmal_vchiq(C) videobuf2_vmalloc v3d snd_seq_device videobuf2_dma_contig snd_compress videobuf2_memops snd_pcm_dmaengine gpu_sched videobuf2_v4l2 snd_pcm i2c_mux_pinctrl videobuf2_common drm snd_timer raspberrypi_hwmon i2c_mux drm_panel_orientation_quirks videodev snd mc vc_sm_cma(C) syscopyarea sysfillrect sysimgblt fb_sys_fops i2c_bcm2835 backlight spi_bcm2835 rpivid_mem uio_pdrv_genirq uio nvmem_rmem nft_chain_nat nf_nat nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables i2c_dev aes_neon_bs nfnetlink sha256_generic [72928.977212] aes_neon_blk crypto_simd cryptd ip_tables x_tables ipv6 [72928.977231] CPU: 1 PID: 635 Comm: python3 Tainted: G C 5.10.52-v8+ #1441 [72928.977234] Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT) [72928.977239] pstate: 20000005 (nzCv daif -PAN -UAO -TCO BTYPE=--) [72928.977247] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [72928.977255] lr : vb2_queue_cancel+0x3c/0x220 [videobuf2_common] [72928.977257] sp : ffffffc011e5bb10 [72928.977260] x29: ffffffc011e5bb10 x28: ffffffc008cffed0 [72928.977267] x27: ffffff8067feec00 x26: 0000000000000000 [72928.977273] x25: ffffff8045e04628 x24: 0000000040045613 [72928.977280] x23: 0000000000000000 x22: ffffffc011298948 [72928.977286] x21: ffffff8067e4d028 x20: ffffff8067e4d028 [72928.977292] x19: ffffff8067e4d028 x18: 0000000000000004 [72928.977297] x17: 0000000000000000 x16: 0000000000000000 [72928.977303] x15: ffffff8046d40030 x14: ffffff807094e4c8 [72928.977309] x13: 0000000000000000 x12: 0000000000000000 [72928.977315] x11: ffffff807094e480 x10: ffffff8046d40038 [72928.977321] x9 : ffffffc008e9b5c4 x8 : ffffff807094e4a8 [72928.977327] x7 : 0000000000000000 x6 : 0000000000000000 [72928.977333] x5 : ffffff8045e0581c x4 : ffffff8047c33c80 [72928.977339] x3 : ffffff8046d40008 x2 : 0000000000000002 [72928.977345] x1 : 0000000000000000 x0 : 0000000000000006 [72928.977351] Call trace: [72928.977359] vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [72928.977367] vb2_core_streamoff+0x2c/0xc8 [videobuf2_common] [72928.977374] vb2_streamoff+0x24/0x78 [videobuf2_v4l2] [72928.977383] v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem] [72928.977389] v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem] [72928.977420] v4l_streamoff+0x2c/0x38 [videodev] [72928.977438] video_do_ioctl+0x18c/0x3f0 [videodev] [72928.977455] video_usercopy+0x154/0x618 [videodev] [72928.977472] video_ioctl2+0x20/0x68 [videodev] [72928.977489] v4l2_ioctl+0x48/0x68 [videodev] [72928.977502] __arm64_sys_ioctl+0xb0/0xf0 [72928.977508] el0_svc_common.constprop.2+0xac/0x1d0 [72928.977511] do_el0_svc+0x2c/0x98 [72928.977518] el0_svc+0x20/0x30 [72928.977522] el0_sync_handler+0x90/0xb8 [72928.977526] el0_sync+0x180/0x1c0 [72928.977529] ---[ end trace 99602805edd4a357 ]--- [72928.977536] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000e9d463b1 in active state [72928.977546] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000bc603baf in active state [72928.977553] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000a8ce9d12 in active state [72928.977560] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000030fb2bf in active state [72928.977567] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000007821d1cf in active state [72928.977573] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000003f6a5f6d in active state [72932.144834] bcm2835_mmal_vchiq: timed out waiting for sync completion

Logs For dmesg output see above.

root@pi-gross-gerau:~ vcdbg log assert No messages available root@pi-gross-gerau:~ vcgencmd measure_clock arm frequency(48)=600169920 root@pi-gross-gerau:~ vcgencmd measure_volts core volt=0.8625V

Additional context Probably related to issue #4592 , but the underlying messages from vcdbg are different. Opening a new issue as suggested by @pelwell in in https://github.com/raspberrypi/linux/issues/4592#issuecomment-926433347

hailfinger commented 2 years ago

One other host (pi-remscheid) has slightly different dmesg (no timeout) and additional messages in vcdbg msg (those "venc: venc_rc: frame 179001 aborted bits" messages are probably from an earlier run with v4l2h2264enc). Should I open a separate issue for that one or should I paste raspinfo here as a comment?

6by9 commented 2 years ago

Please update to 5.10.63 using rpi-update or building your own kernel.

4593 included a load of updates around the stateful encoder and decoder, in particular around "pool exhausted, recyling bust," and the WARN from not returning all the buffers.

hailfinger commented 2 years ago

Absolutely, will do. Thanks! Some of my machines exhibit issues (H264 encoder using 1/4 of specified bitrate) in 64bit mode if kernel+firmware is on the Aug 31 release. Will open a separate bug report for that.

hailfinger commented 2 years ago

@6by9 It seems the problem got worse with 5.10.63 which seems to include #4593: Same problem on another machine, this one has latest rpi-update on it:

root@pi-bonn-mitte:~# uname -r 5.10.63-v8+

root@pi-bonn-mitte:~# vcdbg log msg
005741.484: arasan: arasan_emmc_open 005892.008: brfs: File read: /mfs/sd/tryboot.txt 005892.925: brfs: File read: 1981 bytes 006010.941: HDMI1:EDID error reading EDID block 0 attempt 0 006016.967: HDMI1:EDID error reading EDID block 0 attempt 1 006022.990: HDMI1:EDID error reading EDID block 0 attempt 2 006029.015: HDMI1:EDID error reading EDID block 0 attempt 3 006035.037: HDMI1:EDID error reading EDID block 0 attempt 4 006041.061: HDMI1:EDID error reading EDID block 0 attempt 5 006047.084: HDMI1:EDID error reading EDID block 0 attempt 6 006053.109: HDMI1:EDID error reading EDID block 0 attempt 7 006059.132: HDMI1:EDID error reading EDID block 0 attempt 8 006065.156: HDMI1:EDID error reading EDID block 0 attempt 9 006066.170: HDMI1:EDID giving up on reading EDID block 0 006068.246: brfs: File read: /mfs/sd/tryboot.txt 007350.680: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined 007353.188: *** Restart logging 007353.209: brfs: File read: 1981 bytes 007417.104: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0 007423.132: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1 007429.157: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2 007441.516: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3 007447.568: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4 007453.621: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5 007459.673: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6 007465.726: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7 007471.776: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8 007477.831: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9 007478.866: hdmi: HDMI1:EDID giving up on reading EDID block 0 007483.962: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0 007490.015: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1 007496.067: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2 007502.121: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3 007508.173: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4 007514.227: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5 007520.278: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6 007526.331: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7 007532.382: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8 007538.436: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9 007539.470: hdmi: HDMI1:EDID giving up on reading EDID block 0 007539.509: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 007539.540: HDMI0: hdmi_pixel_encoding: 300000000 007539.564: HDMI1: hdmi_pixel_encoding: 300000000 007545.234: dtb_file 'bcm2711-rpi-4-b.dtb' 007556.677: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb 007556.708: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xc2a9 007587.906: brfs: File read: 49833 bytes 007603.118: brfs: File read: /mfs/sd/overlays/overlay_map.dtb 007761.047: brfs: File read: 1667 bytes 007764.877: brfs: File read: /mfs/sd/tryboot.txt 007765.596: dtparam: i2c_arm=on 007786.656: dtparam: i2c_vc=on 007819.126: dtparam: spi=on 007838.706: dtparam: audio=on 007863.442: brfs: File read: 1981 bytes 007881.345: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d-pi4.dtbo 007923.918: Loaded overlay 'vc4-fkms-v3d' 008009.181: brfs: File read: 1446 bytes 008015.545: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo 008050.786: Loaded overlay 'disable-bt' 008130.506: brfs: File read: 1073 bytes 008135.973: brfs: File read: /mfs/sd/overlays/disable-wifi.dtbo 008156.796: Loaded overlay 'disable-wifi' 008216.241: brfs: File read: 387 bytes 008217.701: brfs: File read: /mfs/sd/cmdline.txt 008217.761: Read command line from file 'cmdline.txt': 008217.783: 'console=tty1 root=PARTUUID=84c6ba5d-04 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait' 008510.391: brfs: File read: 98 bytes 010101.815: brfs: File read: /mfs/sd/kernel8.img 010101.850: Loading 'kernel8.img' to 0x80000 size 0x78a5af 012769.593: Kernel relocated to 0x200000 012769.618: Device tree loaded to 0x2eff3700 (size 0xc896) 012776.725: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined 014843.494: vchiq_core: vchiq_init_state: slot_zero = 0xdb000000, is_master = 1 014846.766: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead 014854.207: TV service:host side not connected, dropping notification 0x00000002, 0x00000001, 0x00000013 017923.694: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018224.326: camsubs: Camera not found 018224.489: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133 018429.755: TV service:host side not connected, dropping notification 0x00000008, 0x00000004, 0x00000000 018525.124: camsubs: Camera found OK 025067.419: TV service:host side not connected, dropping notification 0x00000008, 0x00000004, 0x00000000 101960.511: video_decode:10:RIL: nothing changing 162680.306: video_decode:11:RIL: nothing changing 576605.505: video_decode:12:RIL: nothing changing 2198403.262: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198403.284: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2198443.262: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198443.283: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2198483.580: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198483.598: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2198523.261: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198523.283: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2198563.252: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198563.272: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined) 2198603.258: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2 2198603.280: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)

Last lines of dmesg: [ 2515.034195] ------------[ cut here ]------------ [ 2515.034222] WARNING: CPU: 0 PID: 637 at drivers/media/common/videobuf2/videobuf2-core.c:1956 vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [ 2515.034226] Modules linked in: tcp_diag inet_diag jitterentropy_rng drbg authenc echainiv cast5_generic cast_common ctr algif_skcipher xcbc md4 algif_hash af_alg xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key md5 sctp cfg80211 rfkill 8021q garp stp llc spidev vc4 snd_usb_audio cec snd_hwdep snd_usbmidi_lib drm_kms_helper snd_rawmidi snd_seq_device nft_nat v3d gpu_sched bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem drm videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 i2c_mux_pinctrl drm_panel_orientation_quirks videobuf2_common i2c_bcm2835 raspberrypi_hwmon vc_sm_cma(C) spi_bcm2835 i2c_mux videodev snd_bcm2835(C) snd_soc_core mc snd_compress snd_pcm_dmaengine snd_pcm snd_timer snd rpivid_mem syscopyarea sysfillrect sysimgblt fb_sys_fops backlight nvmem_rmem uio_pdrv_genirq uio nft_chain_nat nf_nat nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables nfnetlink i2c_dev aes_neon_bs sha256_generic [ 2515.034413] aes_neon_blk crypto_simd cryptd ip_tables x_tables ipv6 [ 2515.034433] CPU: 0 PID: 637 Comm: python3 Tainted: G C 5.10.63-v8+ #1457 [ 2515.034436] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT) [ 2515.034441] pstate: 20000005 (nzCv daif -PAN -UAO -TCO BTYPE=--) [ 2515.034449] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [ 2515.034456] lr : vb2_queue_cancel+0x3c/0x220 [videobuf2_common] [ 2515.034459] sp : ffffffc011f33b10 [ 2515.034462] x29: ffffffc011f33b10 x28: ffffffc008d85ed0 [ 2515.034469] x27: ffffff804339dc00 x26: 0000000000000000 [ 2515.034476] x25: ffffff80464cd630 x24: 0000000040045613 [ 2515.034483] x23: 0000000000000000 x22: ffffffc011288948 [ 2515.034490] x21: ffffff80712f4028 x20: ffffff80712f4028 [ 2515.034496] x19: ffffff80712f4028 x18: 0000000000000004 [ 2515.034503] x17: 0000000000000000 x16: 0000000000000000 [ 2515.034509] x15: ffffff8046740030 x14: ffffff80704f0290 [ 2515.034515] x13: 0000000000000000 x12: 0000000000000000 [ 2515.034521] x11: ffffff80704f0248 x10: ffffff8046740038 [ 2515.034528] x9 : ffffffc008dfd99c x8 : ffffff80704f0270 [ 2515.034534] x7 : 0000000000000000 x6 : 0000000000000000 [ 2515.034541] x5 : ffffff80464cd81c x4 : ffffff80470b0000 [ 2515.034547] x3 : ffffff8046740008 x2 : 0000000000000002 [ 2515.034554] x1 : 0000000000000000 x0 : 0000000000000006 [ 2515.034561] Call trace: [ 2515.034569] vb2_queue_cancel+0x1b8/0x220 [videobuf2_common] [ 2515.034576] vb2_core_streamoff+0x2c/0xc8 [videobuf2_common] [ 2515.034584] vb2_streamoff+0x24/0x78 [videobuf2_v4l2] [ 2515.034593] v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem] [ 2515.034600] v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem] [ 2515.034636] v4l_streamoff+0x2c/0x38 [videodev] [ 2515.034654] video_do_ioctl+0x18c/0x3f0 [videodev] [ 2515.034671] video_usercopy+0x154/0x618 [videodev] [ 2515.034687] video_ioctl2+0x20/0x68 [videodev] [ 2515.034704] v4l2_ioctl+0x48/0x68 [videodev] [ 2515.034716] __arm64_sys_ioctl+0xb0/0xf0 [ 2515.034723] el0_svc_common.constprop.3+0xc0/0x1f8 [ 2515.034727] do_el0_svc+0x2c/0x98 [ 2515.034734] el0_svc+0x20/0x30 [ 2515.034738] el0_sync_handler+0x90/0xb8 [ 2515.034742] el0_sync+0x180/0x1c0 [ 2515.034746] ---[ end trace 44e13d342cddce51 ]--- [ 2515.034752] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000be504ef6 in active state [ 2515.034759] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000001199f83b in active state [ 2515.034766] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000008b9a66d9 in active state [ 2515.034772] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000c45762a3 in active state [ 2515.034779] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000a3de1d4b in active state [ 2515.034786] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000f15a4c37 in active state

hailfinger commented 2 years ago

I'm now getting this problem on 60+ devices in my fleet, so it's not an isolated problem anymore. I guess decoding a multi-hour stream, stopping it and decoding a second multi-hour stream is sufficient to trigger it even on multiple devices which survived the first test. Latest rpi-update doesn't help, unfortunately. That said, over_voltage=2 helps in most cases.

hailfinger commented 2 years ago

@pelwell @6by9 The stateful v4l2 decode update from #4593 didn't help. Anything else I can try?

rafhtl commented 2 years ago

Same problem here over_voltage=2 does not help

hailfinger commented 2 years ago

@6by9 even with latest rpi-eeprom-update, the issue persists. The higher over_voltage is set, the longer the issue takes to manifest. The log below is without over_voltage to make the issue easier to trigger.

4593 unfortunately had no positive effect.

root@pi-dortmund-eving:~# vcgencmd version
Oct 19 2021 11:50:40 
Copyright (c) 2012 Broadcom
version 0403e22018aafab833d0a16374ac773f66fd7be9 (clean) (release) (start_db)
root@pi-dortmund-eving:~# uname -r
5.10.74-v8+
root@pi-dortmund-eving:~# vcdbg log assert
2288365.797: assert( vd3_mbloop_end_decode_picture DEC_MAINCTL failed to go idle ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::ResetBackendHW line 129 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2289183.631: assert( loopCount < MAX_HW_IDLE_LOOP_COUNT ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::H264_WaitForIdleHW line 741 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2289286.003: assert( vd3_mbloop_end_decode_picture DEC_MAINCTL failed to go idle ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::ResetBackendHW line 129 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2289804.506: assert( loopCount < MAX_HW_IDLE_LOOP_COUNT ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::H264_WaitForIdleHW line 741 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2289906.888: assert( vd3_mbloop_end_decode_picture DEC_MAINCTL failed to go idle ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::ResetBackendHW line 129 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2290447.805: assert( loopCount < MAX_HW_IDLE_LOOP_COUNT ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::H264_WaitForIdleHW line 741 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2290550.170: assert( vd3_mbloop_end_decode_picture DEC_MAINCTL failed to go idle ) failed; ../../../../../codecs/video/hw/dec3/h264/h264_inner_slice.c::ResetBackendHW line 129 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2291171.267: assert( (status & 0x3f0000) == 0 ) failed; ../../../../../codecs/video/hw/dec3/vd3/vd3_mbloop_fns.c::vd3_mbloop_wait_for_backend line 107 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2291171.353: assert( 0xa00 == ( VCD_REG_RD(INST, DEC_STATUS ) & 0xa00 ) ) failed; ../../../../../codecs/video/hw/dec3/vd3/vd3_mbloop_fns.c::vd3_mbloop_wait_for_backend line 136 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2291273.723: assert( vd3_mbloop_end_decode_picture DEC_MAINCTL failed to go idle ) failed; ../../../../../codecs/video/hw/dec3/vd3/vd3_mbloop.c::vd3_mbloop_end_decode_picture line 1165 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2291273.785: assert( 0 ) failed; ../../../../../vcfw/drivers/chip/vciv/2708/h264pwr.c::h264pwr_disable_lowlevel line 530 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------
2291273.857: assert( 0 ) failed; ../../../../../vcfw/drivers/chip/vciv/2708/h264pwr.c::h264pwr_disable_lowlevel line 555 rev 0403e22
vcdbg_ctx_get_dump_stack: dump_stack failed
----------------

root@pi-dortmund-eving:~# vcdbg log msg
006162.996: arasan: arasan_emmc_open
006604.014: brfs: File read: /mfs/sd/tryboot.txt
006604.998: brfs: File read: 1993 bytes
006656.032: HDMI0:EDID error reading EDID block 0 attempt 0
006662.058: HDMI0:EDID error reading EDID block 0 attempt 1
006668.081: HDMI0:EDID error reading EDID block 0 attempt 2
006674.106: HDMI0:EDID error reading EDID block 0 attempt 3
006680.128: HDMI0:EDID error reading EDID block 0 attempt 4
006686.153: HDMI0:EDID error reading EDID block 0 attempt 5
006692.176: HDMI0:EDID error reading EDID block 0 attempt 6
006698.200: HDMI0:EDID error reading EDID block 0 attempt 7
006704.222: HDMI0:EDID error reading EDID block 0 attempt 8
006710.247: HDMI0:EDID error reading EDID block 0 attempt 9
006711.261: HDMI0:EDID giving up on reading EDID block 0
006731.917: HDMI1:EDID error reading EDID block 0 attempt 0
006737.942: HDMI1:EDID error reading EDID block 0 attempt 1
006743.964: HDMI1:EDID error reading EDID block 0 attempt 2
006749.989: HDMI1:EDID error reading EDID block 0 attempt 3
006756.012: HDMI1:EDID error reading EDID block 0 attempt 4
006762.036: HDMI1:EDID error reading EDID block 0 attempt 5
006768.058: HDMI1:EDID error reading EDID block 0 attempt 6
006774.083: HDMI1:EDID error reading EDID block 0 attempt 7
006780.106: HDMI1:EDID error reading EDID block 0 attempt 8
006786.131: HDMI1:EDID error reading EDID block 0 attempt 9
006787.144: HDMI1:EDID giving up on reading EDID block 0
006788.917: brfs: File read: /mfs/sd/tryboot.txt
007863.419: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
007866.048: *** Restart logging
007866.069: brfs: File read: 1993 bytes
007871.556: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
007877.583: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
007883.607: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
007889.633: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
007895.658: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
007901.686: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
007907.710: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
007913.737: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
007919.762: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
007925.789: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
007926.804: hdmi: HDMI0:EDID giving up on reading EDID block 0
007931.850: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
007937.877: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
007943.901: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
007949.928: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
007955.953: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
007961.980: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
007968.004: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
007974.031: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
007980.056: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
007986.083: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
007987.098: hdmi: HDMI0:EDID giving up on reading EDID block 0
007998.685: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
008004.712: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1
008010.736: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2
008018.440: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3
008028.518: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4
008034.574: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5
008040.625: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6
008046.680: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7
008052.732: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8
008058.788: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9
008059.822: hdmi: HDMI1:EDID giving up on reading EDID block 0
008064.919: hdmi: HDMI1:EDID error reading EDID block 0 attempt 0
008070.972: hdmi: HDMI1:EDID error reading EDID block 0 attempt 1
008077.025: hdmi: HDMI1:EDID error reading EDID block 0 attempt 2
008083.079: hdmi: HDMI1:EDID error reading EDID block 0 attempt 3
008089.132: hdmi: HDMI1:EDID error reading EDID block 0 attempt 4
008095.186: hdmi: HDMI1:EDID error reading EDID block 0 attempt 5
008101.238: hdmi: HDMI1:EDID error reading EDID block 0 attempt 6
008107.292: hdmi: HDMI1:EDID error reading EDID block 0 attempt 7
008113.345: hdmi: HDMI1:EDID error reading EDID block 0 attempt 8
008119.400: hdmi: HDMI1:EDID error reading EDID block 0 attempt 9
008120.432: hdmi: HDMI1:EDID giving up on reading EDID block 0
008120.472: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
008120.503: HDMI0: hdmi_pixel_encoding: 300000000
008120.529: HDMI1: hdmi_pixel_encoding: 300000000
008126.288: dtb_file 'bcm2711-rpi-4-b.dtb'
008137.388: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
008137.420: Loading 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xc2a5
008169.406: brfs: File read: 49829 bytes
008185.002: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
008349.683: brfs: File read: 1667 bytes
008353.186: brfs: File read: /mfs/sd/tryboot.txt
008353.938: dtparam: i2c_arm=on
008375.408: dtparam: i2c_vc=on
008408.572: dtparam: spi=on
008428.538: dtparam: audio=on
008453.993: brfs: File read: 1993 bytes
008471.771: brfs: File read: /mfs/sd/overlays/vc4-fkms-v3d-pi4.dtbo
008515.169: Loaded overlay 'vc4-fkms-v3d'
008602.161: brfs: File read: 1446 bytes
008608.598: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
008644.320: Loaded overlay 'disable-bt'
008725.368: brfs: File read: 1073 bytes
008730.810: brfs: File read: /mfs/sd/overlays/disable-wifi.dtbo
008752.212: Loaded overlay 'disable-wifi'
008813.366: brfs: File read: 387 bytes
008815.079: brfs: File read: /mfs/sd/cmdline.txt
008815.136: Read command line from file 'cmdline.txt':
008815.157: 'console=tty1 root=PARTUUID=00ac1390-04 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait'
009112.227: brfs: File read: 98 bytes
010675.416: brfs: File read: /mfs/sd/kernel8.img
010675.454: Loading 'kernel8.img' to 0x80000 size 0x78b193
013356.834: Kernel relocated to 0x200000
013356.857: Device tree loaded to 0x2eff3700 (size 0xc8c6)
013386.619: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
015477.683: vchiq_core: vchiq_init_state: slot_zero = 0xdb000000, is_master = 1
015481.041: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
015488.632: TV service:host side not connected, dropping notification 0x00000002, 0x00000001, 0x00000013
018635.039: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
018796.115: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
018802.171: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
018808.224: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
018814.280: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
018820.332: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
018826.387: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
018832.440: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
018838.495: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
018844.547: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
018850.603: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
018851.638: hdmi: HDMI0:EDID giving up on reading EDID block 0
018935.780: camsubs: Camera not found
018935.951: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
018986.926: TV service:host side not connected, dropping notification 0x00000004, 0x00000004, 0x00000000
019236.687: camsubs: Camera not found
019236.853: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
019237.573: camsubs: Camera not found
019237.722: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
019238.444: camsubs: Camera not found
019238.595: camsubs: Looking for camera 0: i2c_port = 0, led gpio = -1, power enable gpio = 133
019238.807: camsubs: Camera not found
024207.919: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
024213.945: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
024219.972: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
024225.997: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
024232.026: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
024238.051: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
024244.078: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
024250.103: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
024256.130: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
024262.156: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
024263.175: hdmi: HDMI0:EDID giving up on reading EDID block 0
024268.844: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
024274.869: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
024280.897: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
024286.922: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
024292.949: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
024298.976: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
024305.005: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
024311.031: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
024317.058: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
024323.083: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
024324.101: hdmi: HDMI0:EDID giving up on reading EDID block 0
025323.051: TV service:host side not connected, dropping notification 0x00000004, 0x00000004, 0x00000000
028977.526: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
028983.553: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
028989.581: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
028995.606: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
029001.633: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
029007.660: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
029013.688: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
029019.713: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
029025.741: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
029031.767: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
029032.785: hdmi: HDMI0:EDID giving up on reading EDID block 0
029039.294: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
029045.320: hdmi: HDMI0:EDID error reading EDID block 0 attempt 1
029051.348: hdmi: HDMI0:EDID error reading EDID block 0 attempt 2
029057.373: hdmi: HDMI0:EDID error reading EDID block 0 attempt 3
029063.401: hdmi: HDMI0:EDID error reading EDID block 0 attempt 4
029069.426: hdmi: HDMI0:EDID error reading EDID block 0 attempt 5
029075.453: hdmi: HDMI0:EDID error reading EDID block 0 attempt 6
029081.478: hdmi: HDMI0:EDID error reading EDID block 0 attempt 7
029087.505: hdmi: HDMI0:EDID error reading EDID block 0 attempt 8
029093.532: hdmi: HDMI0:EDID error reading EDID block 0 attempt 9
029094.548: hdmi: HDMI0:EDID giving up on reading EDID block 0
3469065.499: video_decode:6:RIL: nothing changing
4283094.619: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
4283094.641: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
4283134.380: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
4283134.404: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
4283174.313: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
4283174.333: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
4283214.344: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
4283214.368: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
966545.343: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
966545.388: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
966555.445: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
966555.491: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
root@pi-dortmund-eving:~# dmesg
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.000000] Linux version 5.10.74-v8+ (dom@buildbot) (aarch64-linux-gnu-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1471 SMP PREEMPT Mon Oct 18 17:11:19 BST 2021
[    0.000000] random: fast init done
[    0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.1
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created CMA memory pool at 0x000000001ac00000, size 320 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000003fffffff]
[    0.000000]   DMA32    [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000002fffffff]
[    0.000000]   node   0: [mem 0x0000000040000000-0x00000000fbffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x00000000fbffffff]
[    0.000000] On node 0 totalpages: 966656
[    0.000000]   DMA zone: 3072 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 196608 pages, LIFO batch:63
[    0.000000]   DMA32 zone: 12032 pages used for memmap
[    0.000000]   DMA32 zone: 770048 pages, LIFO batch:63
[    0.000000] percpu: Embedded 32 pages/cpu s91416 r8192 d31464 u131072
[    0.000000] pcpu-alloc: s91416 r8192 d31464 u131072 alloc=32*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected PIPT I-cache on CPU0
[    0.000000] CPU features: detected: Spectre-v2
[    0.000000] CPU features: detected: Spectre-v4
[    0.000000] CPU features: detected: ARM errata 1165522, 1319367, or 1530923
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 951552
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=1 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 video=HDMI-A-1:1280x720M@50 smsc95xx.macaddr=DC:A6:32:48:BA:3F vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  console=tty1 root=PARTUUID=00ac1390-04 rootfstype=ext4 elevator=deadline fsck.repair=yes rootwait
[    0.000000] Kernel parameter elevator= does not have any effect anymore.
               Please use sysfs to set IO scheduler for individual devices.
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x0000000016c00000-0x000000001ac00000] (64MB)
[    0.000000] Memory: 3370752K/3866624K available (11136K kernel code, 1946K rwdata, 3988K rodata, 3712K init, 1253K bss, 168192K reserved, 327680K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 36775 entries in 144 pages
[    0.000000] ftrace: allocated 144 pages with 2 groups
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU event tracing is enabled.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000]  Trampoline variant of Tasks RCU enabled.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] random: get_random_bytes called from start_kernel+0x3b0/0x570 with crng_init=1
[    0.000000] arch_timer: cp15 timer(s) running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000007] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000252] Console: colour dummy device 80x25
[    0.000795] printk: console [tty1] enabled
[    0.000860] Calibrating delay loop (skipped), value calculated using timer frequency.. 108.00 BogoMIPS (lpj=216000)
[    0.000903] pid_max: default: 32768 minimum: 301
[    0.001058] LSM: Security Framework initializing
[    0.001301] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.001379] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.002692] cgroup: Disabling memory control group subsystem
[    0.005051] rcu: Hierarchical SRCU implementation.
[    0.006094] EFI services will not be available.
[    0.006619] smp: Bringing up secondary CPUs ...
[    0.007597] Detected PIPT I-cache on CPU1
[    0.007678] CPU1: Booted secondary processor 0x0000000001 [0x410fd083]
[    0.008837] Detected PIPT I-cache on CPU2
[    0.008886] CPU2: Booted secondary processor 0x0000000002 [0x410fd083]
[    0.009955] Detected PIPT I-cache on CPU3
[    0.010004] CPU3: Booted secondary processor 0x0000000003 [0x410fd083]
[    0.010155] smp: Brought up 1 node, 4 CPUs
[    0.010243] SMP: Total of 4 processors activated.
[    0.010267] CPU features: detected: 32-bit EL0 Support
[    0.010290] CPU features: detected: CRC32 instructions
[    0.010313] CPU features: detected: 32-bit EL1 Support
[    0.043378] CPU: All CPU(s) started at EL2
[    0.043464] alternatives: patching kernel code
[    0.045110] devtmpfs: initialized
[    0.055717] Enabled cp15_barrier support
[    0.055784] Enabled setend support
[    0.056004] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.056092] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.064725] pinctrl core: initialized pinctrl subsystem
[    0.065526] DMI not present or invalid.
[    0.065910] NET: Registered protocol family 16
[    0.069036] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[    0.069315] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.070242] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.070356] audit: initializing netlink subsys (disabled)
[    0.070746] audit: type=2000 audit(0.068:1): state=initialized audit_enabled=0 res=1
[    0.071227] thermal_sys: Registered thermal governor 'step_wise'
[    0.071684] cpuidle: using governor menu
[    0.072051] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.072257] ASID allocator initialised with 65536 entries
[    0.072402] Serial: AMBA PL011 UART driver
[    0.103461] bcm2835-mbox fe00b880.mailbox: mailbox enabled
[    0.112377] raspberrypi-firmware soc:firmware: Attached to firmware from 2021-10-19T11:50:40, variant start_db
[    0.116387] raspberrypi-firmware soc:firmware: Firmware hash is 0403e22018aafab833d0a16374ac773f66fd7be9
[    0.150490] bcm2835-dma fe007000.dma: DMA legacy API manager, dmachans=0x1
[    0.154334] vgaarb: loaded
[    0.154761] SCSI subsystem initialized
[    0.154978] usbcore: registered new interface driver usbfs
[    0.155044] usbcore: registered new interface driver hub
[    0.155128] usbcore: registered new device driver usb
[    0.155457] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.157341] clocksource: Switched to clocksource arch_sys_counter
[    1.188099] VFS: Disk quotas dquot_6.6.0
[    1.188218] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.188392] FS-Cache: Loaded
[    1.188642] CacheFiles: Loaded
[    1.189737] simple-framebuffer 3e843000.framebuffer: framebuffer at 0x3e843000, 0x384000 bytes, mapped to 0x(____ptrval____)
[    1.189772] simple-framebuffer 3e843000.framebuffer: format=a8r8g8b8, mode=1280x720x32, linelength=5120
[    1.195167] Console: switching to colour frame buffer device 160x45
[    1.199901] simple-framebuffer 3e843000.framebuffer: fb0: simplefb registered!
[    1.210293] NET: Registered protocol family 2
[    1.210900] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    1.214443] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[    1.214587] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    1.214891] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[    1.215484] TCP: Hash tables configured (established 32768 bind 32768)
[    1.215810] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    1.215955] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    1.216355] NET: Registered protocol family 1
[    1.217403] RPC: Registered named UNIX socket transport module.
[    1.217482] RPC: Registered udp transport module.
[    1.217541] RPC: Registered tcp transport module.
[    1.217600] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.217686] PCI: CLS 0 bytes, default 64
[    1.221886] hw perfevents: enabled with armv8_cortex_a72 PMU driver, 7 counters available
[    1.224074] kvm [1]: IPA Size Limit: 44 bits
[    1.227141] kvm [1]: vgic interrupt IRQ9
[    1.229266] kvm [1]: Hyp mode initialized successfully
[    1.233344] Initialise system trusted keyrings
[    1.235494] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    1.243649] zbud: loaded
[    1.247176] FS-Cache: Netfs 'nfs' registered for caching
[    1.249653] NFS: Registering the id_resolver key type
[    1.251439] Key type id_resolver registered
[    1.253199] Key type id_legacy registered
[    1.255066] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.256871] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    1.259846] Key type asymmetric registered
[    1.261693] Asymmetric key parser 'x509' registered
[    1.263536] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.265638] io scheduler mq-deadline registered
[    1.267455] io scheduler kyber registered
[    1.273403] brcm-pcie fd500000.pcie: host bridge /scb/pcie@7d500000 ranges:
[    1.275269] brcm-pcie fd500000.pcie:   No bus range found for /scb/pcie@7d500000, using [bus 00-ff]
[    1.277182] brcm-pcie fd500000.pcie:      MEM 0x0600000000..0x063fffffff -> 0x00c0000000
[    1.279106] brcm-pcie fd500000.pcie:   IB MEM 0x0000000000..0x00bfffffff -> 0x0400000000
[    1.331438] brcm-pcie fd500000.pcie: link up, 5.0 GT/s PCIe x1 (SSC)
[    1.333606] brcm-pcie fd500000.pcie: PCI host bridge to bus 0000:00
[    1.335353] pci_bus 0000:00: root bus resource [bus 00-ff]
[    1.337085] pci_bus 0000:00: root bus resource [mem 0x600000000-0x63fffffff] (bus address [0xc0000000-0xffffffff])
[    1.339006] pci 0000:00:00.0: [14e4:2711] type 01 class 0x060400
[    1.340986] pci 0000:00:00.0: PME# supported from D0 D3hot
[    1.346645] pci 0000:01:00.0: [1106:3483] type 00 class 0x0c0330
[    1.348450] pci 0000:01:00.0: reg 0x10: [mem 0x00000000-0x00000fff 64bit]
[    1.350578] pci 0000:01:00.0: PME# supported from D0 D3cold
[    1.364595] pci 0000:00:00.0: BAR 8: assigned [mem 0x600000000-0x6000fffff]
[    1.366294] pci 0000:01:00.0: BAR 0: assigned [mem 0x600000000-0x600000fff 64bit]
[    1.367955] pci 0000:00:00.0: PCI bridge to [bus 01]
[    1.369594] pci 0000:00:00.0:   bridge window [mem 0x600000000-0x6000fffff]
[    1.376870] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    1.381303] iproc-rng200 fe104000.rng: hwrng registered
[    1.383393] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.386413] gpiomem-bcm2835 fe200000.gpiomem: Initialised: Registers at 0xfe200000
[    1.388524] cacheinfo: Unable to detect cache hierarchy for CPU 0
[    1.401398] brd: module loaded
[    1.415300] loop: module loaded
[    1.418889] Loading iSCSI transport class v2.0-870.
[    1.423741] libphy: Fixed MDIO Bus: probed
[    1.427055] bcmgenet fd580000.ethernet: GENET 5.0 EPHY: 0x0000
[    1.441370] libphy: bcmgenet MII bus: probed
[    1.489481] unimac-mdio unimac-mdio.-19: Broadcom UniMAC MDIO bus
[    1.492301] usbcore: registered new interface driver r8152
[    1.494103] usbcore: registered new interface driver lan78xx
[    1.495821] usbcore: registered new interface driver smsc95xx
[    1.499137] pci 0000:00:00.0: enabling device (0000 -> 0002)
[    1.500827] xhci_hcd 0000:01:00.0: enabling device (0000 -> 0002)
[    1.502617] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.504270] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 1
[    1.506677] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000060000000890
[    1.509342] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    1.510986] xhci_hcd 0000:01:00.0: new USB bus registered, assigned bus number 2
[    1.512668] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    1.514682] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[    1.516350] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.518023] usb usb1: Product: xHCI Host Controller
[    1.519683] usb usb1: Manufacturer: Linux 5.10.74-v8+ xhci-hcd
[    1.521351] usb usb1: SerialNumber: 0000:01:00.0
[    1.523694] hub 1-0:1.0: USB hub found
[    1.525420] hub 1-0:1.0: 1 port detected
[    1.528022] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[    1.529676] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.531305] usb usb2: Product: xHCI Host Controller
[    1.532922] usb usb2: Manufacturer: Linux 5.10.74-v8+ xhci-hcd
[    1.534556] usb usb2: SerialNumber: 0000:01:00.0
[    1.536786] hub 2-0:1.0: USB hub found
[    1.538473] hub 2-0:1.0: 4 ports detected
[    1.541724] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    1.543612] dwc_otg: FIQ enabled
[    1.543622] dwc_otg: NAK holdoff enabled
[    1.543633] dwc_otg: FIQ split-transaction FSM enabled
[    1.543646] Module dwc_common_port init
[    1.544190] usbcore: registered new interface driver uas
[    1.545942] usbcore: registered new interface driver usb-storage
[    1.547716] mousedev: PS/2 mouse device common for all mice
[    1.551429] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    1.556144] sdhci: Secure Digital Host Controller Interface driver
[    1.557748] sdhci: Copyright(c) Pierre Ossman
[    1.559805] sdhci-pltfm: SDHCI platform and OF driver helper
[    1.564943] ledtrig-cpu: registered to indicate activity on CPUs
[    1.566860] hid: raw HID events driver (C) Jiri Kosina
[    1.568604] usbcore: registered new interface driver usbhid
[    1.570204] usbhid: USB HID core driver
[    1.572042] ashmem: initialized
[    1.581802] Initializing XFRM netlink socket
[    1.583399] NET: Registered protocol family 17
[    1.585024] Key type dns_resolver registered
[    1.587247] registered taskstats version 1
[    1.588822] Loading compiled-in X.509 certificates
[    1.590881] Key type ._fscrypt registered
[    1.592410] Key type .fscrypt registered
[    1.593959] Key type fscrypt-provisioning registered
[    1.606428] uart-pl011 fe201000.serial: there is not valid maps for state default
[    1.608231] uart-pl011 fe201000.serial: cts_event_workaround enabled
[    1.609908] fe201000.serial: ttyAMA0 at MMIO 0xfe201000 (irq = 21, base_baud = 0) is a PL011 rev2
[    1.618001] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    1.629905] of_cfs_init
[    1.631628] of_cfs_init: OK
[    1.658090] mmc0: SDHCI controller on fe340000.mmc [fe340000.mmc] using ADMA
[    1.660595] Waiting for root device PARTUUID=00ac1390-04...
[    1.758470] mmc0: new ultra high speed DDR50 SDHC card at address 0001
[    1.761029] mmcblk0: mmc0:0001 JB1RT 29.8 GiB
[    1.764637]  mmcblk0: p1 p2 p3 p4
[    1.782264] EXT4-fs (mmcblk0p4): mounted filesystem with ordered data mode. Opts: (null)
[    1.784003] VFS: Mounted root (ext4 filesystem) readonly on device 179:4.
[    1.785368] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[    1.791220] devtmpfs: mounted
[    1.802441] Freeing unused kernel memory: 3712K
[    1.805514] Run /sbin/init as init process
[    1.807131]   with arguments:
[    1.807142]     /sbin/init
[    1.807152]   with environment:
[    1.807162]     HOME=/
[    1.807172]     TERM=linux
[    1.936054] usb 1-1: New USB device found, idVendor=2109, idProduct=3431, bcdDevice= 4.21
[    1.937879] usb 1-1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    1.939584] usb 1-1: Product: USB2.0 Hub
[    1.943191] hub 1-1:1.0: USB hub found
[    1.945132] hub 1-1:1.0: 4 ports detected
[    2.229804] systemd[1]: System time before build time, advancing clock.
[    2.315208] NET: Registered protocol family 10
[    2.318681] Segment Routing with IPv6
[    2.374901] systemd[1]: systemd 241 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    2.379265] systemd[1]: Detected architecture arm64.
[    2.428325] systemd[1]: Set hostname to <pi-dortmund-eving>.
[    2.988750] random: systemd: uninitialized urandom read (16 bytes read)
[    2.998237] random: systemd: uninitialized urandom read (16 bytes read)
[    3.003469] systemd[1]: Created slice system-getty.slice.
[    3.007957] random: systemd: uninitialized urandom read (16 bytes read)
[    3.010326] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    3.014632] systemd[1]: Reached target Swap.
[    3.019809] systemd[1]: Listening on Journal Socket.
[    3.035885] systemd[1]: Starting Load Kernel Modules...
[    3.045087] systemd[1]: Mounting RPC Pipe File System...
[    3.055993] systemd[1]: Starting Restore / save the current clock...
[    3.092345] cryptd: max_cpu_qlen set to 1000
[    3.180740] i2c /dev entries driver
[    3.674271] EXT4-fs (mmcblk0p4): re-mounted. Opts: (null)
[    3.762037] systemd-journald[131]: Received request to flush runtime journal from PID 1
[    4.348348] rpivid-mem feb00000.hevc-decoder: rpivid-hevcmem initialised: Registers at 0xfeb00000 length 0x00010000
[    4.349248] rpivid-mem feb10000.rpivid-local-intc: rpivid-intcmem initialised: Registers at 0xfeb10000 length 0x00001000
[    4.356286] rpivid-mem feb20000.h264-decoder: rpivid-h264mem initialised: Registers at 0xfeb20000 length 0x00010000
[    4.368655] rpivid-mem feb30000.vp9-decoder: rpivid-vp9mem initialised: Registers at 0xfeb30000 length 0x00010000
[    4.423351] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    4.448825] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    4.448857] [vc_sm_connected_init]: start
[    4.453387] mc: Linux media interface: v0.10
[    4.460190] [vc_sm_connected_init]: installed successfully
[    4.492894] i2c i2c-22: Added multiplexed i2c bus 0
[    4.493592] i2c i2c-22: Added multiplexed i2c bus 10
[    4.502011] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    4.552238] videodev: Linux video capture interface: v2.00
[    4.563650] bcm2835_audio bcm2835_audio: card created with 4 channels
[    4.613687] bcm2835_audio bcm2835_audio: card created with 4 channels
[    4.680526] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    4.681803] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    4.689925] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    4.702583] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    4.707760] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    4.710075] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    4.758386] [drm] Initialized v3d 1.0.0 20180419 for fec00000.v3d on minor 0
[    4.880298] checking generic (3e843000 384000) vs hw (0 ffffffffffffffff)
[    4.880321] fb0: switching to vc4drmfb from simple
[    4.880823] Console: switching to colour dummy device 80x25
[    4.888151] vc4-drm gpu: bound fe600000.firmwarekms (ops vc4_fkms_ops [vc4])
[    4.891478] [drm] Initialized vc4 0.0.0 20140616 for gpu on minor 1
[    4.952338] vc4-drm gpu: [drm] HDMI-A-1: EDID is invalid:
[    4.952368]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952380]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952391]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952402]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952413]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952424]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952435]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    4.952445]  [00] ZERO 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[    5.107487] Console: switching to colour frame buffer device 160x45
[    5.132428] vc4-drm gpu: [drm] fb0: vc4drmfb frame buffer device
[    5.349421] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    5.349470] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    5.349946] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    5.350750] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    5.351235] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    5.352546] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    5.352583] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    5.352604] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    5.352630] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    5.352648] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    5.352891] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    5.359592] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    5.359647] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    5.372013] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    5.372072] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    5.375632] bcm2835-codec bcm2835-codec: Device registered as /dev/video18
[    5.375683] bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx
[    6.955812] random: crng init done
[    6.955841] random: 7 urandom warning(s) missed due to ratelimiting
[    7.016408] 8021q: 802.1Q VLAN Support v1.8
[    7.206962] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    7.231641] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    7.444594] bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay)
[    7.445080] bcmgenet fd580000.ethernet eth0: Link is Down
[    7.525619] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   10.303356] broken atomic modeset userspace detected, disabling atomic
[   11.517531] bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
[   11.517568] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   16.832642] sctp: Hash tables configured (bind 256/256)
[   17.100465] NET: Registered protocol family 15
[   17.447288] NET: Registered protocol family 38
[186956.953617] bcm2835_mmal_vchiq: timed out waiting for sync completion
[186956.953654] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling i/p port, ret -62
[186958.969627] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 2 outstanding
[186958.969739] ------------[ cut here ]------------
[186958.969764] WARNING: CPU: 2 PID: 3012 at drivers/media/common/videobuf2/videobuf2-core.c:1956 __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186958.969767] Modules linked in: tcp_diag inet_diag jitterentropy_rng drbg authenc echainiv cast5_generic cast_common ctr algif_skcipher xcbc md4 algif_hash af_alg xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key md5 sctp cfg80211 rfkill 8021q garp stp llc spidev vc4 nft_nat cec bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) drm_kms_helper v4l2_mem2mem v3d videobuf2_vmalloc videobuf2_dma_contig gpu_sched videobuf2_memops videobuf2_v4l2 snd_soc_core videobuf2_common snd_compress snd_bcm2835(C) drm snd_pcm_dmaengine i2c_mux_pinctrl raspberrypi_hwmon videodev drm_panel_orientation_quirks mc i2c_mux vc_sm_cma(C) snd_pcm snd_timer snd syscopyarea sysfillrect rpivid_mem sysimgblt fb_sys_fops backlight i2c_bcm2835 spi_bcm2835 nvmem_rmem uio_pdrv_genirq uio nft_chain_nat nf_nat nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables nfnetlink i2c_dev aes_neon_bs sha256_generic aes_neon_blk crypto_simd cryptd ip_tables x_tables ipv6
[186958.969951] CPU: 2 PID: 3012 Comm: python3 Tainted: G         C        5.10.74-v8+ #1471
[186958.969954] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT)
[186958.969959] pstate: 80000005 (Nzcv daif -PAN -UAO -TCO BTYPE=--)
[186958.969967] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186958.969974] lr : __vb2_queue_cancel+0x3c/0x220 [videobuf2_common]
[186958.969977] sp : ffffffc01304bb10
[186958.969980] x29: ffffffc01304bb10 x28: ffffffc008e46ed0 
[186958.969986] x27: ffffff805ce9bb00 x26: 0000000000000000 
[186958.969993] x25: ffffff8045d47630 x24: 0000000040045613 
[186958.969999] x23: 0000000000000000 x22: ffffffc010e1c798 
[186958.970005] x21: ffffff8055576298 x20: ffffff8055576298 
[186958.970011] x19: ffffff8055576298 x18: 0000000000000004 
[186958.970017] x17: 0000000000000000 x16: 0000000000000000 
[186958.970023] x15: ffffff8046d00030 x14: ffffff8070035728 
[186958.970029] x13: 0000000000000000 x12: 0000000000000000 
[186958.970034] x11: ffffff80700356d0 x10: ffffff8046d00038 
[186958.970040] x9 : ffffffc0102aacdc x8 : 000000000010000f 
[186958.970046] x7 : 0000000000000000 x6 : ffffffc010e1c798 
[186958.970052] x5 : ffffffc008d582b4 x4 : ffffffff00fe2120 
[186958.970058] x3 : 0000000000000001 x2 : 0000000000000000 
[186958.970063] x1 : 3964ae8c0c391800 x0 : 0000000000000002 
[186958.970070] Call trace:
[186958.970078]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186958.970084]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
[186958.970095]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
[186958.970108]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
[186958.970114]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
[186958.970173]  v4l_streamoff+0x2c/0x38 [videodev]
[186958.970190]  __video_do_ioctl+0x18c/0x3f0 [videodev]
[186958.970208]  video_usercopy+0x154/0x618 [videodev]
[186958.970225]  video_ioctl2+0x20/0x68 [videodev]
[186958.970242]  v4l2_ioctl+0x48/0x68 [videodev]
[186958.970255]  __arm64_sys_ioctl+0xb0/0xf0
[186958.970262]  el0_svc_common.constprop.3+0xc0/0x1f8
[186958.970266]  do_el0_svc+0x2c/0x98
[186958.970273]  el0_svc+0x20/0x30
[186958.970277]  el0_sync_handler+0x90/0xb8
[186958.970281]  el0_sync+0x180/0x1c0
[186958.970284] ---[ end trace c5f941e74fdb43f9 ]---
[186958.970300] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000002298a574 in active state
[186958.970310] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000aa3226fa in active state
[186960.997596] ------------[ cut here ]------------
[186960.997622] WARNING: CPU: 0 PID: 80 at kernel/workqueue.c:1477 __queue_work+0x474/0x530
[186960.997625] Modules linked in: tcp_diag inet_diag jitterentropy_rng drbg authenc echainiv cast5_generic cast_common ctr algif_skcipher xcbc md4 algif_hash af_alg xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key md5 sctp cfg80211 rfkill 8021q garp stp llc spidev vc4 nft_nat cec bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) drm_kms_helper v4l2_mem2mem v3d videobuf2_vmalloc videobuf2_dma_contig gpu_sched videobuf2_memops videobuf2_v4l2 snd_soc_core videobuf2_common snd_compress snd_bcm2835(C) drm snd_pcm_dmaengine i2c_mux_pinctrl raspberrypi_hwmon videodev drm_panel_orientation_quirks mc i2c_mux vc_sm_cma(C) snd_pcm snd_timer snd syscopyarea sysfillrect rpivid_mem sysimgblt fb_sys_fops backlight i2c_bcm2835 spi_bcm2835 nvmem_rmem uio_pdrv_genirq uio nft_chain_nat nf_nat nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables nfnetlink i2c_dev aes_neon_bs sha256_generic aes_neon_blk crypto_simd cryptd ip_tables x_tables ipv6
[186960.997825] CPU: 0 PID: 80 Comm: vchiq-slot/0 Tainted: G        WC        5.10.74-v8+ #1471
[186960.997828] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT)
[186960.997833] pstate: 00000085 (nzcv daIf -PAN -UAO -TCO BTYPE=--)
[186960.997837] pc : __queue_work+0x474/0x530
[186960.997841] lr : __queue_work+0xa8/0x530
[186960.997843] sp : ffffffc01213bb20
[186960.997846] x29: ffffffc01213bb20 x28: ffffff80fb7efc80 
[186960.997853] x27: ffffffc01146c7a0 x26: 0000000000000000 
[186960.997859] x25: ffffffc0112897c8 x24: 0000000000000100 
[186960.997865] x23: ffffffc01146c790 x22: ffffff8040006800 
[186960.997871] x21: 0000000000000039 x20: ffffff8070c4d210 
[186960.997877] x19: ffffff80fb7f3a00 x18: 0000000000000000 
[186960.997883] x17: 0000000000000000 x16: 0000000000000000 
[186960.997889] x15: 0000000000000000 x14: 0000000000000000 
[186960.997894] x13: 0000000000000000 x12: 0000000000000000 
[186960.997900] x11: 0000000000000040 x10: ffffffc0112a05e0 
[186960.997906] x9 : ffffffc010adc354 x8 : ffffff8040400028 
[186960.997912] x7 : 0000000000000000 x6 : ffffffc01213bac0 
[186960.997918] x5 : 0000000000000001 x4 : 0000000000000001 
[186960.997924] x3 : 0000000000000000 x2 : 0000000000000001 
[186960.997929] x1 : 0000000000000000 x0 : ffffff8070c4d218 
[186960.997936] Call trace:
[186960.997940]  __queue_work+0x474/0x530
[186960.997944]  queue_work_on+0x80/0xc8
[186960.997956]  service_callback+0x1f4/0x570 [bcm2835_mmal_vchiq]
[186960.997965]  slot_handler_func+0xd84/0x1b78
[186960.997970]  kthread+0x148/0x158
[186960.997975]  ret_from_fork+0x10/0x30
[186960.997979] ---[ end trace c5f941e74fdb43fa ]---
[186960.998024] bcm2835_mmal_vchiq: drvbuf.client_context(6) is invalid
[186960.998034] bcm2835_mmal_vchiq: received invalid message context 19!
[186960.998330] ------------[ cut here ]------------
[186960.998355] WARNING: CPU: 1 PID: 3012 at drivers/media/common/videobuf2/videobuf2-core.c:1956 __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186960.998358] Modules linked in: tcp_diag inet_diag jitterentropy_rng drbg authenc echainiv cast5_generic cast_common ctr algif_skcipher xcbc md4 algif_hash af_alg xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 af_key md5 sctp cfg80211 rfkill 8021q garp stp llc spidev vc4 nft_nat cec bcm2835_codec(C) bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) drm_kms_helper v4l2_mem2mem v3d videobuf2_vmalloc videobuf2_dma_contig gpu_sched videobuf2_memops videobuf2_v4l2 snd_soc_core videobuf2_common snd_compress snd_bcm2835(C) drm snd_pcm_dmaengine i2c_mux_pinctrl raspberrypi_hwmon videodev drm_panel_orientation_quirks mc i2c_mux vc_sm_cma(C) snd_pcm snd_timer snd syscopyarea sysfillrect rpivid_mem sysimgblt fb_sys_fops backlight i2c_bcm2835 spi_bcm2835 nvmem_rmem uio_pdrv_genirq uio nft_chain_nat nf_nat nft_counter nft_ct nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables nfnetlink i2c_dev aes_neon_bs sha256_generic aes_neon_blk crypto_simd cryptd ip_tables x_tables ipv6
[186960.998548] CPU: 1 PID: 3012 Comm: python3 Tainted: G        WC        5.10.74-v8+ #1471
[186960.998551] Hardware name: Raspberry Pi 4 Model B Rev 1.1 (DT)
[186960.998556] pstate: 20000005 (nzCv daif -PAN -UAO -TCO BTYPE=--)
[186960.998564] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186960.998571] lr : __vb2_queue_cancel+0x3c/0x220 [videobuf2_common]
[186960.998574] sp : ffffffc01304bb10
[186960.998576] x29: ffffffc01304bb10 x28: ffffffc008e46ed0 
[186960.998583] x27: ffffff805ce9bb00 x26: 0000000000000000 
[186960.998589] x25: ffffff8045d47630 x24: 0000000040045613 
[186960.998595] x23: 0000000000000000 x22: ffffffc010e1c798 
[186960.998604] x21: ffffff8055576028 x20: ffffff8055576028 
[186960.998610] x19: ffffff8055576028 x18: 0000000000000004 
[186960.998616] x17: 0000000000000000 x16: 0000000000000000 
[186960.998622] x15: ffffff8046d00030 x14: ffffff8070035718 
[186960.998628] x13: 0000000000000000 x12: 0000000000000000 
[186960.998633] x11: ffffff80700356d0 x10: ffffff8046d00038 
[186960.998640] x9 : ffffffc008d5999c x8 : ffffff80700356f8 
[186960.998645] x7 : 0000000000000000 x6 : 0000000000000000 
[186960.998651] x5 : ffffff8045d4781c x4 : ffffff80415b0000 
[186960.998657] x3 : ffffff8046d00008 x2 : 0000000000000002 
[186960.998663] x1 : 0000000000000000 x0 : 0000000000000006 
[186960.998669] Call trace:
[186960.998677]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[186960.998685]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
[186960.998695]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
[186960.998704]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
[186960.998710]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
[186960.998747]  v4l_streamoff+0x2c/0x38 [videodev]
[186960.998765]  __video_do_ioctl+0x18c/0x3f0 [videodev]
[186960.998782]  video_usercopy+0x154/0x618 [videodev]
[186960.998801]  video_ioctl2+0x20/0x68 [videodev]
[186960.998818]  v4l2_ioctl+0x48/0x68 [videodev]
[186960.998828]  __arm64_sys_ioctl+0xb0/0xf0
[186960.998835]  el0_svc_common.constprop.3+0xc0/0x1f8
[186960.998839]  do_el0_svc+0x2c/0x98
[186960.998846]  el0_svc+0x20/0x30
[186960.998849]  el0_sync_handler+0x90/0xb8
[186960.998852]  el0_sync+0x180/0x1c0
[186960.998856] ---[ end trace c5f941e74fdb43fb ]---
[186960.998862] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000918a9bc6 in active state
[186960.998873] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000c5bb47db in active state
[186960.998880] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000f1f5a68c in active state
[186960.998886] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000a5bd0b6f in active state
[186960.998893] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000c90aa5e0 in active state
[186960.998899] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000026667f14 in active state

raspberrypi / linux

bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 6 outstanding #4606

System System Information

Videocore information

Filesystem information

Package version information

Networking Information

USB Information

config.txt

cmdline.txt

raspi-gpio settings

vcdbg log messages

dmesg log

4593 included a load of updates around the stateful encoder and decoder, in particular around "pool exhausted, recyling bust," and the WARN from not returning all the buffers.

4593 unfortunately had no positive effect.