search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.2k stars 5.02k forks source link

videobuf2_common: driver bug: stop_streaming operation is leaving buf 0b70dd47 in active state #3791

Open adalava opened 4 years ago

adalava commented 4 years ago

I hit this "driver bug" after stopping an IP camera stream that was left open overnight. The software uses OpenCV to read camera frames using a gstreamer pipeline like this: "rtspsrc protocols=tcp tcp-timeout=2000000 retry=2 do-retransmission=false location=rtsp://192.168.42.10:554/user=admin&password=&channel=1&stream=0.sdp ! rtpjitter buffer ! rtph264depay ! queue ! h264parse ! v4l2h264dec ! queue ! appsink sync=1"

Model: Raspberry Pi 3B

$ cat /etc/rpi-issue Raspberry Pi reference 2020-05-27 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 825107f04027269db77426046f5085475b1ea22f, stage2

$ vcgencmd version Jul 17 2020 11:04:27 Copyright (c) 2012 Broadcom version 21a15cb094f41c7506ad65d2cb9b29c550693057 (clean) (release) (start)

$ uname -a Linux br0001 5.4.51-v7+ #1327 SMP Thu Jul 23 10:58:46 BST 2020 armv7l GNU/Linux

[Thu Aug 13 10:12:33 2020] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 11 outstanding [Thu Aug 13 10:12:33 2020] ------------[ cut here ]------------ [Thu Aug 13 10:12:33 2020] WARNING: CPU: 0 PID: 13924 at drivers/media/common/videobuf2/videobuf2-core.c:1882 vb2_queue_cancel+0x210/0x288 [videobuf2_common] [Thu Aug 13 10:12:33 2020] Modules linked in: cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc brcmfmac brcmutil sha256_generic libsha256 cfg80211 raspberrypi_hwmon rfkill i2c_bcm2835 bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) v4l2_mem2mem snd_bcm2835(C) bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops snd_pcm videobuf2_v4l2 videobuf2_common snd_timer videodev snd mc vc_sm_cma(C) uio_pdrv_genirq uio fixed i2c_dev ip_tables x_tables ipv6 nf_defrag_ipv6 [Thu Aug 13 10:12:33 2020] CPU: 0 PID: 13924 Comm: python Tainted: G WC 5.4.51-v7+ #1327 [Thu Aug 13 10:12:33 2020] Hardware name: BCM2835 [Thu Aug 13 10:12:33 2020] Backtrace: [Thu Aug 13 10:12:33 2020] [<8010d458>] (dump_backtrace) from [<8010d750>] (show_stack+0x20/0x24) [Thu Aug 13 10:12:33 2020] r6:8bcf6000 r5:00000000 r4:80d93ff4 r3:82a41469 [Thu Aug 13 10:12:33 2020] [<8010d730>] (show_stack) from [<808b2324>] (dump_stack+0xe0/0x124) [Thu Aug 13 10:12:33 2020] [<808b2244>] (dump_stack) from [<8011fd24>] (warn+0xec/0x104) [Thu Aug 13 10:12:33 2020] r8:0000075a r7:00000009 r6:7f0ca7c4 r5:00000000 r4:00000000 r3:82a41469 [Thu Aug 13 10:12:33 2020] [<8011fc38>] (warn) from [<8011fdf4>] (warn_slowpath_fmt+0xb8/0xc0) [Thu Aug 13 10:12:33 2020] r9:7f0ca7c4 r8:0000075a r7:7f0c519c r6:00000009 r5:00000000 r4:80d04f48 [Thu Aug 13 10:12:33 2020] [<8011fd40>] (warn_slowpath_fmt) from [<7f0c519c>] (__vb2_queue_cancel+0x210/0x288 [videobuf2_common]) [Thu Aug 13 10:12:33 2020] r9:afa8b40c r8:40045613 r7:7f165ee0 r6:afa8b40c r5:00000009 r4:afa8b40c [Thu Aug 13 10:12:33 2020] [<7f0c4f8c>] (vb2_queue_cancel [videobuf2_common]) from [<7f0c6b00>] (vb2_core_streamoff+0x44/0xb4 [videobuf2_common]) [Thu Aug 13 10:12:33 2020] r10:b1bd27c8 r9:00000020 r8:40045613 r7:7f165ee0 r6:afa8b40c r5:00000009 [Thu Aug 13 10:12:33 2020] r4:afa8b40c r3:00000009 [Thu Aug 13 10:12:33 2020] [<7f0c6abc>] (vb2_core_streamoff [videobuf2_common]) from [<7f0e6084>] (vb2_streamoff+0x40/0x60 [videobuf2_v4l2]) [Thu Aug 13 10:12:33 2020] r4:afa8b400 r3:00000000 [Thu Aug 13 10:12:33 2020] [<7f0e6044>] (vb2_streamoff [videobuf2_v4l2]) from [<7f1d8c08>] (v4l2_m2m_streamoff+0x3c/0xf4 [v4l2_mem2mem]) [Thu Aug 13 10:12:33 2020] [<7f1d8bcc>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<7f1d8ce0>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem]) [Thu Aug 13 10:12:33 2020] r10:b1bd27c8 r9:00000020 r8:40045613 r7:7f165ee0 r6:80d04f48 r5:00000000 [Thu Aug 13 10:12:33 2020] r4:b1bd24a0 r3:97229000 [Thu Aug 13 10:12:33 2020] [<7f1d8cc0>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<7f165f08>] (v4l_streamoff+0x28/0x2c [videodev]) [Thu Aug 13 10:12:33 2020] [<7f165ee0>] (v4l_streamoff [videodev]) from [<7f16acb4>] (video_do_ioctl+0x240/0x470 [videodev]) [Thu Aug 13 10:12:33 2020] [<7f16aa74>] (video_do_ioctl [videodev]) from [<7f16cd54>] (video_usercopy+0x220/0x60c [videodev]) [Thu Aug 13 10:12:33 2020] r10:7f16aa74 r9:40045613 r8:00000000 r7:8bcf7e04 r6:00000004 r5:00000000 [Thu Aug 13 10:12:33 2020] r4:80d04f48 [Thu Aug 13 10:12:33 2020] [<7f16cb34>] (video_usercopy [videodev]) from [<7f16d160>] (video_ioctl2+0x20/0x24 [videodev]) [Thu Aug 13 10:12:33 2020] r10:00000036 r9:8bcf6000 r8:00000026 r7:8e89a540 r6:b1371690 r5:021f1200 [Thu Aug 13 10:12:33 2020] r4:80d04f48 [Thu Aug 13 10:12:33 2020] [<7f16d140>] (video_ioctl2 [videodev]) from [<7f164144>] (v4l2_ioctl+0x4c/0x60 [videodev]) [Thu Aug 13 10:12:33 2020] [<7f1640f8>] (v4l2_ioctl [videodev]) from [<802f8540>] (do_vfs_ioctl+0xbc/0x804) [Thu Aug 13 10:12:33 2020] [<802f8484>] (do_vfs_ioctl) from [<802f8ccc>] (ksys_ioctl+0x44/0x6c) [Thu Aug 13 10:12:33 2020] r10:00000036 r9:8bcf6000 r8:00000026 r7:40045613 r6:8e89a540 r5:021f1200 [Thu Aug 13 10:12:33 2020] r4:8e89a541 [Thu Aug 13 10:12:33 2020] [<802f8c88>] (ksys_ioctl) from [<802f8d0c>] (sys_ioctl+0x18/0x1c) [Thu Aug 13 10:12:33 2020] r8:801011c4 r7:00000036 r6:4ca637d0 r5:4ca63000 r4:6a308648 r3:76d72510 [Thu Aug 13 10:12:33 2020] [<802f8cf4>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28) [Thu Aug 13 10:12:33 2020] Exception stack(0x8bcf7fa8 to 0x8bcf7ff0) [Thu Aug 13 10:12:33 2020] 7fa0: 6a308648 4ca63000 00000026 40045613 021f1200 76d72510 [Thu Aug 13 10:12:33 2020] 7fc0: 6a308648 4ca63000 4ca637d0 00000036 6a307300 6a4785f0 706e492c 74c73ce8 [Thu Aug 13 10:12:33 2020] 7fe0: 708cfc60 7eb630b4 4ca2b954 76d7251c [Thu Aug 13 10:12:33 2020] ---[ end trace abd9ddf252533015 ]--- [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0b70dd47 in active state [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf b0d5ce36 in active state [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf da61dea1 in active state [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf d4e41263 in active state [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf db4367ac in active state [Thu Aug 13 10:12:33 2020] videobuf2_common: driver bug: stop_streaming operation is leaving buf 08347a89 in active state

6by9 commented 4 years ago

Hopefully solved by #3790

popcornmix commented 4 years ago

Fix should be in latest rpi-update kernel.

adalava commented 4 years ago

Thank you! I updated to 5.4.58-v7+ #1335 SMP Thu Aug 13 22:17:06 BST 2020 armv7l GNU/Linux and will let you known if it appears again.

adalava commented 4 years ago

I've being using 5.4.58-v7+ for more than a week, it looks good, so I'm closing this issue. Thank you!

timemaster5 commented 4 years ago

I think the problem is still there. My use case is slightly different. I am playing a youtube video in the wpewebkit browser, and still reaching these messages in dmesg :(

Sorry..

adalava commented 4 years ago

:-( @timemaster5, it's still good here so far. Anyway I reopened the issue and would be nice if you could give more information for the devs, like your dmesg and "uname -a " output. Maybe there's something in your output that could help.

timemaster5 commented 4 years ago

hm, maybe it has multiple causes.. here is the dmesg. The second line is uname -a basically. Hope that helps.

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 5.4.59-v7 (oe-user@oe-host) (gcc version 9.3.0 (GCC)) #1 SMP Tue Aug 25 23:21:36 UTC 2020
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] Reserved memory: created CMA memory pool at 0x1ec00000, size 256 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] On node 0 totalpages: 196608
[    0.000000]   Normal zone: 1728 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 196608 pages, LIFO batch:63
[    0.000000] percpu: Embedded 20 pages/cpu s49868 r8192 d23860 u81920
[    0.000000] pcpu-alloc: s49868 r8192 d23860 u81920 alloc=20*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 194880
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_headphones=1 video=HDMI-A-1:1680x1050M@60 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  dwc_otg.lpm_enable=0  root=/dev/mmcblk0p2 rootfstype=ext4 rootwait loglevel=1 quiet consoleblank=0
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 500792K/786432K available (9216K kernel code, 691K rwdata, 2752K rodata, 1024K init, 828K bss, 23496K reserved, 262144K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 29395 entries in 58 pages
[    0.000000] rcu: Hierarchical RCU implementation.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] random: get_random_bytes called from start_kernel+0x324/0x504 with crng_init=0
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000006] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000017] Switching to timer-based delay loop, resolution 52ns
[    0.000292] Console: colour dummy device 80x30
[    0.000323] printk: console [tty0] enabled
[    0.000378] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.000399] pid_max: default: 32768 minimum: 301
[    0.000799] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.000822] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002270] Disabling memory control group subsystem
[    0.002376] CPU: Testing write buffer coherency: ok
[    0.002990] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.003952] Setting up static identity map for 0x100000 - 0x10003c
[    0.004154] rcu: Hierarchical SRCU implementation.
[    0.004873] smp: Bringing up secondary CPUs ...
[    0.006066] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.007385] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.008599] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.008755] smp: Brought up 1 node, 4 CPUs
[    0.008771] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.008781] CPU: All CPU(s) started in HYP mode.
[    0.008790] CPU: Virtualization extensions available.
[    0.009787] devtmpfs: initialized
[    0.026317] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.026599] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.026629] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.038245] pinctrl core: initialized pinctrl subsystem
[    0.039506] NET: Registered protocol family 16
[    0.043967] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.050185] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.050198] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.050438] Serial: AMBA PL011 UART driver
[    0.053018] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.080213] raspberrypi-firmware soc:firmware: Attached to firmware from 2020-07-13 13:57, variant start
[    0.090226] raspberrypi-firmware soc:firmware: Firmware hash is adcebbdb7b415c623931e80795ba3bae68dcc4fa
[    0.141592] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.143899] SCSI subsystem initialized
[    0.144174] usbcore: registered new interface driver usbfs
[    0.144238] usbcore: registered new interface driver hub
[    0.144370] usbcore: registered new device driver usb
[    0.146348] clocksource: Switched to clocksource arch_sys_counter
[    1.286555] VFS: Disk quotas dquot_6.6.0
[    1.286679] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    1.286883] FS-Cache: Loaded
[    1.287132] CacheFiles: Loaded
[    1.287992] simple-framebuffer 3e536000.framebuffer: framebuffer at 0x3e536000, 0x6c4800 bytes, mapped to 0x(ptrval)
[    1.288010] simple-framebuffer 3e536000.framebuffer: format=a8r8g8b8, mode=1680x1050x32, linelength=6720
[    1.288601] Console: switching to colour frame buffer device 210x65
[    1.318072] simple-framebuffer 3e536000.framebuffer: fb0: simplefb registered!
[    1.327519] thermal_sys: Registered thermal governor 'step_wise'
[    1.327971] NET: Registered protocol family 2
[    1.328934] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[    1.328982] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    1.329098] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    1.329288] TCP: Hash tables configured (established 8192 bind 8192)
[    1.329478] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.329533] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    1.329853] NET: Registered protocol family 1
[    1.330667] RPC: Registered named UNIX socket transport module.
[    1.330677] RPC: Registered udp transport module.
[    1.330688] RPC: Registered tcp transport module.
[    1.330698] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    1.332508] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    1.336023] Initialise system trusted keyrings
[    1.336288] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    1.348188] FS-Cache: Netfs 'nfs' registered for caching
[    1.349028] NFS: Registering the id_resolver key type
[    1.349088] Key type id_resolver registered
[    1.349098] Key type id_legacy registered
[    1.349122] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.350423] Key type asymmetric registered
[    1.350436] Asymmetric key parser 'x509' registered
[    1.350487] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 249)
[    1.350500] io scheduler mq-deadline registered
[    1.350512] io scheduler kyber registered
[    1.359808] bcm2835-rng 3f104000.rng: hwrng registered
[    1.360433] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    1.361125] vc-sm: Videocore shared memory driver
[    1.361647] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.374457] brd: module loaded
[    1.387256] loop: module loaded
[    1.388676] Loading iSCSI transport class v2.0-870.
[    1.389560] libphy: Fixed MDIO Bus: probed
[    1.389674] usbcore: registered new interface driver lan78xx
[    1.389739] usbcore: registered new interface driver smsc95xx
[    1.389763] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.117967] Core Release: 2.80a
[    2.117980] Setting default values for core params
[    2.118012] Finished setting default values for core params
[    2.318409] Using Buffer DMA mode
[    2.318421] Periodic Transfer Interrupt Enhancement - disabled
[    2.318430] Multiprocessor Interrupt Enhancement - disabled
[    2.318442] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.318516] Dedicated Tx FIFOs mode
[    2.319815] WARN::dwc_otg_hcd_init:1072: FIQ DMA bounce buffers: virt = 9ed04000 dma = 0xded04000 len=9024
[    2.319847] FIQ FSM acceleration enabled for :
[    2.319847] Non-periodic Split Transactions
[    2.319847] Periodic Split Transactions
[    2.319847] High-Speed Isochronous Endpoints
[    2.319847] Interrupt/Control Split Transaction hack enabled
[    2.319859] dwc_otg: Microframe scheduler enabled
[    2.319934] WARN::hcd_init_fiq:457: FIQ on core 1
[    2.319944] WARN::hcd_init_fiq:458: FIQ ASM at 8071dbc4 length 36
[    2.319956] WARN::hcd_init_fiq:496: MPHI regs_base at b0810000
[    2.319981] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.320021] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.320083] dwc_otg 3f980000.usb: irq 56, io mem 0x00000000
[    2.320135] Init: Port Power? op_state=1
[    2.320145] Init: Power Port (0)
[    2.320516] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.04
[    2.320533] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.320547] usb usb1: Product: DWC OTG Controller
[    2.320561] usb usb1: Manufacturer: Linux 5.4.59-v7 dwc_otg_hcd
[    2.320576] usb usb1: SerialNumber: 3f980000.usb
[    2.321327] hub 1-0:1.0: USB hub found
[    2.321391] hub 1-0:1.0: 1 port detected
[    2.322237] dwc_otg: FIQ enabled
[    2.322247] dwc_otg: NAK holdoff enabled
[    2.322257] dwc_otg: FIQ split-transaction FSM enabled
[    2.322271] Module dwc_common_port init
[    2.322593] usbcore: registered new interface driver usb-storage
[    2.322801] mousedev: PS/2 mouse device common for all mice
[    2.324851] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    2.326401] cpufreq: cpufreq_online: CPU0: Running at unlisted freq: 600000 KHz
[    2.328285] cpufreq: cpufreq_online: CPU0: Unlisted initial frequency changed to: 700000 KHz
[    2.329034] sdhci: Secure Digital Host Controller Interface driver
[    2.329042] sdhci: Copyright(c) Pierre Ossman
[    2.329643] mmc-bcm2835 3f300000.mmcnr: could not get clk, deferring probe
[    2.330191] sdhost-bcm2835 3f202000.mmc: could not get clk, deferring probe
[    2.330413] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.332162] ledtrig-cpu: registered to indicate activity on CPUs
[    2.332498] hidraw: raw HID events driver (C) Jiri Kosina
[    2.332684] usbcore: registered new interface driver usbhid
[    2.332693] usbhid: USB HID core driver
[    2.333688] vchiq: vchiq_init_state: slot_zero = (ptrval)
[    2.335378] [vc_sm_connected_init]: start
[    2.523168] [vc_sm_connected_init]: end - returning 0
[    2.524759] Initializing XFRM netlink socket
[    2.524793] NET: Registered protocol family 17
[    2.524964] Key type dns_resolver registered
[    2.525510] Registering SWP/SWPB emulation handler
[    2.525829] registered taskstats version 1
[    2.525849] Loading compiled-in X.509 certificates
[    2.526318] Key type ._fscrypt registered
[    2.526378] Key type .fscrypt registered
[    2.535886] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    2.535974] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    2.536590] Indeed it is in host mode hprt0 = 00021501
[    2.537956] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    2.540023] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    2.540035] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    2.566480] sdhost: log_buf @ (ptrval) (ded03000)
[    2.602454] mmc1: queuing unknown CIS tuple 0x80 (2 bytes)
[    2.604069] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.605686] mmc1: queuing unknown CIS tuple 0x80 (3 bytes)
[    2.608650] mmc1: queuing unknown CIS tuple 0x80 (7 bytes)
[    2.615074] random: fast init done
[    2.616423] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    2.618804] of_cfs_init
[    2.618952] of_cfs_init: OK
[    2.620075] Waiting for root device /dev/mmcblk0p2...
[    2.676149] mmc0: host does not support reading read-only switch, assuming write-enable
[    2.679607] mmc0: new high speed SDHC card at address 59b4
[    2.680621] mmcblk0: mmc0:59b4 SDU1  14.8 GiB
[    2.683261]  mmcblk0: p1 p2
[    2.695236] mmc1: new high speed SDIO card at address 0001
[    2.708764] EXT4-fs (mmcblk0p2): INFO: recovery required on readonly filesystem
[    2.708778] EXT4-fs (mmcblk0p2): write access will be enabled during recovery
[    2.746396] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    2.746532] Indeed it is in host mode hprt0 = 00001101
[    2.965250] EXT4-fs (mmcblk0p2): recovery complete
[    2.972793] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.972885] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.973603] devtmpfs: mounted
[    2.979628] Freeing unused kernel memory: 1024K
[    2.980005] Run /sbin/init as init process
[    2.986717] usb 1-1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    2.986742] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    2.987455] hub 1-1:1.0: USB hub found
[    2.987553] hub 1-1:1.0: 4 ports detected
[    3.251288] systemd[1]: System time before build time, advancing clock.
[    3.316401] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    3.366022] NET: Registered protocol family 10
[    3.367351] Segment Routing with IPv6
[    3.389110] systemd[1]: systemd 244.3+ 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)
[    3.389978] systemd[1]: Detected architecture arm.
[    3.446696] usb 1-1.1: New USB device found, idVendor=0424, idProduct=2514, bcdDevice= b.b3
[    3.446714] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.447427] hub 1-1.1:1.0: USB hub found
[    3.447536] hub 1-1.1:1.0: 3 ports detected
[    3.450436] systemd[1]: Set hostname to <raspberrypi3>.
[    3.800395] dwc_otg_handle_wakeup_detected_intr lxstate = 2
[    4.011705] random: systemd: uninitialized urandom read (16 bytes read)
[    4.014758] systemd[1]: Created slice system-serial\x2dgetty.slice.
[    4.015048] random: systemd: uninitialized urandom read (16 bytes read)
[    4.016081] systemd[1]: Created slice User and Session Slice.
[    4.016215] random: systemd: uninitialized urandom read (16 bytes read)
[    4.016627] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    4.016961] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    4.017373] systemd[1]: Reached target Paths.
[    4.017514] systemd[1]: Reached target Remote File Systems.
[    4.017638] systemd[1]: Reached target Slices.
[    4.017810] systemd[1]: Reached target Swap.
[    4.020332] systemd[1]: Listening on Syslog Socket.
[    4.020788] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    4.039508] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[    4.040382] systemd[1]: Listening on Journal Socket (/dev/log).
[    4.041174] systemd[1]: Listening on Journal Socket.
[    4.041869] systemd[1]: Listening on udev Control Socket.
[    4.042359] systemd[1]: Listening on udev Kernel Socket.
[    4.043169] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    4.048092] systemd[1]: Mounting POSIX Message Queue File System...
[    4.053997] systemd[1]: Mounting Kernel Debug File System...
[    4.060710] systemd[1]: Mounting Temporary Directory (/tmp)...
[    4.067675] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    4.073498] systemd[1]: Starting Start psplash boot splash screen...
[    4.079452] systemd[1]: Starting File System Check on Root Device...
[    4.090012] systemd[1]: Starting Journal Service...
[    4.110956] systemd[1]: Condition check resulted in Load Kernel Modules being skipped.
[    4.111910] systemd[1]: Condition check resulted in FUSE Control File System being skipped.
[    4.118004] systemd[1]: Mounting Kernel Configuration File System...
[    4.124127] systemd[1]: Starting Apply Kernel Variables...
[    4.130825] systemd[1]: Starting udev Coldplug all Devices...
[    4.144024] systemd[1]: Mounted POSIX Message Queue File System.
[    4.145022] systemd[1]: Mounted Kernel Debug File System.
[    4.145909] systemd[1]: Mounted Temporary Directory (/tmp).
[    4.148778] systemd[1]: Started Create list of static device nodes for the current kernel.
[    4.150067] systemd[1]: Mounted Kernel Configuration File System.
[    4.157078] systemd[1]: Started Start psplash boot splash screen.
[    4.163878] systemd[1]: Started Start psplash-systemd progress communication helper.
[    4.210583] systemd[1]: Started Journal Service.
[    4.326479] usb 1-1.1.1: new high-speed USB device number 4 using dwc_otg
[    4.352664] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[    4.352709] ext4 filesystem being remounted at / supports timestamps until 2038 (0x7fffffff)
[    4.392156] systemd-journald[103]: Received client request to flush runtime journal.
[    4.456966] usb 1-1.1.1: New USB device found, idVendor=0424, idProduct=7800, bcdDevice= 3.00
[    4.456985] usb 1-1.1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.734244] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): No External EEPROM. Setting MAC Speed
[    4.735530] libphy: lan78xx-mdiobus: probed
[    4.761370] lan78xx 1-1.1.1:1.0 (unnamed net_device) (uninitialized): int urb period 64
[    5.003460] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    5.006904] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    5.006924] [vc_sm_connected_init]: start
[    5.012885] [vc_sm_connected_init]: installed successfully
[    5.020382] mc: Linux media interface: v0.10
[    5.081296] videodev: Linux video capture interface: v2.00
[    5.144917] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.146838] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.150248] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    5.168312] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    5.207757] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    5.233902] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    5.257448] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    5.259965] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    5.264701] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    5.271149] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    5.271189] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    5.271212] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    5.271228] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    5.271246] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    5.271683] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    5.277415] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    5.277487] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    5.289349] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    5.321091] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    5.321294] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    5.344381] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[    5.358286] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    5.358335] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    5.406778] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    5.407836] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    5.407860] cfg80211: failed to load regulatory.db
[    5.516788] brcmfmac: F1 signature read @0x18000000=0x15264345
[    5.542233] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    5.543915] usbcore: registered new interface driver brcmfmac
[    5.584932] brcmfmac mmc1:0001:1: Direct firmware load for brcm/brcmfmac43455-sdio.raspberrypi,3-model-b-plus.txt failed with error -2
[    5.626184] debugfs: Directory '3f902000.hdmi' with parent 'vc4-hdmi' already present!
[    5.630029] vc4_hdmi 3f902000.hdmi: vc4-hdmi-hifi <-> 3f902000.hdmi mapping ok
[    5.632418] vc4-drm soc:gpu: bound 3f902000.hdmi (ops vc4_hdmi_ops [vc4])
[    5.632720] vc4-drm soc:gpu: bound 3f806000.vec (ops vc4_vec_ops [vc4])
[    5.632979] vc4-drm soc:gpu: bound 3f004000.txp (ops vc4_txp_ops [vc4])
[    5.633189] vc4-drm soc:gpu: bound 3f400000.hvs (ops vc4_hvs_ops [vc4])
[    5.633474] vc4-drm soc:gpu: bound 3f206000.pixelvalve (ops vc4_crtc_ops [vc4])
[    5.633756] vc4-drm soc:gpu: bound 3f207000.pixelvalve (ops vc4_crtc_ops [vc4])
[    5.634013] vc4-drm soc:gpu: bound 3f807000.pixelvalve (ops vc4_crtc_ops [vc4])
[    5.634234] vc4-drm soc:gpu: bound 3fc00000.v3d (ops vc4_v3d_ops [vc4])
[    5.635050] checking generic (3e536000 6c4800) vs hw (0 ffffffff)
[    5.635062] fb0: switching to vc4drmfb from simple
[    5.646945] Console: switching to colour dummy device 80x30
[    5.647195] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    5.647205] [drm] Driver supports precise vblank timestamp query.
[    5.648652] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
[    5.692885] Console: switching to colour frame buffer device 210x65
[    5.692939] vc4-drm soc:gpu: fb0: vc4drmfb frame buffer device
[    5.816452] random: crng init done
[    5.816471] random: 7 urandom warning(s) missed due to ratelimiting
[    5.834180] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43455-sdio for chip BCM4345/6
[    5.891303] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM4345/6 wl0: Mar  2 2020 23:30:41 version 7.45.202 (r724630 CY) FWID 01-72f6ece2
[    7.633522] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   13.956692] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   61.817630] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[  145.116766] usb 1-1.3: new low-speed USB device number 5 using dwc_otg
[  145.264850] usb 1-1.3: New USB device found, idVendor=0603, idProduct=0002, bcdDevice= 2.21
[  145.264872] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  145.264884] usb 1-1.3: Product: USB Composite Device
[  145.264897] usb 1-1.3: Manufacturer: SINO WEALTH
[  145.288037] input: SINO WEALTH USB Composite Device as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/0003:0603:0002.0001/input/input0
[  145.359517] hid-generic 0003:0603:0002.0001: input,hidraw0: USB HID v1.10 Keyboard [SINO WEALTH USB Composite Device] on usb-3f980000.usb-1.3/input0
[  145.370481] input: SINO WEALTH USB Composite Device Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:0603:0002.0002/input/input1
[  145.374289] input: SINO WEALTH USB Composite Device System Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:0603:0002.0002/input/input2
[  145.447227] input: SINO WEALTH USB Composite Device Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:0603:0002.0002/input/input3
[  145.447933] hid-generic 0003:0603:0002.0002: input,hiddev96,hidraw1: USB HID v1.10 Mouse [SINO WEALTH USB Composite Device] on usb-3f980000.usb-1.3/input1
[  176.237324] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 2 outstanding
[  176.237350] ------------[ cut here ]------------
[  176.237399] WARNING: CPU: 0 PID: 336 at drivers/media/common/videobuf2/videobuf2-core.c:1882 __vb2_queue_cancel+0x244/0x2c0 [videobuf2_common]
[  176.237407] Modules linked in: joydev evdev vc4 brcmfmac brcmutil cec sha256_generic libsha256 snd_soc_core bcm2835_codec(C) snd_compress cfg80211 bcm2835_isp(C) snd_pcm_dmaengine bcm2835_v4l2(C) snd_pcm v4l2_mem2mem rfkill bcm2835_mmal_vchiq(C) snd_timer videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops snd videobuf2_v4l2 videobuf2_common videodev raspberrypi_hwmon mc vc_sm_cma(C) uio_pdrv_genirq uio fixed sch_fq_codel ipv6 nf_defrag_ipv6
[  176.237558] CPU: 0 PID: 336 Comm: eadedCompositor Tainted: G         C        5.4.59-v7 #1
[  176.237562] Hardware name: BCM2835
[  176.237567] Backtrace: 
[  176.237586] [<8010e068>] (dump_backtrace) from [<8010e3c4>] (show_stack+0x20/0x24)
[  176.237597]  r7:ffffffff r6:00000000 r5:600b0113 r4:80e962a0
[  176.237612] [<8010e3a4>] (show_stack) from [<80910f24>] (dump_stack+0xd4/0x118)
[  176.237626] [<80910e50>] (dump_stack) from [<801206a4>] (__warn+0xe0/0x108)
[  176.237638]  r10:9ce793d0 r9:00000008 r8:00000009 r7:0000075a r6:7f1b75b0 r5:00000009
[  176.237644]  r4:7f1bcae0 r3:00000000
[  176.237656] [<801205c4>] (__warn) from [<80120a70>] (warn_slowpath_fmt+0x74/0xcc)
[  176.237665]  r7:7f1b75b0 r6:0000075a r5:7f1bcae0 r4:00000000
[  176.237698] [<80120a00>] (warn_slowpath_fmt) from [<7f1b75b0>] (__vb2_queue_cancel+0x244/0x2c0 [videobuf2_common])
[  176.237709]  r8:9e126330 r7:9bf59c0c r6:9cc3dbc8 r5:9bf59c6c r4:9bf59c0c
[  176.237762] [<7f1b736c>] (__vb2_queue_cancel [videobuf2_common]) from [<7f1ba004>] (vb2_core_queue_release+0x28/0x48 [videobuf2_common])
[  176.237774]  r10:9ce793d0 r9:00000008 r8:9e126330 r7:9e6b0f10 r6:9cc3dbc8 r5:9bf59c6c
[  176.237780]  r4:9bf59c0c r3:80e04f48
[  176.237827] [<7f1b9fdc>] (vb2_core_queue_release [videobuf2_common]) from [<7f1d47dc>] (vb2_queue_release+0x18/0x1c [videobuf2_v4l2])
[  176.237834]  r5:9cd24000 r4:9bf59c00
[  176.237875] [<7f1d47c4>] (vb2_queue_release [videobuf2_v4l2]) from [<7f18c350>] (v4l2_m2m_ctx_release+0x24/0x38 [v4l2_mem2mem])
[  176.237918] [<7f18c32c>] (v4l2_m2m_ctx_release [v4l2_mem2mem]) from [<7f0b5cc0>] (bcm2835_codec_release+0x64/0xcc [bcm2835_codec])
[  176.237927]  r5:9cd24000 r4:9cc3d840
[  176.238075] [<7f0b5c5c>] (bcm2835_codec_release [bcm2835_codec]) from [<7f1166e0>] (v4l2_release+0xbc/0xe8 [videodev])
[  176.238084]  r7:9e6b0f10 r6:9ce793d0 r5:9cc3d8a0 r4:9c073e40
[  176.238194] [<7f116624>] (v4l2_release [videodev]) from [<802f4790>] (__fput+0xa4/0x23c)
[  176.238200]  r5:000e001f r4:9c073e40
[  176.238212] [<802f46ec>] (__fput) from [<802f4940>] (____fput+0x18/0x1c)
[  176.238223]  r10:fffffe30 r9:9c26eff0 r8:80eadcf4 r7:9c26f014 r6:9c26eac0 r5:9dc5cc00
[  176.238228]  r4:9c073300
[  176.238245] [<802f4928>] (____fput) from [<801417e4>] (task_work_run+0xb4/0xd4)
[  176.238259] [<80141730>] (task_work_run) from [<80124f00>] (do_exit+0x3f4/0xb58)
[  176.238271]  r9:9c393f58 r8:00000000 r7:9e7b5a40 r6:9c392000 r5:9e7b5a00 r4:9c26eac0
[  176.238285] [<80124b0c>] (do_exit) from [<80125700>] (do_group_exit+0x50/0xe0)
[  176.238290]  r7:9c392000
[  176.238304] [<801256b0>] (do_group_exit) from [<80132a34>] (get_signal+0x168/0x9a8)
[  176.238313]  r7:9c392000 r6:00000008 r5:9dd6ee40 r4:00000008
[  176.238327] [<801328cc>] (get_signal) from [<8010ca88>] (do_work_pending+0x140/0x564)
[  176.238338]  r10:fffffe30 r9:4a5fc024 r8:00000001 r7:9c393f44 r6:9c393fb0 r5:9c393f30
[  176.238343]  r4:ffffe000
[  176.238357] [<8010c948>] (do_work_pending) from [<80101034>] (slow_work_pending+0xc/0x20)
[  176.238363] Exception stack(0x9c393fb0 to 0x9c393ff8)
[  176.238371] 3fa0:                                     00000001 00000002 00000063 00000000
[  176.238383] 3fc0: 00000063 705239e8 6fcfe790 000000a8 6fcfdc64 00000063 00000001 7e89385c
[  176.238392] 3fe0: 000000a8 6fcfdc38 4a674921 4a5fc026 800d0030 705239e8
[  176.238403]  r10:000000a8 r9:9c392000 r8:801011c4 r7:000000a8 r6:6fcfe790 r5:705239e8
[  176.238408]  r4:00000063
[  176.238418] ---[ end trace 566a229dbfdfd720 ]---
[  176.238435] videobuf2_common: driver bug: stop_streaming operation is leaving buf 718fbbd3 in active state
[  176.238452] videobuf2_common: driver bug: stop_streaming operation is leaving buf 2f09dc18 in active state
[  215.517829] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 4 outstanding
[  215.518062] ------------[ cut here ]------------
[  215.518121] WARNING: CPU: 2 PID: 477 at drivers/media/common/videobuf2/videobuf2-core.c:1882 __vb2_queue_cancel+0x244/0x2c0 [videobuf2_common]
[  215.518130] Modules linked in: joydev evdev vc4 brcmfmac brcmutil cec sha256_generic libsha256 snd_soc_core bcm2835_codec(C) snd_compress cfg80211 bcm2835_isp(C) snd_pcm_dmaengine bcm2835_v4l2(C) snd_pcm v4l2_mem2mem rfkill bcm2835_mmal_vchiq(C) snd_timer videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops snd videobuf2_v4l2 videobuf2_common videodev raspberrypi_hwmon mc vc_sm_cma(C) uio_pdrv_genirq uio fixed sch_fq_codel ipv6 nf_defrag_ipv6
[  215.518301] CPU: 2 PID: 477 Comm: appsrc3:src Tainted: G        WC        5.4.59-v7 #1
[  215.518306] Hardware name: BCM2835
[  215.518313] Backtrace: 
[  215.518337] [<8010e068>] (dump_backtrace) from [<8010e3c4>] (show_stack+0x20/0x24)
[  215.518350]  r7:ffffffff r6:00000000 r5:60070113 r4:80e962a0
[  215.518365] [<8010e3a4>] (show_stack) from [<80910f24>] (dump_stack+0xd4/0x118)
[  215.518379] [<80910e50>] (dump_stack) from [<801206a4>] (__warn+0xe0/0x108)
[  215.518391]  r10:7f131c4c r9:00000001 r8:00000009 r7:0000075a r6:7f1b75b0 r5:00000009
[  215.518397]  r4:7f1bcae0 r3:00000000
[  215.518409] [<801205c4>] (__warn) from [<80120a70>] (warn_slowpath_fmt+0x74/0xcc)
[  215.518418]  r7:7f1b75b0 r6:0000075a r5:7f1bcae0 r4:00000000
[  215.518451] [<80120a00>] (warn_slowpath_fmt) from [<7f1b75b0>] (__vb2_queue_cancel+0x244/0x2c0 [videobuf2_common])
[  215.518462]  r8:9cc3dbc8 r7:9c083c0c r6:00000009 r5:9c083c0c r4:9c083c0c
[  215.518514] [<7f1b736c>] (__vb2_queue_cancel [videobuf2_common]) from [<7f1b8ae8>] (vb2_core_streamoff+0x28/0xb4 [videobuf2_common])
[  215.518526]  r10:7f131c4c r9:00000001 r8:9cc3dbc8 r7:7f117dd0 r6:00000009 r5:9c083c0c
[  215.518534]  r4:9c083c0c r3:00000009
[  215.518584] [<7f1b8ac0>] (vb2_core_streamoff [videobuf2_common]) from [<7f1d5fa4>] (vb2_streamoff+0x24/0x60 [videobuf2_v4l2])
[  215.518591]  r5:9c083c0c r4:9c083c00
[  215.518634] [<7f1d5f80>] (vb2_streamoff [videobuf2_v4l2]) from [<7f18bd18>] (v4l2_m2m_streamoff+0x40/0x10c [v4l2_mem2mem])
[  215.518676] [<7f18bcd8>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<7f18be04>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
[  215.518688]  r10:7f131c4c r9:00000001 r8:9cc3dbc8 r7:7f117dd0 r6:00000000 r5:40045613
[  215.518692]  r4:7f18bde4
[  215.518847] [<7f18bde4>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<7f117df8>] (v4l_streamoff+0x28/0x2c [videodev])
[  215.519053] [<7f117dd0>] (v4l_streamoff [videodev]) from [<7f11cbec>] (__video_do_ioctl+0x240/0x470 [videodev])
[  215.519060]  r5:40045613 r4:9cc3d8a0
[  215.519260] [<7f11c9ac>] (__video_do_ioctl [videodev]) from [<7f11d1c0>] (video_usercopy+0x220/0x650 [videodev])
[  215.519272]  r10:9cd9fe0c r9:00000004 r8:7f11c9ac r7:00000001 r6:00000000 r5:00000000
[  215.519277]  r4:40045613
[  215.519475] [<7f11cfa0>] (video_usercopy [videodev]) from [<7f11d610>] (video_ioctl2+0x20/0x24 [videodev])
[  215.519487]  r10:00000036 r9:0000002d r8:9cdef180 r7:019d91d0 r6:40045613 r5:9ce793d0
[  215.519492]  r4:7f11d5f0
[  215.519690] [<7f11d5f0>] (video_ioctl2 [videodev]) from [<7f1161f4>] (v4l2_ioctl+0x4c/0x60 [videodev])
[  215.519801] [<7f1161a8>] (v4l2_ioctl [videodev]) from [<80308938>] (do_vfs_ioctl+0x3cc/0x7f4)
[  215.519808]  r5:9ce793d0 r4:019d91d0
[  215.519823] [<8030856c>] (do_vfs_ioctl) from [<80308da4>] (ksys_ioctl+0x44/0x70)
[  215.519835]  r10:00000036 r9:9cd9e000 r8:9cdef180 r7:019d91d0 r6:40045613 r5:0000002d
[  215.519840]  r4:9cdef181
[  215.519854] [<80308d60>] (ksys_ioctl) from [<80308de8>] (sys_ioctl+0x18/0x1c)
[  215.519868]  r9:9cd9e000 r8:801011c4 r7:00000036 r6:6a4ff7e4 r5:6a4ff000 r4:019d4530
[  215.519883] [<80308dd0>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28)
[  215.519889] Exception stack(0x9cd9ffa8 to 0x9cd9fff0)
[  215.519899] ffa0:                   019d4530 6a4ff000 0000002d 40045613 019d91d0 4a676091
[  215.519912] ffc0: 019d4530 6a4ff000 6a4ff7e4 00000036 019d9450 019ee4f0 019e2388 4ae74678
[  215.519920] ffe0: 4acac048 66cfbdb4 6a4d06a5 4a676098
[  215.519930] ---[ end trace 566a229dbfdfd721 ]---
[  215.519947] videobuf2_common: driver bug: stop_streaming operation is leaving buf 9c8ae841 in active state
[  215.519965] videobuf2_common: driver bug: stop_streaming operation is leaving buf dd95bef2 in active state
[  228.397827] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 6 outstanding
[  228.398075] ------------[ cut here ]------------
[  228.398136] WARNING: CPU: 3 PID: 421 at drivers/media/common/videobuf2/videobuf2-core.c:1882 __vb2_queue_cancel+0x244/0x2c0 [videobuf2_common]
[  228.398144] Modules linked in: joydev evdev vc4 brcmfmac brcmutil cec sha256_generic libsha256 snd_soc_core bcm2835_codec(C) snd_compress cfg80211 bcm2835_isp(C) snd_pcm_dmaengine bcm2835_v4l2(C) snd_pcm v4l2_mem2mem rfkill bcm2835_mmal_vchiq(C) snd_timer videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops snd videobuf2_v4l2 videobuf2_common videodev raspberrypi_hwmon mc vc_sm_cma(C) uio_pdrv_genirq uio fixed sch_fq_codel ipv6 nf_defrag_ipv6
[  228.398322] CPU: 3 PID: 421 Comm: WPEWebProcess Tainted: G        WC        5.4.59-v7 #1
[  228.398330] Hardware name: BCM2835
[  228.398337] Backtrace: 
[  228.398360] [<8010e068>] (dump_backtrace) from [<8010e3c4>] (show_stack+0x20/0x24)
[  228.398374]  r7:ffffffff r6:00000000 r5:600d0013 r4:80e962a0
[  228.398393] [<8010e3a4>] (show_stack) from [<80910f24>] (dump_stack+0xd4/0x118)
[  228.398407] [<80910e50>] (dump_stack) from [<801206a4>] (__warn+0xe0/0x108)
[  228.398420]  r10:7f131c4c r9:00000001 r8:00000009 r7:0000075a r6:7f1b75b0 r5:00000009
[  228.398426]  r4:7f1bcae0 r3:00000000
[  228.398437] [<801205c4>] (__warn) from [<80120a70>] (warn_slowpath_fmt+0x74/0xcc)
[  228.398447]  r7:7f1b75b0 r6:0000075a r5:7f1bcae0 r4:00000000
[  228.398480] [<80120a00>] (warn_slowpath_fmt) from [<7f1b75b0>] (__vb2_queue_cancel+0x244/0x2c0 [videobuf2_common])
[  228.398491]  r8:9cc3dbc8 r7:9c083c0c r6:00000009 r5:9c083c0c r4:9c083c0c
[  228.398543] [<7f1b736c>] (__vb2_queue_cancel [videobuf2_common]) from [<7f1b8ae8>] (vb2_core_streamoff+0x28/0xb4 [videobuf2_common])
[  228.398555]  r10:7f131c4c r9:00000001 r8:9cc3dbc8 r7:7f117dd0 r6:00000009 r5:9c083c0c
[  228.398561]  r4:9c083c0c r3:00000009
[  228.398618] [<7f1b8ac0>] (vb2_core_streamoff [videobuf2_common]) from [<7f1d5fa4>] (vb2_streamoff+0x24/0x60 [videobuf2_v4l2])
[  228.398625]  r5:9c083c0c r4:9c083c00
[  228.398673] [<7f1d5f80>] (vb2_streamoff [videobuf2_v4l2]) from [<7f18bd18>] (v4l2_m2m_streamoff+0x40/0x10c [v4l2_mem2mem])
[  228.398714] [<7f18bcd8>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<7f18be04>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
[  228.398727]  r10:7f131c4c r9:00000001 r8:9cc3dbc8 r7:7f117dd0 r6:00000000 r5:40045613
[  228.398732]  r4:7f18bde4
[  228.398905] [<7f18bde4>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<7f117df8>] (v4l_streamoff+0x28/0x2c [videodev])
[  228.399107] [<7f117dd0>] (v4l_streamoff [videodev]) from [<7f11cbec>] (__video_do_ioctl+0x240/0x470 [videodev])
[  228.399114]  r5:40045613 r4:9cc3d8a0
[  228.399312] [<7f11c9ac>] (__video_do_ioctl [videodev]) from [<7f11d1c0>] (video_usercopy+0x220/0x650 [videodev])
[  228.399323]  r10:9beefe0c r9:00000004 r8:7f11c9ac r7:00000001 r6:00000000 r5:00000000
[  228.399328]  r4:40045613
[  228.399527] [<7f11cfa0>] (video_usercopy [videodev]) from [<7f11d610>] (video_ioctl2+0x20/0x24 [videodev])
[  228.399542]  r10:00000036 r9:0000003a r8:9cdef180 r7:019d91d0 r6:40045613 r5:9ce793d0
[  228.399547]  r4:7f11d5f0
[  228.399742] [<7f11d5f0>] (video_ioctl2 [videodev]) from [<7f1161f4>] (v4l2_ioctl+0x4c/0x60 [videodev])
[  228.399856] [<7f1161a8>] (v4l2_ioctl [videodev]) from [<80308938>] (do_vfs_ioctl+0x3cc/0x7f4)
[  228.399863]  r5:9ce793d0 r4:019d91d0
[  228.399879] [<8030856c>] (do_vfs_ioctl) from [<80308da4>] (ksys_ioctl+0x44/0x70)
[  228.399891]  r10:00000036 r9:9beee000 r8:9cdef180 r7:019d91d0 r6:40045613 r5:0000003a
[  228.399896]  r4:9cdef181
[  228.399913] [<80308d60>] (ksys_ioctl) from [<80308de8>] (sys_ioctl+0x18/0x1c)
[  228.399927]  r9:9beee000 r8:801011c4 r7:00000036 r6:6a4ff7e4 r5:6a4ff000 r4:019d4300
[  228.399942] [<80308dd0>] (sys_ioctl) from [<80101000>] (ret_fast_syscall+0x0/0x28)
[  228.399949] Exception stack(0x9beeffa8 to 0x9beefff0)
[  228.399960] ffa0:                   019d4300 6a4ff000 0000003a 40045613 019d91d0 4a676091
[  228.399971] ffc0: 019d4300 6a4ff000 6a4ff7e4 00000036 019d9450 019e2388 00001407 4ae74678
[  228.399979] ffe0: 4ae733bc 7eb3ab24 6a4d06a5 4a676098
[  228.399991] ---[ end trace 566a229dbfdfd722 ]---
[  228.400007] videobuf2_common: driver bug: stop_streaming operation is leaving buf d7c9d963 in active state
[  228.400026] videobuf2_common: driver bug: stop_streaming operation is leaving buf 439ca233 in active state
[  267.118243] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Timeout waiting for buffers to be returned - 6 outstanding
timemaster5 commented 4 years ago

there has been some progress in suspiciously similar issue https://github.com/raspberrypi/linux/issues/3325#issuecomment-684040830, is it helpful?

hailfinger commented 3 years ago

@timemaster5 This might be fixed in firmware release edf2e9c318863999c97c50cdb74eee235ede3af5 which will hopefully reach your Pi with a regular update soon.

timemaster5 commented 3 years ago

@hailfinger thank you for letting me know.. I use a custom distribution build with Yocto, so will try to pull this version manually

timemaster5 commented 3 years ago

however, struggling with finding this.. is it a commit id in the raspberrypi/firmware repo?

pelwell commented 3 years ago

That's probably the build version (commit hash for the source code) - the correct hash for the firmware repo is https://github.com/raspberrypi/firmware/commit/20081d8e86119e95e516526700be62049850c01a, or https://github.com/Hexxeh/rpi-firmware/commit/c0cf93a133dab106439c208f03d32155bc19e432 for rpi-update.

alecov commented 3 years ago

Facing the same issue here, the system crashes when streaming video via any browser. Sometimes there is no log available.

This is from my crash:

May 25 20:29:37 raspberrypi kernel: [ 1178.638469] ------------[ cut here ]------------
May 25 20:29:37 raspberrypi kernel: [ 1178.638491] WARNING: CPU: 0 PID: 5964 at drivers/media/common/videobuf2/videobuf2-core.c:1945 __vb2_queue_cancel+0x1e0/0x258 [videobuf2_common]
May 25 20:29:37 raspberrypi kernel: [ 1178.638496] Modules linked in: binfmt_misc rfcomm cmac bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc joydev v3d brcmfmac brcmutil gpu_sched sha256_generic cfg80211 rfkill sg vc4 cec raspberrypi_hwmon bcm2835_codec(C) v4l2_mem2mem drm_kms_helper bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_mmal_vchiq(C) videobuf2_vmalloc vc_sm_cma(C) videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common videodev snd_bcm2835(C) mc drm rpivid_mem drm_panel_orientation_quirks snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer snd syscopyarea sysfillrect sysimgblt fb_sys_fops backlight uio_pdrv_genirq nvmem_rmem uio ip_tables x_tables ipv6
May 25 20:29:37 raspberrypi kernel: [ 1178.638785] CPU: 0 PID: 5964 Comm: WebKitWebProces Tainted: G         C        5.10.17-v7l+ #1414
May 25 20:29:37 raspberrypi kernel: [ 1178.638788] Hardware name: BCM2711
May 25 20:29:37 raspberrypi kernel: [ 1178.638792] Backtrace: 
May 25 20:29:37 raspberrypi kernel: [ 1178.638810] [<c0b63050>] (dump_backtrace) from [<c0b633e4>] (show_stack+0x20/0x24)
May 25 20:29:37 raspberrypi kernel: [ 1178.638815]  r7:ffffffff r6:00000000 r5:60000013 r4:c12e69fc
May 25 20:29:37 raspberrypi kernel: [ 1178.638821] [<c0b633c4>] (show_stack) from [<c0b67774>] (dump_stack+0xcc/0xf8)
May 25 20:29:37 raspberrypi kernel: [ 1178.638829] [<c0b676a8>] (dump_stack) from [<c0220bac>] (__warn+0xfc/0x114)
May 25 20:29:37 raspberrypi kernel: [ 1178.638834]  r10:bf2328dc r9:00000009 r8:bf0dc6b4 r7:00000799 r6:00000009 r5:bf0dc6b4
May 25 20:29:37 raspberrypi kernel: [ 1178.638838]  r4:bf0e1f90 r3:c1205094
May 25 20:29:37 raspberrypi kernel: [ 1178.638844] [<c0220ab0>] (__warn) from [<c0b63b54>] (warn_slowpath_fmt+0x70/0xd8)
May 25 20:29:37 raspberrypi kernel: [ 1178.638848]  r7:00000799 r6:bf0e1f90 r5:c1205048 r4:00000000
May 25 20:29:37 raspberrypi kernel: [ 1178.638860] [<c0b63ae8>] (warn_slowpath_fmt) from [<bf0dc6b4>] (__vb2_queue_cancel+0x1e0/0x258 [videobuf2_common])
May 25 20:29:37 raspberrypi kernel: [ 1178.638865]  r9:bf240098 r8:c272abe0 r7:00000001 r6:c480e014 r5:c480e014 r4:c480e014
May 25 20:29:37 raspberrypi kernel: [ 1178.638881] [<bf0dc4d4>] (__vb2_queue_cancel [videobuf2_common]) from [<bf0dd6b4>] (vb2_core_streamoff+0x28/0xbc [videobuf2_common])
May 25 20:29:37 raspberrypi kernel: [ 1178.638886]  r10:bf2328dc r9:bf240098 r8:c272abe0 r7:00000001 r6:00000009 r5:c480e014
May 25 20:29:37 raspberrypi kernel: [ 1178.638889]  r4:c480e014 r3:00000009
May 25 20:29:37 raspberrypi kernel: [ 1178.638906] [<bf0dd68c>] (vb2_core_streamoff [videobuf2_common]) from [<bf17b0f8>] (vb2_streamoff+0x24/0x64 [videobuf2_v4l2])
May 25 20:29:37 raspberrypi kernel: [ 1178.638910]  r5:c480e014 r4:c480e000
May 25 20:29:37 raspberrypi kernel: [ 1178.638926] [<bf17b0d4>] (vb2_streamoff [videobuf2_v4l2]) from [<bf224f08>] (v4l2_m2m_streamoff+0x40/0x10c [v4l2_mem2mem])
May 25 20:29:37 raspberrypi kernel: [ 1178.638940] [<bf224ec8>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<bf224ff4>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
May 25 20:29:37 raspberrypi kernel: [ 1178.638945]  r10:bf2328dc r9:bf240098 r8:c272abe0 r7:00000001 r6:c1205048 r5:40045613
May 25 20:29:37 raspberrypi kernel: [ 1178.638948]  r4:bf224fd4
May 25 20:29:37 raspberrypi kernel: [ 1178.638989] [<bf224fd4>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<bf2400c4>] (v4l_streamoff+0x2c/0x30 [videodev])
May 25 20:29:37 raspberrypi kernel: [ 1178.639040] [<bf240098>] (v4l_streamoff [videodev]) from [<bf245114>] (__video_do_ioctl+0x234/0x460 [videodev])
May 25 20:29:37 raspberrypi kernel: [ 1178.639044]  r5:40045613 r4:c272a8a0
May 25 20:29:37 raspberrypi kernel: [ 1178.639092] [<bf244ee0>] (__video_do_ioctl [videodev]) from [<bf245b28>] (video_usercopy+0x128/0x5ac [videodev])
May 25 20:29:37 raspberrypi kernel: [ 1178.639097]  r10:c6f05e3c r9:79124e18 r8:00000000 r7:c663ec00 r6:c1205048 r5:40045613
May 25 20:29:37 raspberrypi kernel: [ 1178.639100]  r4:40045613
May 25 20:29:37 raspberrypi kernel: [ 1178.639147] [<bf245a00>] (video_usercopy [videodev]) from [<bf245fcc>] (video_ioctl2+0x20/0x24 [videodev])
May 25 20:29:37 raspberrypi kernel: [ 1178.639152]  r10:00000054 r9:c6f04000 r8:00000000 r7:c663ec00 r6:c663ec01 r5:c1205048
May 25 20:29:37 raspberrypi kernel: [ 1178.639156]  r4:bf245fac
May 25 20:29:37 raspberrypi kernel: [ 1178.639205] [<bf245fac>] (video_ioctl2 [videodev]) from [<bf23e1f4>] (v4l2_ioctl+0x4c/0x60 [videodev])
May 25 20:29:37 raspberrypi kernel: [ 1178.639237] [<bf23e1a8>] (v4l2_ioctl [videodev]) from [<c045178c>] (sys_ioctl+0x1d4/0x8ec)
May 25 20:29:37 raspberrypi kernel: [ 1178.639242]  r5:c1205048 r4:40045613
May 25 20:29:37 raspberrypi kernel: [ 1178.639248] [<c04515b8>] (sys_ioctl) from [<c0200040>] (ret_fast_syscall+0x0/0x28)
May 25 20:29:37 raspberrypi kernel: [ 1178.639252] Exception stack(0xc6f05fa8 to 0xc6f05ff0)
May 25 20:29:37 raspberrypi kernel: [ 1178.639257] 5fa0:                   a75d6b90 78dde000 00000054 40045613 79124e18 b0368510
May 25 20:29:37 raspberrypi kernel: [ 1178.639261] 5fc0: a75d6b90 78dde000 78dde7d0 00000036 9ef0bd48 00000001 8603b080 ab550fbc
May 25 20:29:37 raspberrypi kernel: [ 1178.639265] 5fe0: b117ec60 be8e036c 78da6954 b036851c
May 25 20:29:37 raspberrypi kernel: [ 1178.639270]  r10:00000036 r9:c6f04000 r8:c0200204 r7:00000036 r6:78dde7d0 r5:78dde000
May 25 20:29:37 raspberrypi kernel: [ 1178.639273]  r4:a75d6b90
May 25 20:29:37 raspberrypi kernel: [ 1178.639278] ---[ end trace afd83ae938f3abf0 ]---
May 25 20:29:37 raspberrypi kernel: [ 1178.639285] videobuf2_common: driver bug: stop_streaming operation is leaving buf 379ac7f3 in active state
May 25 20:29:37 raspberrypi kernel: [ 1178.639293] videobuf2_common: driver bug: stop_streaming operation is leaving buf ca7b0c4f in active state
May 25 20:29:37 raspberrypi kernel: [ 1178.639300] videobuf2_common: driver bug: stop_streaming operation is leaving buf a1e29602 in active state

uname:

Linux raspberrypi 5.10.17-v7l+ #1414 SMP Fri Apr 30 13:20:47 BST 2021 armv7l GNU/Linux

firmware:

Apr 30 2021 13:45:52 
Copyright (c) 2012 Broadcom
version d7f29d96450abfc77cd6cf011af1faf1e03e5e56 (clean) (release) (start)

FWIW, I've tested the aarch64 (beta) release from RaspiOS and the issue is still there.

EDIT: I've just faced this crash just by merely opening Midori (without loading any page). /var/log/messages got corrupted, so nothing informative, though I'm pretty sure this is the same bug.

adalava commented 3 years ago

I'm still getting similar error while decoding h264 from IP cameras using gstreamer, no luck so far. Kernel "4.19.118-v7+ #1311 SMP Mon Apr 27 14:21:24 BST 2020" seems stable, I'm not hitting this problem after several weeks.

I'll upgrade to Hexxeh/rpi-firmware@c0cf93a as soon as possible.

timemaster5 commented 2 years ago

Do we have any progress or clues here? Or even workaround from the others. I want to help somehow, but I am out of ideas. I feel it like the vc4 opensource driver is just not ready yet.

Last week, I did some tests with the userland driver and was able to play videos in a loop without significant issues. Nothing in the kernel log at least :) Only GStreamer had something to tell, but I guess it wasn't substantial enough to break something.

I tried even the newest bullseye firmware, but the situation is the same. The only noticeable difference between the old kernel 4.19 and 5.4 and 5.10 was that in 4.19, after the video crashed, the new one didn't start. On the newer kernel, the new loop starts playing, but kernel log keeps growing of those messages :(

hailfinger commented 2 years ago

Try adding over_voltage=2 to config.txt. If that doesn't help, try increasing until over_voltage=6. For my fleet of ~150 devices, a majority will behave with over_voltage=2, those which are still not fixed get over_voltage=4, and the still unfixed remainder gets over_voltage=6 (roughly 5% of my devices need that). Three devices still don't work reliably even with over_voltage=6, but I'll remove those from production soon.

Despite claims to the contrary, these buffers will accumulate (every time the error message gets repeated, the reported number of buffers increases) and eventually playing videos will fail. Since my devices are in production, those which cannot be fixed even with over_voltage=6 get regular scheduled reboots. That's a horrible workaround, but at least it's a workaround.

timemaster5 commented 2 years ago

Hi @hailfinger, thank you for your response. I found your thread somewhere else some time ago and immediately thought, hey, that's my missing bit, but it wasn't :( I tried over_voltage up to 6, then even more, but the problem is still there. And it is immediate. I mean, this error log appears the first time the video plays and then with every loop. I don't need to wait hours for it :( That is why I am quite surprised no one can sort it.

If I'm correct, you were on raspberry pi 4, is that right?. Here I am on the Compute Module 3+.

hailfinger commented 2 years ago

Ah yes, that might explain the difference. I'm on a Raspberry Pi 4B.

timemaster5 commented 2 years ago

I believe it is an issue with the hardware itself. All is fine with userland on CM3+ or Rpi3b+, so the decoder is not "broken", but as userland is the closed source, I guess the vc4 driver does something potentially right from the general point of view, but BCM requires something specific, maybe more non-standard to work correctly in this case.

The reason why this is haven't been fixed, I guess, is because of this difference in board versions. Many people successfully resolved this issue with the newer firmware release, but they were on Rpi 4. On Rpi 3, this has never been fixed and maybe not even looked into.

6by9 commented 2 years ago

I believe it is an issue with the hardware itself.

It's not. You say it yourself:

All is fine with userland on CM3+ or Rpi3b+

The V4L2 driver uses exactly the same parts of the firmware, but there is a path that I believe I know what the issue is, but haven't had time to investigate (partly as I don't have a reliable route to reproduce).

I've said it multiple times, videobuf2_common: driver bug: stop_streaming operation is leaving buf XXXXXX in active state is not a fatal issue.

timemaster5 commented 2 years ago

I believe it is an issue with the hardware itself.

It's not. You say it yourself:

All is fine with userland on CM3+ or Rpi3b+

I am sorry for the misunderstanding. The context is further in the following sentence. I believe it is hardware-specific, not a hardware bug, just a specific way we need to treat BCM here. I don't know much about documentation available for this specific bit, but in general, I know it is let's say more problematic with Broadcom.

I've said it multiple times, videobuf2_common: driver bug: stop_streaming operation is leaving buf XXXXXX in active state is not a fatal issue.

I have to disagree here. This cause system lockup and the only variable is time. If you have a short 10s video you want to play in a loop, the number of buffers left in the active state increase every 10s. It is worse on the 4.19 kernel, where the new video loop doesn't even start, and you can't reboot the system to fix it because it will not boot again. The only way to fix it is to power cycle.

It is much better on 5.4. and up, where the video can play, but at some point, the number of buffers left is just too high. I don't know whether the memory runs out or there is no new buffer available for the next video loop.

The V4L2 driver uses exactly the same parts of the firmware, but there is a path that I believe I know what the issue is, but haven't had time to investigate (partly as I don't have a reliable route to reproduce).

I am happy to help. If you want, I can build you an image with all the tools you need and some example video so you can just flash and immediately see what is wrong.

timemaster5 commented 2 years ago

Linking bugs and pull requests, which I believe are related. https://github.com/raspberrypi/linux/issues/4824 https://github.com/raspberrypi/linux/issues/4606 https://github.com/raspberrypi/linux/pull/4765

tysonite commented 2 years ago

Same on Linux 5.10.92-v7l+ #1514 SMP Mon Jan 17 17:38:03 GMT 2022 armv7l GNU/Linux with GStreamer and web camera.

[363583.786353] restoring control 00000000-0000-0000-0000-000000000101/3/7
[363583.786358] restoring control 00000000-0000-0000-0000-000000000101/6/10
[363583.786364] restoring control 00000000-0000-0000-0000-000000000101/9/4
[363583.786369] restoring control 00000000-0000-0000-0000-000000000101/12/11
[364321.215193] restoring control 00000000-0000-0000-0000-000000000001/1/2
[364321.215203] restoring control 00000000-0000-0000-0000-000000000001/3/4
[364321.215209] restoring control 00000000-0000-0000-0000-000000000001/5/6
[364321.215215] restoring control 00000000-0000-0000-0000-000000000001/17/8
[364321.215615] restoring control 00000000-0000-0000-0000-000000000101/0/2
[364321.215622] restoring control 00000000-0000-0000-0000-000000000101/1/3
[364321.215627] restoring control 00000000-0000-0000-0000-000000000101/3/7
[364321.215634] restoring control 00000000-0000-0000-0000-000000000101/6/10
[364321.215639] restoring control 00000000-0000-0000-0000-000000000101/9/4
[364321.215645] restoring control 00000000-0000-0000-0000-000000000101/12/11
[364325.758121] restoring control 00000000-0000-0000-0000-000000000001/1/2
[364325.758129] restoring control 00000000-0000-0000-0000-000000000001/3/4
[364325.758135] restoring control 00000000-0000-0000-0000-000000000001/5/6
[364325.758141] restoring control 00000000-0000-0000-0000-000000000001/17/8
[364325.758517] restoring control 00000000-0000-0000-0000-000000000101/0/2
[364325.758523] restoring control 00000000-0000-0000-0000-000000000101/1/3
[364325.758528] restoring control 00000000-0000-0000-0000-000000000101/3/7
[364325.758534] restoring control 00000000-0000-0000-0000-000000000101/6/10
[364325.758539] restoring control 00000000-0000-0000-0000-000000000101/9/4
[364325.758545] restoring control 00000000-0000-0000-0000-000000000101/12/11
[364591.527886] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 23 outstanding
[364591.528097] ------------[ cut here ]------------
[364591.528120] WARNING: CPU: 1 PID: 27736 at drivers/media/common/videobuf2/videobuf2-core.c:1956 __vb2_queue_cancel+0x1e0/0x258 [videobuf2_common]
[364591.528126] Modules linked in: rfcomm cmac algif_hash aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc 8021q garp stp llc spidev tc358743 snd_soc_hdmi_codec brcmfmac brcmutil snd_usb_audio snd_hwdep snd_usbmidi_lib cfg80211 rfkill uvcvideo snd_rawmidi snd_seq_device bcm2835_codec(C) v4l2_mem2mem v3d spi_bcm2835 gpu_sched snd_soc_simple_card snd_soc_simple_card_utils snd_soc_spdif_rx raspberrypi_hwmon bcm2835_isp(C) bcm2835_unicam bcm2835_v4l2(C) videobuf2_dma_contig v4l2_dv_timings bcm2835_mmal_vchiq(C) v4l2_fwnode videobuf2_vmalloc i2c_mux_pinctrl i2c_brcmstb videobuf2_memops i2c_mux videobuf2_v4l2 i2c_bcm2835 videobuf2_common videodev mc snd_soc_bcm2835_i2s vc4 snd_bcm2835(C) vc_sm_cma(C) cec drm_kms_helper rpivid_mem snd_soc_core snd_compress snd_pcm_dmaengine snd_pcm snd_timer uio_pdrv_genirq uio ir_rc6_decoder snd syscopyarea sysfillrect sysimgblt fb_sys_fops gpio_ir_tx nvmem_rmem gpio_ir_recv i2c_dev drm drm_panel_orientation_quirks
[364591.528520]  backlight fuse ip_tables x_tables ipv6
[364591.528552] CPU: 1 PID: 27736 Comm: gst-launch-1.0 Tainted: G         C        5.10.92-v7l+ #1514
[364591.528555] Hardware name: BCM2711
[364591.528559] Backtrace:
[364591.528574] [<c0b87728>] (dump_backtrace) from [<c0b87abc>] (show_stack+0x20/0x24)
[364591.528580]  r7:ffffffff r6:00000000 r5:60000013 r4:c12e6fd8
[364591.528587] [<c0b87a9c>] (show_stack) from [<c0b8be9c>] (dump_stack+0xcc/0xf8)
[364591.528595] [<c0b8bdd0>] (dump_stack) from [<c0220d2c>] (__warn+0xfc/0x114)
[364591.528600]  r10:ffffe000 r9:00000009 r8:bf40f6b4 r7:000007a4 r6:00000009 r5:bf40f6b4
[364591.528604]  r4:bf414f90 r3:c1205094
[364591.528610] [<c0220c30>] (__warn) from [<c0b8821c>] (warn_slowpath_fmt+0x70/0xd8)
[364591.528614]  r7:000007a4 r6:bf414f90 r5:c1205048 r4:00000000
[364591.528627] [<c0b881b0>] (warn_slowpath_fmt) from [<bf40f6b4>] (__vb2_queue_cancel+0x1e0/0x258 [videobuf2_common])
[364591.528631]  r9:00000000 r8:c25bb5d8 r7:c28fa790 r6:c4e27414 r5:c4e27474 r4:c4e27414
[364591.528649] [<bf40f4d4>] (__vb2_queue_cancel [videobuf2_common]) from [<bf411cf8>] (vb2_core_queue_release+0x28/0x48 [videobuf2_common])
[364591.528654]  r10:ffffe000 r9:00000000 r8:c25bb5d8 r7:c28fa790 r6:c2f663e0 r5:c4e27474
[364591.528657]  r4:c4e27414 r3:1c02cd6b
[364591.528674] [<bf411cd0>] (vb2_core_queue_release [videobuf2_common]) from [<bf1a4850>] (vb2_queue_release+0x18/0x1c [videobuf2_v4l2])
[364591.528678]  r5:c4c59000 r4:c4e27400
[364591.528693] [<bf1a4838>] (vb2_queue_release [videobuf2_v4l2]) from [<bf39b37c>] (v4l2_m2m_ctx_release+0x24/0x38 [v4l2_mem2mem])
[364591.528707] [<bf39b358>] (v4l2_m2m_ctx_release [v4l2_mem2mem]) from [<bf3ac7f4>] (bcm2835_codec_release+0x7c/0xc8 [bcm2835_codec])
[364591.528711]  r5:c4c59000 r4:c2f66040
[364591.528749] [<bf3ac778>] (bcm2835_codec_release [bcm2835_codec]) from [<bf30c6e0>] (v4l2_release+0xd8/0xe4 [videodev])
[364591.528753]  r7:c28fa790 r6:000e001f r5:c4f2a0c0 r4:c2f660a0
[364591.528786] [<bf30c608>] (v4l2_release [videodev]) from [<c0440af0>] (__fput+0x90/0x25c)
[364591.528789]  r5:c3499b68 r4:c4f2a0c0
[364591.528795] [<c0440a60>] (__fput) from [<c0440cd4>] (____fput+0x18/0x1c)
[364591.528799]  r9:00000000 r8:c1356d6c r7:c1981f00 r6:c1982454 r5:c4f02600 r4:c4f2a0c0
[364591.528808] [<c0440cbc>] (____fput) from [<c0242c88>] (task_work_run+0xb4/0xe4)
[364591.528815] [<c0242bd4>] (task_work_run) from [<c02258a8>] (do_exit+0x498/0xb88)
[364591.528820]  r9:00000000 r8:c6673044 r7:c5b91e94 r6:ffffe000 r5:c6673000 r4:c1981f00
[364591.528825] [<c0225410>] (do_exit) from [<c0226034>] (do_group_exit+0x50/0xe0)
[364591.528829]  r7:c3341500
[364591.528836] [<c0225fe4>] (do_group_exit) from [<c0233c04>] (get_signal+0x1c0/0xae0)
[364591.528840]  r7:c3341500 r6:00000008 r5:00000000 r4:00418004
[364591.528846] [<c0233a44>] (get_signal) from [<c020b994>] (do_work_pending+0x498/0x5a8)
[364591.528851]  r10:c1205048 r9:fffffe30 r8:5ac3c35a r7:c5b91f44 r6:b6b8c734 r5:c5b91fb0
[364591.528854]  r4:ffffe000
[364591.528859] [<c020b4fc>] (do_work_pending) from [<c0200074>] (slow_work_pending+0xc/0x20)
[364591.528863] Exception stack(0xc5b91fb0 to 0xc5b91ff8)
[364591.528867] 1fa0:                                     00b27f98 00000002 ffffffff 00000000
[364591.528872] 1fc0: 00b27f98 b6f482c0 ffffffff 000000a8 bee8f628 ffffffff 00000001 00000000
[364591.528877] 1fe0: 00000000 bee8f600 00000000 b6b8c734 80000010 00b27f98
[364591.528882]  r10:000000a8 r9:c5b90000 r8:c0200204 r7:000000a8 r6:ffffffff r5:b6f482c0
[364591.528886]  r4:00b27f98
[364591.528890] ---[ end trace 04e3ac58609ee0e7 ]---
[364591.528898] videobuf2_common: driver bug: stop_streaming operation is leaving buf ccec6edb in active state
[364591.528906] videobuf2_common: driver bug: stop_streaming operation is leaving buf 513295fd in active state
[364591.528913] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0ad0a4c2 in active state
[364591.528920] videobuf2_common: driver bug: stop_streaming operation is leaving buf ddd2b210 in active state
[364591.528928] videobuf2_common: driver bug: stop_streaming operation is leaving buf 20dab796 in active state
[364591.528935] videobuf2_common: driver bug: stop_streaming operation is leaving buf d7f39b19 in active state
[364591.528942] videobuf2_common: driver bug: stop_streaming operation is leaving buf 39cb1b70 in active state
[364591.528949] videobuf2_common: driver bug: stop_streaming operation is leaving buf 77fd10f1 in active state
[364591.528957] videobuf2_common: driver bug: stop_streaming operation is leaving buf 60992429 in active state
[364591.528964] videobuf2_common: driver bug: stop_streaming operation is leaving buf 7346b1e3 in active state
[364591.528971] videobuf2_common: driver bug: stop_streaming operation is leaving buf 4c92cbda in active state
[364591.528978] videobuf2_common: driver bug: stop_streaming operation is leaving buf da212de7 in active state
[364591.528985] videobuf2_common: driver bug: stop_streaming operation is leaving buf 46fc3f17 in active state
[364591.528993] videobuf2_common: driver bug: stop_streaming operation is leaving buf d88ea0cf in active state
[364591.529000] videobuf2_common: driver bug: stop_streaming operation is leaving buf 3e88bbd9 in active state
[364591.529007] videobuf2_common: driver bug: stop_streaming operation is leaving buf 43cb6e9f in active state
[364591.529014] videobuf2_common: driver bug: stop_streaming operation is leaving buf 79fd4e02 in active state
[364591.529022] videobuf2_common: driver bug: stop_streaming operation is leaving buf 1b1cdb87 in active state
[364591.529029] videobuf2_common: driver bug: stop_streaming operation is leaving buf 87bbcbf6 in active state
[364591.529037] videobuf2_common: driver bug: stop_streaming operation is leaving buf b3ddc833 in active state
[364591.529044] videobuf2_common: driver bug: stop_streaming operation is leaving buf 5705413d in active state
[364591.529051] videobuf2_common: driver bug: stop_streaming operation is leaving buf 051591ab in active state
[364591.529058] videobuf2_common: driver bug: stop_streaming operation is leaving buf ae93b7f0 in active state
nicoske commented 1 year ago

Facing the same issue when looping a 30s video from WPEWebkit on latest kernel 6.1.13-v7l.

Feb 27 11:47:01 pi-ibbdis-865a7b kernel: ------------[ cut here ]------------
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: WARNING: CPU: 3 PID: 343 at drivers/media/common/videobuf2/videobuf2-core.c:2035 __vb2_queue_cancel+0x23c/0x2b8 [videobuf2_common]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: Modules linked in: vc4 snd_soc_hdmi_codec drm_display_helper cec drm_dma_helper drm_kms_helper brcmfmac brcmutil snd_soc_core bcm2835_codec(C) bcm2835_isp(C) snd_compress bcm2835_v4l2(C) bcm2835_mmal_vchiq(C) v4l2_mem2mem snd_pcm_dmaengine videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 cfg80211 raspberrypi_hwmon videobuf2_common syscopyarea snd_bcm2835(C) sysfillrect sysimgblt fb_sys_fops rfkill snd_pcm videodev i2c_bcm2835 snd_timer snd vc_sm_cma(C) uio_pdrv_genirq uio ipt_REJECT nf_reject_ipv4 xt_limit xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_addrtype xt_tcpudp iptable_filter sch_fq_codel drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: CPU: 3 PID: 343 Comm: WPEWebProcess Tainted: G        WC         6.1.13-v7l #1
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: Hardware name: BCM2835
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  unwind_backtrace from show_stack+0x18/0x1c
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  show_stack from dump_stack_lvl+0x68/0x8c
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  dump_stack_lvl from __warn+0x84/0x11c
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  __warn from warn_slowpath_fmt+0x80/0xbc
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  warn_slowpath_fmt from __vb2_queue_cancel+0x23c/0x2b8 [videobuf2_common]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  __vb2_queue_cancel [videobuf2_common] from vb2_core_streamoff+0x20/0xb4 [videobuf2_common]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  vb2_core_streamoff [videobuf2_common] from v4l2_m2m_streamoff+0x44/0x108 [v4l2_mem2mem]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  v4l2_m2m_streamoff [v4l2_mem2mem] from __video_do_ioctl+0x240/0x490 [videodev]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  __video_do_ioctl [videodev] from video_usercopy+0x2a0/0x610 [videodev]
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  video_usercopy [videodev] from sys_ioctl+0x110/0xa14
Feb 27 11:47:01 pi-ibbdis-865a7b kernel:  sys_ioctl from __sys_trace_return+0x0/0x10
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: Exception stack(0xf0a9dfa8 to 0xf0a9dff0)
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: dfa0:                   a3c798ec a3c7a14c 00000027 40045613 a6a80788 beb5e870
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: dfc0: a3c798ec a3c7a14c a24ea420 00000036 a223a1c0 a244fb50 b166cc5d b40c64b4
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: dfe0: 00000036 beb5e858 b3d96a49 b3d124e6
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: ---[ end trace 0000000000000000 ]---
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: videobuf2_common: driver bug: stop_streaming operation is leaving buf ad8b427c in active state
Feb 27 11:47:01 pi-ibbdis-865a7b kernel: videobuf2_common: driver bug: stop_streaming operation is leaving buf 999aa935 in active state
ph818 commented 1 year ago

I was experiencing crashes streaming videos from Youtube to the "Tubecast" app on Kodi. Both from the android Youtube App and Chromium's 'cast' feature.

I get this error message repeating in syslog when casting from Chromium, right before the system becomes unresponsive.

###More of the same, about 10 messages total####
Mar 10 11:22:11 patpi4raspios64 kernel: [  564.938623] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000038107b06 in active state
Mar 10 11:22:11 patpi4raspios64 kernel: [  564.938630] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000024d8e299 in active state
Mar 10 11:22:11 patpi4raspios64 kernel: [  564.938637] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000de5b842c in active state
###Crashed here#####

When I stream from the youtube app on android, it gives stuff like this in syslog:

Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787703] x29: ffffffc010eebac0 x28: 0000000000000000 x27: ffffff8043d54080
Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787730] x20: 0000000000000000 x19: ffffff8047280178 x18: 0000000000000000
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278578] sp : ffffffc010eebaf0
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278582] x29: ffffffc010eebaf0 x28: 0000000000000000 x27: ffffffc010eebd28
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278591] x26: 0000000000000000 x25: ffffff804308cf00 x24: ffffff8043d54628
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278600] x23: 0000000000000001 x22: ffffffe2490989a8 x21: ffffff804702a298
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278609] x20: ffffff804702a298 x19: ffffff804702a298 x18: 0000000000000029
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278618] x17: 00400000000002ee x16: ffffffe2484c76a8 x15: ffffff8047280030
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278626] x14: ffffff805cdc7f08 x13: 0000000000000000 x12: 0000000000000000
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278634] x11: ffffff805cdc7d98 x10: ffffff8047280038 x9 : ffffffe2484c79dc
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278643] x8 : 0000000080100009 x7 : 0000000000000000 x6 : 0000000000000000
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278651] x5 : ffffffe1f75572b4 x4 : fffffffe01acd920 x3 : ffffff806b364c00
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278660] x2 : fffffffe01acd920 x1 : 2ea77266622b8d00 x0 : 0000000000000009
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278668] Call trace:
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278672]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278686]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278699]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278711]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278737]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278749]  v4l_streamoff+0x2c/0x38 [videodev]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278810]  __video_do_ioctl+0x188/0x410 [videodev]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278841]  video_usercopy+0x310/0x7d0 [videodev]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278871]  video_ioctl2+0x20/0x38 [videodev]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278902]  v4l2_ioctl+0x48/0x68 [videodev]
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278932]  __arm64_sys_ioctl+0xb0/0xf0
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278950]  invoke_syscall+0x4c/0x110
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278963]  el0_svc_common.constprop.3+0xfc/0x120
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278969]  do_el0_svc+0x2c/0x90
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278975]  el0_svc+0x24/0x60
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278987]  el0t_64_sync_handler+0x90/0xb8
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278991]  el0t_64_sync+0x1a0/0x1a4
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.279002] ---[ end trace 24e2c228a4c4c555 ]---
####this didn't crash, just stopped the video####

and

Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787703] x29: ffffffc010eebac0 x28: 0000000000000000 x27: ffffff8043d54080
Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787730] x20: 0000000000000000 x19: ffffff8047280178 x18: 0000000000000000
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278578] sp : ffffffc010eebaf0
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278591] x26: 0000000000000000 x25: ffffff804308cf00 x24: ffffff8043d54628
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278600] x23: 0000000000000001 x22: ffffffe2490989a8 x21: ffffff804702a298
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278668] Call trace:
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278699]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590954] sp : ffffffc010eebaf0
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590958] x29: ffffffc010eebaf0 x28: 0000000000000000 x27: ffffffc010eebd28
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590967] x26: 0000000000000000 x25: ffffff804308cf00 x24: ffffff8043d54628
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590975] x23: 0000000000000001 x22: ffffffe2490989a8 x21: ffffff804702a298
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590984] x20: ffffff804702a298 x19: ffffff804702a298 x18: 0000000000000029
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.590992] x17: 0000000000000000 x16: ffffffe2484c76a8 x15: ffffff8047280030
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591000] x14: ffffff805cdc7f08 x13: 0000000000000000 x12: 0000000000000000
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591008] x11: ffffff805cdc7d98 x10: ffffff8047280038 x9 : ffffffe2484c79dc
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591016] x8 : 000000008010000d x7 : 0000000000000000 x6 : 0000000000000000
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591024] x5 : ffffffe1f75572b4 x4 : fffffffe01005ea0 x3 : ffffff804017a500
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591032] x2 : fffffffe01005ea0 x1 : 2ea77266622b8d00 x0 : 000000000000000e
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591041] Call trace:
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591045]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591058]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591070]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591082]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591099]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591110]  v4l_streamoff+0x2c/0x38 [videodev]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591158]  __video_do_ioctl+0x188/0x410 [videodev]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591189]  video_usercopy+0x310/0x7d0 [videodev]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591219]  video_ioctl2+0x20/0x38 [videodev]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591249]  v4l2_ioctl+0x48/0x68 [videodev]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591278]  __arm64_sys_ioctl+0xb0/0xf0
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591294]  invoke_syscall+0x4c/0x110
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591301]  el0_svc_common.constprop.3+0xfc/0x120
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591306]  do_el0_svc+0x2c/0x90
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591312]  el0_svc+0x24/0x60
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591318]  el0t_64_sync_handler+0x90/0xb8
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591322]  el0t_64_sync+0x1a0/0x1a4
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591328] ---[ end trace 24e2c228a4c4c556 ]---
#####this also didn't crash the system, just interrupted the youtube video, froze the picture, allowing the laggy audio to continue playing

here is another one

Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787703] x29: ffffffc010eebac0 x28: 0000000000000000 x27: ffffff8043d54080
Mar 10 11:49:20 patpi4raspios64 kernel: [ 1057.787730] x20: 0000000000000000 x19: ffffff8047280178 x18: 0000000000000000
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278578] sp : ffffffc010eebaf0
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278591] x26: 0000000000000000 x25: ffffff804308cf00 x24: ffffff8043d54628
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278600] x23: 0000000000000001 x22: ffffffe2490989a8 x21: ffffff804702a298
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278668] Call trace:
Mar 10 11:49:55 patpi4raspios64 kernel: [ 1092.278699]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591041] Call trace:
Mar 10 11:56:12 patpi4raspios64 kernel: [ 1469.591070]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653036] sp : ffffffc00d4e3af0
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653039] x29: ffffffc00d4e3af0 x28: 0000000000000000 x27: ffffffc00d4e3d28
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653049] x26: 0000000000000000 x25: ffffff8040947000 x24: ffffff8043d54628
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653058] x23: 0000000000000001 x22: ffffffe2490989a8 x21: ffffff8048621298
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653066] x20: ffffff8048621298 x19: ffffff8048621298 x18: 0000000000000015
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653074] x17: 0000000000000000 x16: ffffffe2484c76a8 x15: ffffff8047280030
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653082] x14: ffffff805cdc7e68 x13: 0000000000000000 x12: 0000000000000000
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653091] x11: ffffff805cdc7d98 x10: ffffff8047280038 x9 : ffffffe1f75572b4
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653099] x8 : ffffff805cdc7dc0 x7 : 0000000000000000 x6 : 0000000000000000
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653107] x5 : 0000000000000001 x4 : ffffff807fbc1e80 x3 : 0000000001dc2a03
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653115] x2 : ffffff804b728000 x1 : 2ea77266622b8d00 x0 : 000000000000000b
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653123] Call trace:
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653127]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653139]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653151]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653162]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653179]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653189]  v4l_streamoff+0x2c/0x38 [videodev]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653238]  __video_do_ioctl+0x188/0x410 [videodev]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653269]  video_usercopy+0x310/0x7d0 [videodev]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653299]  video_ioctl2+0x20/0x38 [videodev]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653329]  v4l2_ioctl+0x48/0x68 [videodev]
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653359]  __arm64_sys_ioctl+0xb0/0xf0
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653372]  invoke_syscall+0x4c/0x110
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653380]  el0_svc_common.constprop.3+0xfc/0x120
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653385]  do_el0_svc+0x2c/0x90
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653391]  el0_svc+0x24/0x60
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653398]  el0t_64_sync_handler+0x90/0xb8
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653402]  el0t_64_sync+0x1a0/0x1a4
Mar 10 12:01:04 patpi4raspios64 kernel: [ 1761.653407] ---[ end trace 24e2c228a4c4c557 ]---

Eventually the system will crash, which doesn't show any helpful messages, but does give a lot of this: "@^@^@^@^@^@^"

tetsuoMikami commented 1 year ago

I found a similar issue. I observed a video buffer crash when converting a UVC camera's MJPEG to H.264 and delivering it via RTSP. The time from the start of RTSP distribution until the crash occurs is approximately 1 to 3 hours. Crash happened in both RPi 4B and RPi 3B.

kernel 6.1.21-v8+ on RPi 4B

[ 6246.641801] ------------[ cut here ]------------
[ 6246.641822] WARNING: CPU: 1 PID: 894 at drivers/media/common/videobuf2/videobuf2-core.c:2035 __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[ 6246.641881] Modules linked in: cmac algif_hash aes_arm64 aes_generic algif_skcipher af_alg bnep snd_usb_audio uvcvideo snd_hwdep snd_usbmidi_lib cdc_ether snd_rawmidi snd_seq_device hci_uart btbcm bluetooth ecdh_generic ecc libaes 8021q garp stp llc brcmfmac brcmutil vc4 cfg80211 snd_soc_hdmi_codec drm_display_helper cec drm_dma_helper rfkill drm_kms_helper bcm2835_v4l2(C) bcm2835_isp(C) bcm2835_codec(C) rpivid_hevc(C) v3d bcm2835_mmal_vchiq(C) v4l2_mem2mem raspberrypi_hwmon snd_soc_core videobuf2_vmalloc videobuf2_dma_contig gpu_sched videobuf2_memops snd_compress snd_bcm2835(C) snd_pcm_dmaengine snd_pcm drm_shmem_helper videobuf2_v4l2 snd_timer videobuf2_common i2c_brcmstb snd syscopyarea videodev vc_sm_cma(C) sysfillrect sysimgblt mc fb_sys_fops uio_pdrv_genirq nvmem_rmem uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[ 6246.642197] CPU: 1 PID: 894 Comm: pool-test-launc Tainted: G         C         6.1.21-v8+ #1642
[ 6246.642210] Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT)
[ 6246.642217] pstate: 20000005 (nzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[ 6246.642229] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[ 6246.642266] lr : __vb2_queue_cancel+0x3c/0x220 [videobuf2_common]
[ 6246.642301] sp : ffffffc00949bae0
[ 6246.642307] x29: ffffffc00949bae0 x28: ffffffdcbb0a2938 x27: 0000000000000000
[ 6246.642327] x26: 0000000040045613 x25: ffffff8043985528 x24: 0000000000000000
[ 6246.642346] x23: ffffff80516aa600 x22: ffffffdd346ad858 x21: ffffff8048e16028
[ 6246.642364] x20: ffffff8048e16028 x19: ffffff8048e16028 x18: ffffff80468c0028
[ 6246.642382] x17: 0000000133ae8f08 x16: ffffffdd34369bb0 x15: ffffff808f43b978
[ 6246.642400] x14: 0000000000000000 x13: ffffff80468c0028 x12: ffffff808f43b908
[ 6246.642418] x11: 0000000000000000 x10: ffffff80468c0030 x9 : ffffffdcbb20b24c
[ 6246.642435] x8 : ffffff808f43b930 x7 : 0000000000000000 x6 : 0000000000000001
[ 6246.642452] x5 : ffffff804398581c x4 : ffffff8040fddc40 x3 : ffffff80468c0008
[ 6246.642470] x2 : 0000000000000002 x1 : 0000000000000000 x0 : 0000000000000006
[ 6246.642487] Call trace:
[ 6246.642492]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[ 6246.642529]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
[ 6246.642564]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
[ 6246.642594]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
[ 6246.642628]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
[ 6246.642659]  v4l_streamoff+0x2c/0x38 [videodev]
[ 6246.642743]  __video_do_ioctl+0x184/0x3d8 [videodev]
[ 6246.642822]  video_usercopy+0x2d8/0x740 [videodev]
[ 6246.642899]  video_ioctl2+0x20/0x38 [videodev]
[ 6246.642977]  v4l2_ioctl+0x48/0x68 [videodev]
[ 6246.643054]  __arm64_sys_ioctl+0xb0/0xf0
[ 6246.643074]  invoke_syscall+0x4c/0x110
[ 6246.643090]  el0_svc_common.constprop.3+0xfc/0x120
[ 6246.643104]  do_el0_svc+0x34/0xd0
[ 6246.643117]  el0_svc+0x30/0x88
[ 6246.643131]  el0t_64_sync_handler+0x98/0xc0
[ 6246.643143]  el0t_64_sync+0x18c/0x190
[ 6246.643154] ---[ end trace 0000000000000000 ]---
[ 6246.643278] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000013046bea in active state
[ 6246.643300] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000267e1628 in active state
[ 6246.643366] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000f387843c in active state
[ 6246.643382] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000008d73a95c in active state
[ 6246.643396] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000009965ce5a in active state
[ 6246.643411] videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000b599f765 in active state
nicoske commented 1 year ago

Still have the issue as well on latest kernel 6.1.51-v8 with gstreamer 1.22.2 and wpewebkit 2.40.3. I'm just playing a 1080p video in loop..

Sep 08 12:06:19 pi-ibbdis-769213 kernel: ------------[ cut here ]------------
Sep 08 12:06:19 pi-ibbdis-769213 kernel: WARNING: CPU: 0 PID: 427 at drivers/media/common/videobuf2/videobuf2-core.c:2035 __vb2_queue_cancel+0x200/0x280 [videobuf2_common]
Sep 08 12:06:19 pi-ibbdis-769213 kernel: Modules linked in: cfg80211 rfkill vc4 snd_soc_hdmi_codec drm_display_helper cec drm_dma_helper drm_kms_helper snd_soc_core snd_compress v3d snd_bcm2835(C) raspberrypi_hwmon snd_pcm_dmaengine snd_pcm bcm2835_v4l2(C) bcm2835_codec(C) gpu_sched rpivid_hevc(C) bcm2835_isp(C) i2c_brcmstb drm_shmem_helper bcm2835_mmal_vchiq(C) snd_timer v4l2_mem2mem videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops syscopyarea snd vc_sm_cma(C) sysfillrect videobuf2_v4l2 videobuf2_common sysimgblt fb_sys_fops videodev nvmem_rmem uio_pdrv_genirq uio ipt_REJECT nf_reject_ipv4 xt_limit xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_addrtype xt_tcpudp iptable_filter sch_fq_codel drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
Sep 08 12:06:19 pi-ibbdis-769213 kernel: CPU: 0 PID: 427 Comm: WPEWebProcess Tainted: G        WC         6.1.51-v8 #1
Sep 08 12:06:19 pi-ibbdis-769213 kernel: Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT)
Sep 08 12:06:19 pi-ibbdis-769213 kernel: pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
Sep 08 12:06:19 pi-ibbdis-769213 kernel: pc : __vb2_queue_cancel+0x200/0x280 [videobuf2_common]
Sep 08 12:06:19 pi-ibbdis-769213 kernel: lr : __vb2_queue_cancel+0x38/0x280 [videobuf2_common]
Sep 08 12:06:19 pi-ibbdis-769213 kernel: sp : ffffffc008d73ae0
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x29: ffffffc008d73ae0 x28: ffffffe2563e0d08 x27: ffffff8041e72528
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x26: ffffffe2563e0f68 x25: 0000000040045613 x24: ffffff8053969400
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x23: 0000000000000000 x22: ffffff8046adf028 x21: ffffff8046adf028
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x20: 0000000000000009 x19: ffffff8046adf028 x18: ffffffc088d73787
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x17: 0003bbfdb54d3510 x16: ffffffe278fdeaa0 x15: ffffff80fb7da240
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x14: 0000000000000019 x13: ffffff8045c00028 x12: 0000000000000000
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x11: ffffff8047b3e7b8 x10: ffffff8047b3e6c8 x9 : ffffffe25644a98c
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x8 : ffffff8047b3e6f0 x7 : 0000000000000001 x6 : ffffffffc0000000
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x5 : ffffff8041e7281c x4 : 0000000000000000 x3 : ffffff8045c00008
Sep 08 12:06:19 pi-ibbdis-769213 kernel: x2 : 0000000000000000 x1 : 00000000000051a8 x0 : 0000000000000002
Sep 08 12:06:19 pi-ibbdis-769213 kernel: Call trace:
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  __vb2_queue_cancel+0x200/0x280 [videobuf2_common]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  vb2_core_streamoff+0x2c/0xd0 [videobuf2_common]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  vb2_streamoff+0x24/0x80 [videobuf2_v4l2]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  v4l2_m2m_streamoff+0x80/0x160 [v4l2_mem2mem]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  v4l_streamoff+0x28/0x40 [videodev]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  __video_do_ioctl+0x18c/0x3e0 [videodev]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  video_usercopy+0x21c/0x790 [videodev]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  video_ioctl2+0x20/0x40 [videodev]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  v4l2_ioctl+0x48/0x70 [videodev]
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  __arm64_sys_ioctl+0xac/0xf0
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  invoke_syscall+0x50/0x120
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  el0_svc_common.constprop.0+0x104/0x130
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  do_el0_svc+0x38/0xe0
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  el0_svc+0x30/0xa0
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  el0t_64_sync_handler+0xbc/0x140
Sep 08 12:06:19 pi-ibbdis-769213 kernel:  el0t_64_sync+0x18c/0x190
Sep 08 12:06:19 pi-ibbdis-769213 kernel: ---[ end trace 0000000000000000 ]---
Sep 08 12:06:19 pi-ibbdis-769213 kernel: videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000829dd968 in active state
Sep 08 12:06:19 pi-ibbdis-769213 kernel: videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000008fbd3223 in active state
Sep 08 12:06:20 pi-ibbdis-769213 kernel: swiotlb_tbl_map_single: 280 callbacks suppressed
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1855488 bytes), total 32768 (slots), used 212 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1855488 bytes), total 32768 (slots), used 212 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1855488 bytes), total 32768 (slots), used 212 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 1855488 bytes), total 32768 (slots), used 212 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
Sep 08 12:06:20 pi-ibbdis-769213 kernel: vc4-drm gpu: swiotlb buffer is full (sz: 6885376 bytes), total 32768 (slots), used 94 (slots)
6by9 commented 1 year ago

The warnings

WARNING: CPU: 0 PID: 427 at drivers/media/common/videobuf2/videobuf2-core.c:2035 __vb2_queue_cancel+0x200/0x280 [videobuf2_common]
videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000829dd968 in active state

are just that - warnings, not errors.

If you have an issue, they are symptoms and not the cause.

nicoske commented 1 year ago

@6by9 Sorry I wasn't specific enough, the video still plays but after a few hours it stops with the following error:

Sep 08 13:56:50 pi-ibbdis-769213 kernel: bcm2835_mmal_vchiq: timed out waiting for sync completion
Sep 08 13:56:50 pi-ibbdis-769213 kernel: bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling o/p port, ret -62
Sep 08 13:56:52 pi-ibbdis-769213 kernel: bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 4 outstanding
Sep 08 13:56:55 pi-ibbdis-769213 kernel: bcm2835_mmal_vchiq: timed out waiting for sync completion
Sep 08 13:56:55 pi-ibbdis-769213 kernel: bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed enabling component, ret -62
6by9 commented 1 year ago

timed out waiting for sync completion generally means that the firmware has given up totally. Without a way to reproduce this, we can't really debug what has happened in the firmware. "sudo vclog -m" may give some useful information, but no guarantees.

nicoske commented 1 year ago

After some verification I've noticed that the allocated GPU memory was only 78Mb. There's some confusion on how to configure it for KMS driver.

Config.txt:

[all]
disable_splash=1
kernel=u-boot.bin
disable_overscan=1
dtparam=audio=on
display_auto_detect=1
dtoverlay=disable-wifi
dtoverlay=disable-bt

[pi4]
dtoverlay=vc4-kms-v3d,cma-256
arm_64bit=1
arm_boost=1

I thought "cma-256" would dynamically allow memory to the GPU when needed but it seems not the case. Adding gpu_mem=256 solved the issue..

popcornmix commented 1 year ago

The default gpu_mem setting should be good for Level 4.1 H.264. Are you using a higher level, or decoding more than one stream at once?

nicoske commented 1 year ago

Only one stream, here are the specs:

Format                                   : MPEG-4
Format profile                           : Base Media / Version 2
Codec ID                                 : mp42 (mp41/isom)
File size                                : 5.04 MiB
Duration                                 : 15 s 600 ms
Overall bit rate                         : 2 712 kb/s
Frame rate                               : 25.000 FPS
Encoded date                             : 2023-09-07 12:41:48 UTC
Tagged date                              : 2023-09-07 12:41:48 UTC

Video
ID                                       : 1
Format                                   : AVC
Format/Info                              : Advanced Video Codec
Format profile                           : Constrained Baseline@L4
Format settings                          : 2 Ref Frames
Format settings, CABAC                   : No
Format settings, Reference frames        : 2 frames
Format settings, GOP                     : M=1, N=25
Codec ID                                 : avc1
Codec ID/Info                            : Advanced Video Coding
Duration                                 : 15 s 600 ms
Bit rate                                 : 2 711 kb/s
Width                                    : 1 920 pixels
Height                                   : 1 080 pixels
Display aspect ratio                     : 16:9
Frame rate mode                          : Constant
Frame rate                               : 25.000 FPS
Color space                              : YUV
Chroma subsampling                       : 4:2:0
Bit depth                                : 8 bits
Scan type                                : Progressive
Bits/(Pixel*Frame)                       : 0.052
Stream size                              : 5.04 MiB (100%)
Encoded date                             : 2023-09-07 12:41:48 UTC
Tagged date                              : 2023-09-07 12:41:48 UTC
Codec configuration box                  : avcC

I'll have a look to compile vclog to the target device

popcornmix commented 1 year ago

Is there anything your code is doing that may allocate additional gpu_mem?

Are you confident increasing gpu_mem really fixes the issue completely (rather than making the failure take ~4x longer to occur?)

nicoske commented 6 months ago

Hi, better late than never. We are still facing the issue with small length videos. When looped continuously seem to cause the buffer not to clean up correctly, eventually leading to a system freeze after several hours.

Tested on latest kernel 6.6.30-v8 on RPI3, RPI3B+, RPI4. GStreamer 1.24.3.

Below is the Python script used to instantiate a playlist of videos in a loop:

    import gi
    gi.require_version('Gst', '1.0')
    from gi.repository import Gst, GLib
    import json

    # Initialize GStreamer
    Gst.init(None)

    video_pipeline = "playbin uri={url}"

    def load_media_list_from_json(filename):
        with open(filename, 'r') as file:
            return json.load(file)

    def play_media(media):
        loop = GLib.MainLoop()
        pipeline_str = video_pipeline.format(url=media["url"])

        pipeline = Gst.parse_launch(pipeline_str)

        def on_eos(bus, message, loop):
            stop_media(pipeline, loop)

        bus = pipeline.get_bus()
        bus.add_signal_watch()
        bus.connect("message::eos", on_eos, loop)

        print("Playing:", media["url"])
        pipeline.set_state(Gst.State.PLAYING)

        loop.run()

    def stop_media(pipeline, loop):
        print("Stopping playback")
        pipeline.set_state(Gst.State.NULL)
        # Add a short timeout to ensure pipeline state change completes
        GLib.timeout_add_seconds(0.1, lambda: play_next_media(loop))

    def play_next_media(loop):
        loop.quit()

    def main():
        media_list = load_media_list_from_json("media_playlist.json")
        print(len(media_list), "items found in the playlist")
        index = 0
        while True:
            play_media(media_list[index])
            index = (index + 1) % len(media_list)

    if __name__ == "__main__":
        main()

The media_playlist.json contains 2 videos:

[
    {
        "type": "video",
        "url": "https://github.com/chthomos/video-media-samples/raw/master/big-buck-bunny-1080p-30sec.mp4"
    },
    {
        "type": "video",
        "url": "http://commondatastorage.googleapis.com/gtv-videos-bucket/sample/ForBiggerBlazes.mp4"
    }
]

Here is a sample of the kernel message logged at each video stop/start.

------------[ cut here ]------------
WARNING: CPU: 0 PID: 505 at drivers/media/common/videobuf2/videobuf2-core.c:2024 __vb2_queue_cancel+0x220/0x2a0 [videobuf2_common]
Modules linked in: cfg80211 rfkill vc4 snd_soc_hdmi_codec drm_display_helper cec drm_dma_helper drm_kms_helper v3d gpu_sched drm_shmem_helper snd_soc_core bcm2835_codec(C) raspberrypi_hwmon bcm2835_isp(C) rpivid_hevc(C) snd_compress v4l2_mem2mem snd_bcm2835(C) bcm2835_v4l2(C) snd_pcm_dmaengine bcm2835_mmal_vchiq(C) snd_pcm videobuf2_dma_contig videobuf2_vmalloc snd_timer videobuf2_memops videobuf2_v4l2 i2c_brcmstb vc_sm_cma(C) raspberrypi_gpiomem videodev videobuf2_common snd joydev nvmem_rmem uio_pdrv_genirq uio ipt_REJECT nf_reject_ipv4 xt_limit xt_conntrack nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 xt_addrtype xt_tcpudp iptable_filter sch_fq_codel fuse drm drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
CPU: 0 PID: 505 Comm: python Tainted: G        WC         6.6.30-v8 #1
Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT)
pstate: 80000005 (Nzcv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
pc : __vb2_queue_cancel+0x220/0x2a0 [videobuf2_common]
lr : __vb2_queue_cancel+0x38/0x2a0 [videobuf2_common]
sp : ffffffc080ac3b00
x29: ffffffc080ac3b00 x28: 0000000000000000 x27: ffffffde883b5d28
x26: 0000000000000000 x25: ffffffc080ac3d28 x24: ffffff8045421530
x23: ffffff804640a600 x22: ffffff804165e028 x21: ffffff804165e028
x20: 0000000000000009 x19: ffffff804165e028 x18: ffffffc080ac3650
x17: 0000000100000000 x16: ffffffdeef0fd708 x15: ffffffc100ac37a7
x14: 0000000000000004 x13: ffffff8045600028 x12: 0000000000000000
x11: ffffff80504d74c0 x10: ffffff80504d7478 x9 : ffffffde88361b1c
x8 : ffffff80504d74a0 x7 : 0000000000000000 x6 : ffffff80504d76a0
x5 : ffffff804542181c x4 : 0000000000000000 x3 : 0000000000000000
x2 : ffffff8046708000 x1 : 0000000000000000 x0 : 0000000000000002
Call trace:
 __vb2_queue_cancel+0x220/0x2a0 [videobuf2_common]
 vb2_core_streamoff+0x2c/0xd0 [videobuf2_common]
 vb2_streamoff+0x20/0x78 [videobuf2_v4l2]
 v4l2_m2m_streamoff+0x80/0x158 [v4l2_mem2mem]
 v4l2_m2m_ioctl_streamoff+0x20/0x38 [v4l2_mem2mem]
 v4l_streamoff+0x28/0x40 [videodev]
 __video_do_ioctl+0x348/0x408 [videodev]
 video_usercopy+0x2d0/0x740 [videodev]
 video_ioctl2+0x20/0x40 [videodev]
 v4l2_ioctl+0x48/0x70 [videodev]
 __arm64_sys_ioctl+0xb0/0x100
 invoke_syscall+0x50/0x128
 el0_svc_common.constprop.0+0xc8/0xf0
 do_el0_svc+0x24/0x38
 el0_svc+0x40/0xe8
 el0t_64_sync_handler+0x120/0x130
 el0t_64_sync+0x190/0x198
---[ end trace 0000000000000000 ]---
videobuf2_common: driver bug: stop_streaming operation is leaving buf 00000000d92d0279 in active state
videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000035ee8d9e in active state

And here is vclog output from boot till +2 hours of video loop:

004914.097: arasan: arasan_emmc_open
004914.267: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 400000 delay: 5
005019.043: arasan: arasan_emmc_set_clock C0: 0x00800000 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 400000 max: 400000 delay: 5
005019.128: arasan: arasan_emmc_set_clock C0: 0x00800f00 C1: 0x000e0047 emmc: 200000000 actual: 390625 div: 0x00000100 target: 400000 min: 390000 max: 400000 delay: 5
005049.333: arasan: arasan_emmc_set_clock C0: 0x00800f06 C1: 0x000e0207 emmc: 200000000 actual: 50000000 div: 0x00000002 target: 50000000 min: 0 max: 50000000 delay: 1
005056.246: brfs: File read: /mfs/sd/config.txt
005056.883: brfs: File read: 665 bytes
005078.387: HDMI0:EDID error reading EDID block 0 attempt 0
005079.402: HDMI0:EDID giving up on reading EDID block 0
005140.319: brfs: File read: /mfs/sd/config.txt
005589.599: gpioman: gpioman_get_pin_num: pin DISPLAY_DSI_PORT not defined
005591.768: *** Restart logging
005591.787: brfs: File read: 665 bytes
005596.963: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
005597.981: hdmi: HDMI0:EDID giving up on reading EDID block 0
005603.025: hdmi: HDMI0:EDID error reading EDID block 0 attempt 0
005604.041: hdmi: HDMI0:EDID giving up on reading EDID block 0
005604.060: hdmi: HDMI:hdmi_get_state is deprecated, use hdmi_get_display_state instead
005663.005: HDMI0: hdmi_pixel_encoding: 300000000
005663.017: HDMI1: hdmi_pixel_encoding: 300000000
005673.036: dtb_file 'bcm2711-rpi-4-b.dtb'
005680.198: brfs: File read: /mfs/sd/bcm2711-rpi-4-b.dtb
005680.214: Loaded 'bcm2711-rpi-4-b.dtb' to 0x100 size 0xd9f4
005693.737: brfs: File read: 55796 bytes
005704.498: brfs: File read: /mfs/sd/overlays/overlay_map.dtb
005727.972: brfs: File read: 5195 bytes
005730.436: brfs: File read: /mfs/sd/config.txt
005730.493: dtparam: audio=on
005734.718: brfs: File read: 665 bytes
005751.989: brfs: File read: /mfs/sd/overlays/disable-wifi.dtbo
005760.853: Loaded overlay 'disable-wifi'
005774.208: brfs: File read: 387 bytes
005785.454: brfs: File read: /mfs/sd/overlays/disable-bt.dtbo
005800.700: Loaded overlay 'disable-bt'
005835.026: brfs: File read: 1073 bytes
005839.427: brfs: File read: /mfs/sd/overlays/vc4-kms-v3d-pi4.dtbo
005989.681: Loaded overlay 'vc4-kms-v3d'
005989.703: dtparam: cma-256=true
006401.207: brfs: File read: 3913 bytes
006403.384: Failed to open command line file 'cmdline.txt'
006895.467: brfs: File read: /mfs/sd/u-boot.bin
006895.503: Loaded 'u-boot.bin' to 0x200000 size 0x93c28
006896.542: Kernel relocated to 0x80000
006896.568: Device tree loaded to 0x1ffe2000 (size 0xdf70)
006903.965: gpioman: gpioman_get_pin_num: pin SDCARD_CONTROL_POWER not defined
007011.740: sdram: sdram refresh 1562->3124 (2)

021549.942: vchiq_core: vchiq_init_state: slot_zero = 0xcfe00000, is_master = 1
021563.418: TV service:host side not connected, dropping notification 0x00000002, 0x00000001, 0x00000010
147739.305: video_decode:8:RIL: nothing changing
217247.362: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
217247.398: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
217301.221: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
217301.241: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
249840.239: video_decode:9:RIL: colourspace changing
280070.931: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
280070.955: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
280114.311: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
280114.330: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
280902.481: video_decode:10:RIL: nothing changing
350334.560: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
350334.582: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
350390.924: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
350390.958: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
382876.827: video_decode:11:RIL: colourspace changing
413109.060: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
413109.097: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
413151.223: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
413151.243: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
413940.639: video_decode:12:RIL: nothing changing
483379.470: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
483379.503: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
483434.298: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
483434.320: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
515832.229: video_decode:13:RIL: colourspace changing
546077.508: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
546077.546: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
546118.268: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
546118.287: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
546891.816: video_decode:14:RIL: nothing changing
616334.649: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
616334.670: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
616390.928: mmalsrv: mmal_server_do_buffer_from_host: pool exhausted, recyling bust, on comp 64 port 2
616390.963: mmal: mmal_port_event_send: event lost on port 1,0 (buffer header callback not defined)
648827.271: video_decode:15:RIL: colourspace changing
nicoske commented 6 months ago

I managed to retrieve some kernel messages ater the crash/freeze. Unfortunately It's not complete (missing the exact crash timestamp).: This message is repeating itself every minute:

[ 1374.677622] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 1374.683717] rcu:     0-...0: (3 ticks this GP) idle=02fc/1/0x4000000000000002 softirq=156354/156354 fqs=3056780
[ 1374.693550] rcu:     (detected by 1, t=8329707 jiffies, g=334681, q=1924 ncpus=4)
[ 1374.700771] Task dump for CPU 0:
[ 1374.703995] task:swapper/0       state:R  running task     stack:0     pid:0     ppid:0      flags:0x0000000a
[ 1374.713917] Call trace:
[ 1374.716359]  __switch_to+0xe0/0x160
[ 1374.719853]  cpu_number+0x0/0x8
nicoske commented 2 months ago

Could we please find a solution for this issue? Looping videos that are at least 15 seconds each does seem to stabilize things somewhat, but we’re still seeing numerous warnings in the logs. This makes it quite challenging to read and diagnose other potential issues. Any assistance would be greatly appreciated!

6by9 commented 2 months ago

The WARN triggered by GStreamer (and other apps using VIDIOC_CREATE_BUFS) has been fixed with #6348 (merged last week).

nicoske commented 2 months ago

Thank you @6by9 ! Testing now and indeed the message is gone, no issue so far !