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
11k stars 4.95k forks source link

`bcm2835_mmal_vchiq: timed out waiting for sync completion`, `bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling i/p port, ret -62` when using FullHD + CBR + main profile #5360

Open arkanoid87 opened 1 year ago

arkanoid87 commented 1 year ago

Describe the bug

Managed to raise error in bcm2835_mmal_vchiq and bcm2835-codec by using v4l2h264enc gstreamer element:

here the recipe:

lowering resolution works lowering profile to baseline works changing encoding to VBR works, even with higher profiles

Steps to reproduce the behaviour

ENCODER_SETTINGS_OK="controls,video_bitrate_mode=0,h264_minimum_qp_value=35,h264_maximum_qp_value=35;"
ENCODER_SETTINGS_KO="controls,video_bitrate_mode=1,video_bitrate=2000000;"

gst-launch-1.0 \
    libcamerasrc ! video/x-raw,width=1920,height=1080,framerate=30/1,format=I420,interlace-mode=progressive ! \
    v4l2h264enc extra-controls=$ENCODER_SETTINGS_KO ! video/x-h264,level=\(string\)4,profile=main ! fakesink

Device (s)

Raspberry Pi Zero 2 W

System

Raspberry Pi reference 2022-09-22 Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 005a8c73b05a2cab394073150208bf4f069e861a, stage2

Jan 5 2023 10:48:31 Copyright (c) 2012 Broadcom version 8ba17717fbcedd4c3b6d4bce7e50c7af4155cba9 (clean) (release) (start)

Linux raspberrypi 5.15.84-v8+ #1613 SMP PREEMPT Thu Jan 5 12:03:08 GMT 2023 aarch64 GNU/Linux

Logs

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000] Linux version 5.15.84-v8+ (dom@buildbot) (aarch64-linux-gnu-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1613 SMP PREEMPT Thu Jan 5 12:03:08 GMT 2023
[    0.000000] random: crng init done
[    0.000000] Machine model: Raspberry Pi Zero 2 W Rev 1.0
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created CMA memory pool at 0x000000000bc00000, size 256 MiB
[    0.000000] OF: reserved mem: initialized node linux,cma, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000001bffffff]
[    0.000000]   DMA32    empty
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000001bffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000001bffffff]
[    0.000000] On node 0, zone DMA: 16384 pages in unavailable ranges
[    0.000000] percpu: Embedded 28 pages/cpu s77336 r8192 d29160 u114688
[    0.000000] pcpu-alloc: s77336 r8192 d29160 u114688 alloc=28*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: kernel page table isolation forced ON by KASLR
[    0.000000] CPU features: detected: Kernel page table isolation (KPTI)
[    0.000000] CPU features: detected: ARM erratum 843419
[    0.000000] CPU features: detected: ARM erratum 845719
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 112896
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_compat_alsa=0 snd_bcm2835.enable_hdmi=1 video=Composite-1:720x480@60i smsc95xx.macaddr=B8:27:EB:83:3C:D6 vc_mem.mem_base=0x1ec00000 vc_mem.mem_size=0x20000000  console=ttyS0,115200 console=tty1 root=PARTUUID=928292f9-02 rootfstype=ext4 fsck.repair=yes rootwait
[    0.000000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.000000] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] Memory: 163504K/458752K available (11520K kernel code, 1956K rwdata, 4136K rodata, 3776K init, 975K bss, 33104K reserved, 262144K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 38065 entries in 149 pages
[    0.000000] ftrace: allocated 149 pages with 4 groups
[    0.000000] trace event string verifier disabled
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU event tracing is enabled.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000]  Trampoline variant of Tasks RCU enabled.
[    0.000000]  Rude variant of Tasks RCU enabled.
[    0.000000]  Tracing variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] Root IRQ handler: bcm2836_arm_irqchip_handle_irq
[    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.000001] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000398] Console: colour dummy device 80x25
[    0.001328] printk: console [tty1] enabled
[    0.001412] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=76800)
[    0.001478] pid_max: default: 32768 minimum: 301
[    0.001671] LSM: Security Framework initializing
[    0.001947] Mount-cache hash table entries: 1024 (order: 1, 8192 bytes, linear)
[    0.002008] Mountpoint-cache hash table entries: 1024 (order: 1, 8192 bytes, linear)
[    0.003730] cgroup: Disabling memory control group subsystem
[    0.007948] rcu: Hierarchical SRCU implementation.
[    0.009470] EFI services will not be available.
[    0.010244] smp: Bringing up secondary CPUs ...
[    0.011837] Detected VIPT I-cache on CPU1
[    0.011968] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.013753] Detected VIPT I-cache on CPU2
[    0.013819] CPU2: Booted secondary processor 0x0000000002 [0x410fd034]
[    0.015495] Detected VIPT I-cache on CPU3
[    0.015552] CPU3: Booted secondary processor 0x0000000003 [0x410fd034]
[    0.015767] smp: Brought up 1 node, 4 CPUs
[    0.015926] SMP: Total of 4 processors activated.
[    0.015961] CPU features: detected: 32-bit EL0 Support
[    0.016055] CPU features: detected: 32-bit EL1 Support
[    0.016091] CPU features: detected: CRC32 instructions
[    0.057948] CPU: All CPU(s) started at EL2
[    0.058097] alternatives: patching kernel code
[    0.060045] devtmpfs: initialized
[    0.083136] Enabled cp15_barrier support
[    0.083222] Enabled setend support
[    0.083267] KASLR enabled
[    0.083579] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.083651] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.096284] pinctrl core: initialized pinctrl subsystem
[    0.097585] DMI not present or invalid.
[    0.098614] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.110066] DMA: preallocated 1024 KiB GFP_KERNEL pool for atomic allocations
[    0.110585] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.112053] DMA: preallocated 1024 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.112241] audit: initializing netlink subsys (disabled)
[    0.112684] audit: type=2000 audit(0.112:1): state=initialized audit_enabled=0 res=1
[    0.113624] thermal_sys: Registered thermal governor 'step_wise'
[    0.113963] cpuidle: using governor menu
[    0.114548] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.114862] ASID allocator initialised with 32768 entries
[    0.115121] Serial: AMBA PL011 UART driver
[    0.131090] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.164803] raspberrypi-firmware soc:firmware: Attached to firmware from 2023-01-05T10:48:31, variant start
[    0.168820] raspberrypi-firmware soc:firmware: Firmware hash is 8ba17717fbcedd4c3b6d4bce7e50c7af4155cba9
[    0.230270] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.236006] vgaarb: loaded
[    0.236681] SCSI subsystem initialized
[    0.237048] usbcore: registered new interface driver usbfs
[    0.237228] usbcore: registered new interface driver hub
[    0.237350] usbcore: registered new device driver usb
[    0.237926] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.238260] usb_phy_generic phy: dummy supplies not allowed for exclusive requests
[    0.238668] pps_core: LinuxPPS API ver. 1 registered
[    0.238706] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.238771] PTP clock support registered
[    0.241253] clocksource: Switched to clocksource arch_sys_counter
[    0.370008] VFS: Disk quotas dquot_6.6.0
[    0.370190] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.370474] FS-Cache: Loaded
[    0.370807] CacheFiles: Loaded
[    0.372203] simple-framebuffer 1eaa9000.framebuffer: framebuffer at 0x1eaa9000, 0x151800 bytes
[    0.372258] simple-framebuffer 1eaa9000.framebuffer: format=a8r8g8b8, mode=720x480x32, linelength=2880
[    0.378695] Console: switching to colour frame buffer device 90x30
[    0.387185] simple-framebuffer 1eaa9000.framebuffer: fb0: simplefb registered!
[    0.405983] NET: Registered PF_INET protocol family
[    0.409410] IP idents hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.414323] tcp_listen_portaddr_hash hash table entries: 256 (order: 0, 4096 bytes, linear)
[    0.420868] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.424428] TCP established hash table entries: 4096 (order: 3, 32768 bytes, linear)
[    0.428108] TCP bind hash table entries: 4096 (order: 4, 65536 bytes, linear)
[    0.431825] TCP: Hash tables configured (established 4096 bind 4096)
[    0.435668] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)
[    0.439364] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)
[    0.443962] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    0.448919] RPC: Registered named UNIX socket transport module.
[    0.452587] RPC: Registered udp transport module.
[    0.456181] RPC: Registered tcp transport module.
[    0.459597] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.463024] PCI: CLS 0 bytes, default 64
[    0.468827] hw perfevents: enabled with armv8_cortex_a53 PMU driver, 7 counters available
[    0.476190] kvm [1]: IPA Size Limit: 40 bits
[    0.481404] kvm [1]: Hyp mode initialized successfully
[    1.751237] Initialise system trusted keyrings
[    1.755175] workingset: timestamp_bits=46 max_order=17 bucket_order=0
[    1.769490] zbud: loaded
[    1.775610] FS-Cache: Netfs 'nfs' registered for caching
[    1.779880] NFS: Registering the id_resolver key type
[    1.783155] Key type id_resolver registered
[    1.786289] Key type id_legacy registered
[    1.789535] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    1.792556] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    1.797477] Key type asymmetric registered
[    1.800434] Asymmetric key parser 'x509' registered
[    1.803475] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    1.806880] io scheduler mq-deadline registered
[    1.809853] io scheduler kyber registered
[    1.828534] bcm2835-rng 3f104000.rng: hwrng registered
[    1.832447] vc-mem: phys_addr:0x00000000 mem_base=0x1ec00000 mem_size:0x20000000(512 MiB)
[    1.840387] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    1.862753] brd: module loaded
[    1.881103] loop: module loaded
[    1.885376] Loading iSCSI transport class v2.0-870.
[    1.895546] usbcore: registered new interface driver r8152
[    1.898730] usbcore: registered new interface driver lan78xx
[    1.901782] usbcore: registered new interface driver smsc95xx
[    1.905407] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.636964] Core Release: 2.80a
[    2.639845] Setting default values for core params
[    2.642719] Finished setting default values for core params
[    2.846083] Using Buffer DMA mode
[    2.848900] Periodic Transfer Interrupt Enhancement - disabled
[    2.851821] Multiprocessor Interrupt Enhancement - disabled
[    2.854798] OTG VER PARAM: 0, OTG VER FLAG: 0
[    2.857725] Dedicated Tx FIFOs mode

[    2.865059] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = ffffffc008471000 dma = 0x00000000cc000000 len=9024
[    2.873475] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    2.887032] dwc_otg: Microframe scheduler enabled

[    2.887108] WARN::hcd_init_fiq:497: MPHI regs_base at ffffffc008065000
[    2.892236] dwc_otg 3f980000.usb: DWC OTG Controller
[    2.894899] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    2.897651] dwc_otg 3f980000.usb: irq 74, io mem 0x00000000
[    2.900328] Init: Port Power? op_state=1
[    2.903018] Init: Power Port (0)
[    2.906263] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.15
[    2.911835] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.914824] usb usb1: Product: DWC OTG Controller
[    2.917760] usb usb1: Manufacturer: Linux 5.15.84-v8+ dwc_otg_hcd
[    2.920705] usb usb1: SerialNumber: 3f980000.usb
[    2.924636] hub 1-0:1.0: USB hub found
[    2.927582] hub 1-0:1.0: 1 port detected
[    2.931645] dwc_otg: FIQ enabled
[    2.931664] dwc_otg: NAK holdoff enabled
[    2.931679] dwc_otg: FIQ split-transaction FSM enabled
[    2.931700] Module dwc_common_port init
[    2.932456] usbcore: registered new interface driver uas
[    2.935457] usbcore: registered new interface driver usb-storage
[    2.938870] mousedev: PS/2 mouse device common for all mice
[    2.946943] sdhci: Secure Digital Host Controller Interface driver
[    2.949739] sdhci: Copyright(c) Pierre Ossman
[    2.953273] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.958796] ledtrig-cpu: registered to indicate activity on CPUs
[    2.962450] hid: raw HID events driver (C) Jiri Kosina
[    2.965520] usbcore: registered new interface driver usbhid
[    2.968373] usbhid: USB HID core driver
[    2.971633] ashmem: initialized
[    2.982844] NET: Registered PF_PACKET protocol family
[    2.985878] Key type dns_resolver registered
[    2.990428] registered taskstats version 1
[    2.993144] Loading compiled-in X.509 certificates
[    2.996816] Key type .fscrypt registered
[    2.999557] Key type fscrypt-provisioning registered
[    3.021291] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    3.024164] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 99, base_baud = 0) is a PL011 rev2
[    3.034314] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    3.037775] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    3.043324] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    3.046173] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    3.076223] sdhost: log_buf @ 00000000b0c734ec (c2ef1000)
[    3.149099] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    3.157046] of_cfs_init
[    3.160111] of_cfs_init: OK
[    3.164469] Waiting for root device PARTUUID=928292f9-02...
[    3.189547] mmc0: host does not support reading read-only switch, assuming write-enable
[    3.195670] mmc0: new high speed SDHC card at address 0001
[    3.200531] mmcblk0: mmc0:0001 EB1QT 29.8 GiB 
[    3.209034]  mmcblk0: p1 p2
[    3.212902] mmcblk0: mmc0:0001 EB1QT 29.8 GiB
[    3.249359] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null). Quota mode: none.
[    3.255454] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.262707] mmc1: new high speed SDIO card at address 0001
[    3.268185] devtmpfs: mounted
[    3.281860] Freeing unused kernel memory: 3776K
[    3.285180] Run /sbin/init as init process
[    3.288316]   with arguments:
[    3.288331]     /sbin/init
[    3.288346]   with environment:
[    3.288359]     HOME=/
[    3.288373]     TERM=linux
[    3.894780] systemd[1]: System time before build time, advancing clock.
[    4.166114] NET: Registered PF_INET6 protocol family
[    4.171729] Segment Routing with IPv6
[    4.174864] In-situ OAM (IOAM) with IPv6
[    4.267550] systemd[1]: systemd 247.3-7+deb11u1 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +ZSTD +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=unified)
[    4.278603] systemd[1]: Detected architecture arm64.
[    4.311468] systemd[1]: Set hostname to <raspberrypi>.
[    5.381767] systemd[1]: Queued start job for default target Multi-User System.
[    5.391973] systemd[1]: Created slice system-getty.slice.
[    5.401214] systemd[1]: Created slice system-modprobe.slice.
[    5.410317] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.419241] systemd[1]: Created slice system-wg\x2dquick.slice.
[    5.427833] systemd[1]: Created slice User and Session Slice.
[    5.435864] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.444116] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.453557] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    5.465737] systemd[1]: Reached target Local Encrypted Volumes.
[    5.473982] systemd[1]: Reached target Host and Network Name Lookups.
[    5.482082] systemd[1]: Reached target Paths.
[    5.490243] systemd[1]: Reached target Slices.
[    5.498321] systemd[1]: Reached target Swap.
[    5.507586] systemd[1]: Listening on Syslog Socket.
[    5.516590] systemd[1]: Listening on fsck to fsckd communication Socket.
[    5.525073] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    5.534923] systemd[1]: Listening on Journal Audit Socket.
[    5.543970] systemd[1]: Listening on Journal Socket (/dev/log).
[    5.553327] systemd[1]: Listening on Journal Socket.
[    5.567296] systemd[1]: Listening on udev Control Socket.
[    5.576285] systemd[1]: Listening on udev Kernel Socket.
[    5.584882] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    5.597384] systemd[1]: Mounting POSIX Message Queue File System...
[    5.611616] systemd[1]: Mounting RPC Pipe File System...
[    5.626941] systemd[1]: Mounting Kernel Debug File System...
[    5.642368] systemd[1]: Mounting Kernel Trace File System...
[    5.651066] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[    5.666474] systemd[1]: Starting Restore / save the current clock...
[    5.681807] systemd[1]: Starting Set the console keyboard layout...
[    5.697732] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    5.718013] systemd[1]: Starting Load Kernel Module configfs...
[    5.734578] systemd[1]: Starting Load Kernel Module drm...
[    5.751301] systemd[1]: Starting Load Kernel Module fuse...
[    5.769207] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[    5.775972] systemd[1]: Starting File System Check on Root Device...
[    5.801802] systemd[1]: Starting Journal Service...
[    5.840663] systemd[1]: Starting Load Kernel Modules...
[    5.855824] fuse: init (API version 7.34)
[    5.882745] systemd[1]: Starting Coldplug All udev Devices...
[    5.921734] systemd[1]: Mounted POSIX Message Queue File System.
[    5.931836] systemd[1]: Mounted RPC Pipe File System.
[    5.942066] systemd[1]: Mounted Kernel Debug File System.
[    5.951104] systemd[1]: Mounted Kernel Trace File System.
[    5.962182] systemd[1]: Finished Restore / save the current clock.
[    5.974939] systemd[1]: Finished Create list of static device nodes for the current kernel.
[    5.990108] systemd[1]: modprobe@configfs.service: Succeeded.
[    5.996375] systemd[1]: Finished Load Kernel Module configfs.
[    6.007561] systemd[1]: modprobe@drm.service: Succeeded.
[    6.013895] systemd[1]: Finished Load Kernel Module drm.
[    6.024786] systemd[1]: modprobe@fuse.service: Succeeded.
[    6.031705] systemd[1]: Finished Load Kernel Module fuse.
[    6.058659] systemd[1]: Finished Load Kernel Modules.
[    6.100923] systemd[1]: Mounting FUSE Control File System...
[    6.134286] systemd[1]: Mounting Kernel Configuration File System...
[    6.174287] systemd[1]: Started File System Check Daemon to report status.
[    6.215160] systemd[1]: Starting Apply Kernel Variables...
[    6.246619] systemd[1]: Started Journal Service.
[    6.515532] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null). Quota mode: none.
[    6.626468] systemd-journald[139]: Received client request to flush runtime journal.
[    6.654060] systemd-journald[139]: File /var/log/journal/a332c52bb59841a5b468a845c96ae7c0/system.journal corrupted or uncleanly shut down, renaming and replacing.
[   11.786160] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[   11.789023] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[   11.789078] [vc_sm_connected_init]: start
[   11.790651] [vc_sm_connected_init]: installed successfully
[   11.848890] mc: Linux media interface: v0.10
[   11.982311] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[   11.994967] bcm2835_audio bcm2835_audio: there is not valid maps for state default
[   12.001548] videodev: Linux video capture interface: v2.00
[   12.113428] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   12.120081] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   12.132092] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[   12.164399] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[   12.168885] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[   12.174254] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[   12.226303] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[   12.226405] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[   12.231463] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[   12.247716] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[   12.253957] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[   12.254049] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[   12.257674] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[   12.258364] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[   12.258418] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[   12.258453] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[   12.258482] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[   12.258510] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[   12.263298] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20
[   12.273528] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21
[   12.273709] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[   12.273911] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[   12.280518] bcm2835-codec bcm2835-codec: Device registered as /dev/video18
[   12.280617] bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx
[   12.289574] bcm2835-codec bcm2835-codec: Device registered as /dev/video31
[   12.289656] bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image
[   12.291649] i2c i2c-11: Added multiplexed i2c bus 0
[   12.292948] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22
[   12.293689] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23
[   12.293742] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[   12.293778] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[   12.293832] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[   12.293861] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[   12.294865] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[   12.297193] i2c 10-001a: Fixing up cyclic dependency with 3f801000.csi
[   12.298656] i2c i2c-11: Added multiplexed i2c bus 10
[   12.658421] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   12.712346] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   12.735078] cfg80211: loaded regulatory.db is malformed or signature is missing/invalid
[   13.100876] checking generic (1eaa9000 151800) vs hw (0 ffffffffffffffff)
[   13.100920] fb0: switching to vc4 from simple
[   13.123963] Console: switching to colour dummy device 80x25
[   13.141423] vc4-drm soc:gpu: bound 3f400000.hvs (ops vc4_hvs_ops [vc4])
[   13.146096] brcmfmac: F1 signature read @0x18000000=0x1542a9a6
[   13.146800] Registered IR keymap rc-cec
[   13.147139] rc rc0: vc4 as /devices/platform/soc/3f902000.hdmi/rc/rc0
[   13.147518] input: vc4 as /devices/platform/soc/3f902000.hdmi/rc/rc0/input0
[   13.163162] vc4-drm soc:gpu: bound 3f902000.hdmi (ops vc4_hdmi_ops [vc4])
[   13.163797] vc4-drm soc:gpu: bound 3f004000.txp (ops vc4_txp_ops [vc4])
[   13.164245] vc4-drm soc:gpu: bound 3f206000.pixelvalve (ops vc4_crtc_ops [vc4])
[   13.171512] vc4-drm soc:gpu: bound 3f207000.pixelvalve (ops vc4_crtc_ops [vc4])
[   13.172194] vc4-drm soc:gpu: bound 3f807000.pixelvalve (ops vc4_crtc_ops [vc4])
[   13.172629] vc4-drm soc:gpu: bound 3fc00000.v3d (ops vc4_v3d_ops [vc4])
[   13.198814] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
[   13.199491] vc4-drm soc:gpu: [drm] Cannot find any crtc or sizes
[   13.205727] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43436-sdio for chip BCM43430/2
[   13.206897] usbcore: registered new interface driver brcmfmac
[   13.402735] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43436-sdio for chip BCM43430/2
[   13.432768] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/2 wl0: Mar 31 2022 17:24:51 version 9.88.4.77 (g58bc5cc) FWID 01-3b307371
[   14.337557] imx708 10-001a: camera module ID 0x0301
[   14.354985] imx708 10-001a: Consider updating driver imx708 to match on endpoints
[   14.483278] uart-pl011 3f201000.serial: no DMA platform data
[   14.758358] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   14.936128] 8021q: 802.1Q VLAN Support v1.8
[   15.198340] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[   16.672957] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   18.278847] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.wlan0.retrans_time - use net.ipv6.neigh.wlan0.retrans_time_ms instead
[   20.413426] Bluetooth: Core ver 2.22
[   20.414213] NET: Registered PF_BLUETOOTH protocol family
[   20.414231] Bluetooth: HCI device and connection manager initialized
[   20.414262] Bluetooth: HCI socket layer initialized
[   20.414279] Bluetooth: L2CAP socket layer initialized
[   20.414315] Bluetooth: SCO socket layer initialized
[   20.431365] Bluetooth: HCI UART driver ver 2.3
[   20.431399] Bluetooth: HCI UART protocol H4 registered
[   20.432151] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   20.432923] Bluetooth: HCI UART protocol Broadcom registered
[   21.049848] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   21.049887] Bluetooth: BNEP filters: protocol multicast
[   21.049924] Bluetooth: BNEP socket layer initialized
[   21.088659] NET: Registered PF_ALG protocol family
[   22.827942] wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
[   22.827967] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[   23.261711] vc4-drm soc:gpu: [drm] Cannot find any crtc or sizes
[   33.757295] cam-dummy-reg: disabling
[  122.587838] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  122.587881] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling i/p port, ret -62
[  124.603829] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 2 outstanding
[  124.604022] ------------[ cut here ]------------
[  124.604032] WARNING: CPU: 2 PID: 825 at drivers/media/common/videobuf2/videobuf2-core.c:1995 __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  124.604106] Modules linked in: wireguard libchacha20poly1305 chacha_neon poly1305_neon ip6_udp_tunnel udp_tunnel libcurve25519_generic libchacha cmac algif_hash aes_arm64 aes_generic algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc libaes 8021q garp stp llc imx708 dw9807_vcm brcmfmac vc4 brcmutil snd_soc_hdmi_codec cec drm_kms_helper cfg80211 snd_soc_core snd_compress snd_pcm_dmaengine i2c_mux_pinctrl bcm2835_unicam i2c_mux syscopyarea sysfillrect sysimgblt v4l2_dv_timings fb_sys_fops v4l2_fwnode bcm2835_isp(C) bcm2835_v4l2(C) bcm2835_codec(C) v4l2_async raspberrypi_hwmon bcm2835_mmal_vchiq(C) rfkill v4l2_mem2mem videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common snd_bcm2835(C) videodev snd_pcm snd_timer snd mc vc_sm_cma(C) i2c_bcm2835 uio_pdrv_genirq uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[  124.604595] CPU: 2 PID: 825 Comm: gst-launch-1.0 Tainted: G         C        5.15.84-v8+ #1613
[  124.604613] Hardware name: Raspberry Pi Zero 2 W Rev 1.0 (DT)
[  124.604623] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[  124.604639] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  124.604689] lr : __vb2_queue_cancel+0x3c/0x220 [videobuf2_common]
[  124.604735] sp : ffffffc008b9baf0
[  124.604743] x29: ffffffc008b9baf0 x28: 0000000000000000 x27: ffffffc008b9bd28
[  124.604772] x26: 0000000000000000 x25: ffffff80072d4800 x24: ffffff8004bc2628
[  124.604800] x23: 0000000000000001 x22: ffffffe9b5c989a8 x21: ffffff8007b96298
[  124.604827] x20: ffffff8007b96298 x19: ffffff8007b96298 x18: 0000000000000009
[  124.604854] x17: 756f656d6954203a x16: ffffffe9b50c76a8 x15: ffffff8006780030
[  124.604881] x14: ffffff8007475740 x13: 0000000000000000 x12: 0000000000000000
[  124.604908] x11: ffffff80074756d0 x10: ffffff8006780038 x9 : ffffffe9b50c7598
[  124.604935] x8 : 000000000010000f x7 : 0000000000000000 x6 : ffffffc008b9b840
[  124.604962] x5 : 0000000000000001 x4 : 0000000000000000 x3 : ffffffe9b6129000
[  124.604988] x2 : ffffffe9b6129078 x1 : 84e410918fb9a200 x0 : 0000000000000002
[  124.605016] Call trace:
[  124.605024]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  124.605073]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
[  124.605120]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
[  124.605159]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
[  124.605207]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
[  124.605250]  v4l_streamoff+0x2c/0x38 [videodev]
[  124.605392]  __video_do_ioctl+0x188/0x410 [videodev]
[  124.605518]  video_usercopy+0x310/0x7d0 [videodev]
[  124.605644]  video_ioctl2+0x20/0x38 [videodev]
[  124.605773]  v4l2_ioctl+0x48/0x68 [videodev]
[  124.605899]  __arm64_sys_ioctl+0xb0/0xf0
[  124.605922]  invoke_syscall+0x4c/0x110
[  124.605942]  el0_svc_common.constprop.3+0xfc/0x120
[  124.605960]  do_el0_svc+0x2c/0x90
[  124.605977]  el0_svc+0x24/0x60
[  124.605993]  el0t_64_sync_handler+0x90/0xb8
[  124.606008]  el0t_64_sync+0x1a0/0x1a4
[  124.606025] ---[ end trace c260ec64c07e120e ]---
[  124.606037] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000000e1f0de8 in active state
[  124.606069] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000008e3e0919 in active state
[  127.707918] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  127.707959] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling o/p port, ret -62
[  129.723814] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 4 outstanding
[  132.827905] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  132.827948] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed enabling component, ret -62
[  132.828123] ------------[ cut here ]------------
[  132.828132] WARNING: CPU: 0 PID: 825 at drivers/media/common/videobuf2/videobuf2-core.c:1995 __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  132.828206] Modules linked in: wireguard libchacha20poly1305 chacha_neon poly1305_neon ip6_udp_tunnel udp_tunnel libcurve25519_generic libchacha cmac algif_hash aes_arm64 aes_generic algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc libaes 8021q garp stp llc imx708 dw9807_vcm brcmfmac vc4 brcmutil snd_soc_hdmi_codec cec drm_kms_helper cfg80211 snd_soc_core snd_compress snd_pcm_dmaengine i2c_mux_pinctrl bcm2835_unicam i2c_mux syscopyarea sysfillrect sysimgblt v4l2_dv_timings fb_sys_fops v4l2_fwnode bcm2835_isp(C) bcm2835_v4l2(C) bcm2835_codec(C) v4l2_async raspberrypi_hwmon bcm2835_mmal_vchiq(C) rfkill v4l2_mem2mem videobuf2_dma_contig videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_common snd_bcm2835(C) videodev snd_pcm snd_timer snd mc vc_sm_cma(C) i2c_bcm2835 uio_pdrv_genirq uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[  132.828695] CPU: 0 PID: 825 Comm: gst-launch-1.0 Tainted: G        WC        5.15.84-v8+ #1613
[  132.828713] Hardware name: Raspberry Pi Zero 2 W Rev 1.0 (DT)
[  132.828723] pstate: 20000005 (nzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[  132.828740] pc : __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  132.828788] lr : __vb2_queue_cancel+0x3c/0x220 [videobuf2_common]
[  132.828834] sp : ffffffc008b9baf0
[  132.828843] x29: ffffffc008b9baf0 x28: 0000000000000000 x27: ffffffc008b9bd28
[  132.828871] x26: 0000000000000000 x25: ffffff80072d4800 x24: ffffff8004bc2628
[  132.828898] x23: 0000000000000001 x22: ffffffe9b5c989a8 x21: ffffff8007b96028
[  132.828925] x20: ffffff8007b96028 x19: ffffff8007b96028 x18: 0000000000000001
[  132.828952] x17: 656c696146203a67 x16: 6e696d6165727473 x15: 5f706f74735f6365
[  132.828980] x14: 646f635f35333832 x13: 32362d2074657220 x12: ffffffe9b61b6660
[  132.829007] x11: 0000000000000003 x10: ffffffe9b619e620 x9 : ffffffe9b4eee9bc
[  132.829034] x8 : 0000000000017fe8 x7 : c0000000ffffefff x6 : 0000000000000001
[  132.829061] x5 : ffffff966601b000 x4 : 0000000000000000 x3 : 0000000000000001
[  132.829086] x2 : 0000000000000002 x1 : 0000000000000000 x0 : 0000000000000004
[  132.829113] Call trace:
[  132.829121]  __vb2_queue_cancel+0x1b8/0x220 [videobuf2_common]
[  132.829170]  vb2_core_streamoff+0x2c/0xc8 [videobuf2_common]
[  132.829218]  vb2_streamoff+0x24/0x78 [videobuf2_v4l2]
[  132.829256]  v4l2_m2m_streamoff+0x44/0x130 [v4l2_mem2mem]
[  132.829304]  v4l2_m2m_ioctl_streamoff+0x20/0x30 [v4l2_mem2mem]
[  132.829346]  v4l_streamoff+0x2c/0x38 [videodev]
[  132.829487]  __video_do_ioctl+0x188/0x410 [videodev]
[  132.829614]  video_usercopy+0x310/0x7d0 [videodev]
[  132.829742]  video_ioctl2+0x20/0x38 [videodev]
[  132.829870]  v4l2_ioctl+0x48/0x68 [videodev]
[  132.829994]  __arm64_sys_ioctl+0xb0/0xf0
[  132.830017]  invoke_syscall+0x4c/0x110
[  132.830036]  el0_svc_common.constprop.3+0xfc/0x120
[  132.830054]  do_el0_svc+0x2c/0x90
[  132.830071]  el0_svc+0x24/0x60
[  132.830087]  el0t_64_sync_handler+0x90/0xb8
[  132.830102]  el0t_64_sync+0x1a0/0x1a4
[  132.830119] ---[ end trace c260ec64c07e120f ]---
[  132.830132] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000009bd149e5 in active state
[  132.830162] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000002bc5953 in active state
[  132.830187] videobuf2_common: driver bug: stop_streaming operation is leaving buf 000000005bd8fb62 in active state
[  132.830211] videobuf2_common: driver bug: stop_streaming operation is leaving buf 0000000022f7b4ea in active state
[  135.899821] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  138.971792] bcm2835_mmal_vchiq: timed out waiting for sync completion

Additional context

No response

6by9 commented 1 year ago

Forum thread too - https://forums.raspberrypi.com/viewtopic.php?t=347942. Being able to reproduce with videotestsrc is going to be of more use than libcamerasrc.

Could you enable the firmware side asserts using start_debug=1 in config.txt, and reading out the log after the lockup with https://github.com/raspberrypi/utils/tree/master/vclog and sudo vclog --assert? (vclog replaces vcdbg and can work on 64bit userland). Also worth checking sudo vclog --msg.

There is a known issue with the H264 encoder that if rate control overshoots and ends up dropping the last frame of the encode, then it doesn't clean up properly. Only 2Mbit/s for a 1080p30 encode is pretty optimistic.

6by9 commented 1 year ago

CABAC is incompatible with CBR because of the way the encoder is pipelined. Drop to the baseline profile and it works.

I'll have a look at why this isn't validated when the encoder starts, as that can through an error to make the pipeline fail cleanly.

stephendade commented 1 year ago

I used this pipeline (1080p / main / CBR): 

gst-launch-1.0 -vvvv videotestsrc pattern=ball ! video/x-raw,width=1920,height=1080,framerate=25/1 ! v4l2convert ! v4l2h264enc extra-controls="controls,repeat_sequence_header=1,video_bitrate_mode=1,h264_profile=2,video_bitrate=5000000" ! 'video/x-h264,profile=main,level=(string)4' ! fakesink

Could you enable the firmware side asserts using start_debug=1 in config.txt, and reading out the log after the lockup with https://github.com/raspberrypi/utils/tree/master/vclog and sudo vclog --assert? (vclog replaces vcdbg and can work on 64bit userland). Also worth checking sudo vclog --msg.

Both sudo vclog --assert and sudo vclog --msg show no output after running the above pipeline.

However, using raspinfo, in the "demsg log" section was the following snippet:

[   94.631011] bcm2835_mmal_vchiq: timed out waiting for sync completion
[   94.631039] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling i/p port, ret -62
[   96.710986] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 2 outstanding
[   96.711025] ------------[ cut here ]------------
[   96.711038] WARNING: CPU: 2 PID: 964 at drivers/media/common/videobuf2/videobuf2-core.c:1995 __vb2_queue_cancel+0x1e0/0x258 [videobuf2_common]
[   96.711137] Modules linked in: xt_MASQUERADE xt_mark nft_compat nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_counter nf_tables cmac algif_hash aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc nfnetlink tun imx219 8021q garp stp llc brcmfmac brcmutil sha256_generic cfg80211 i2c_mux_pinctrl i2c_mux raspberrypi_hwmon rfkill bcm2835_isp(C) snd_bcm2835(C) bcm2835_unicam v4l2_dv_timings bcm2835_codec(C) v4l2_fwnode snd_pcm bcm2835_v4l2(C) v4l2_async v4l2_mem2mem videobuf2_vmalloc bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_memops snd_timer videobuf2_v4l2 videobuf2_common snd videodev vc_sm_cma(C) i2c_bcm2835 mc uio_pdrv_genirq fixed uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[   96.711931] CPU: 2 PID: 964 Comm: gst-launch-1.0 Tainted: G         C        5.15.84-v7+ #1613
[   96.711948] Hardware name: BCM2835
[   96.711957] Backtrace: 
[   96.711970] [<80a47ec8>] (dump_backtrace) from [<80a48110>] (show_stack+0x20/0x24)
[   96.712009]  r7:000007cb r6:80d19fc0 r5:00000000 r4:60000013
[   96.712017] [<80a480f0>] (show_stack) from [<80a4c6dc>] (dump_stack_lvl+0x70/0x94)
[   96.712048] [<80a4c66c>] (dump_stack_lvl) from [<80a4c718>] (dump_stack+0x18/0x1c)
[   96.712084]  r7:000007cb r6:00000009 r5:7f20268c r4:7f208064
[   96.712091] [<80a4c700>] (dump_stack) from [<80120b30>] (__warn+0xfc/0x114)
[   96.712121] [<80120a34>] (__warn) from [<80a486c8>] (warn_slowpath_fmt+0x70/0xd8)
[   96.712152]  r7:000007cb r6:7f208064 r5:81005008 r4:00000000
[   96.712160] [<80a4865c>] (warn_slowpath_fmt) from [<7f20268c>] (__vb2_queue_cancel+0x1e0/0x258 [videobuf2_common])
[   96.712255]  r9:81415bd0 r8:00000001 r7:7f1b0140 r6:8bc29978 r5:8bc29978 r4:8bc29978
[   96.712264] [<7f2024ac>] (__vb2_queue_cancel [videobuf2_common]) from [<7f203668>] (vb2_core_streamoff+0x28/0xbc [videobuf2_common])
[   96.712411]  r10:7f22d90c r9:81415bd0 r8:00000001 r7:7f1b0140 r6:0000000a r5:8bc29978
[   96.712422]  r4:8bc29978 r3:0000000a
[   96.712429] [<7f203640>] (vb2_core_streamoff [videobuf2_common]) from [<7f0980f0>] (vb2_streamoff+0x24/0x64 [videobuf2_v4l2])
[   96.712549]  r5:8bc29978 r4:8bc29800
[   96.712557] [<7f0980cc>] (vb2_streamoff [videobuf2_v4l2]) from [<7f260c3c>] (v4l2_m2m_streamoff+0x40/0x10c [v4l2_mem2mem])
[   96.712659] [<7f260bfc>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<7f260d28>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
[   96.712770]  r10:7f22d90c r9:81415bd0 r8:00000001 r7:7f1b0140 r6:81005008 r5:40045613
[   96.712780]  r4:7f260d08
[   96.712787] [<7f260d08>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<7f1b016c>] (v4l_streamoff+0x2c/0x30 [videodev])
[   96.713072] [<7f1b0140>] (v4l_streamoff [videodev]) from [<7f1b5470>] (__video_do_ioctl+0x234/0x460 [videodev])
[   96.713508]  r5:40045613 r4:814158a0
[   96.713516] [<7f1b523c>] (__video_do_ioctl [videodev]) from [<7f1b5c30>] (video_usercopy+0x140/0x630 [videodev])
[   96.713955]  r10:00000000 r9:00000000 r8:87c09e34 r7:00000000 r6:81005008 r5:40045613
[   96.713965]  r4:40045613
[   96.713973] [<7f1b5af0>] (video_usercopy [videodev]) from [<7f1b6140>] (video_ioctl2+0x20/0x24 [videodev])
[   96.714413]  r10:0000001a r9:0212ec08 r8:83c7eb40 r7:00000000 r6:76543844 r5:81005008
[   96.714423]  r4:7f1b6120
[   96.714430] [<7f1b6120>] (video_ioctl2 [videodev]) from [<7f1ae1f4>] (v4l2_ioctl+0x4c/0x60 [videodev])
[   96.714860] [<7f1ae1a8>] (v4l2_ioctl [videodev]) from [<80366908>] (sys_ioctl+0x12c/0xa20)
[   96.715095]  r5:81005008 r4:40045613
[   96.715103] [<803667dc>] (sys_ioctl) from [<80100040>] (ret_fast_syscall+0x0/0x1c)
[   96.715131] Exception stack(0x87c09fa8 to 0x87c09ff0)
[   96.715149] 9fa0:                   0215b0e0 76543000 0000001a 40045613 0212ec08 76b3ed40
[   96.715167] 9fc0: 0215b0e0 76543000 76543844 00000036 75a0ff30 766fba30 01f6df18 0215625c
[   96.715181] 9fe0: 76d68c88 7e94ecb4 76508264 76b3ed4c
[   96.715198]  r10:00000036 r9:87c08000 r8:80100244 r7:00000036 r6:76543844 r5:76543000
[   96.715207]  r4:0215b0e0
[   96.715215] ---[ end trace 0b47d1b1d2e2b573 ]---
[   96.715232] videobuf2_common: driver bug: stop_streaming operation is leaving buf 9ebdb769 in active state
[   96.715257] videobuf2_common: driver bug: stop_streaming operation is leaving buf 147080e6 in active state
[   99.750959] bcm2835_mmal_vchiq: timed out waiting for sync completion
[   99.750989] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling o/p port, ret -62
[  101.830940] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 4 outstanding
[  104.871087] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  104.871114] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed enabling component, ret -62
[  104.871136] ------------[ cut here ]------------
[  104.871149] WARNING: CPU: 2 PID: 964 at drivers/media/common/videobuf2/videobuf2-core.c:1995 __vb2_queue_cancel+0x1e0/0x258 [videobuf2_common]
[  104.871248] Modules linked in: xt_MASQUERADE xt_mark nft_compat nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_counter nf_tables cmac algif_hash aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc nfnetlink tun imx219 8021q garp stp llc brcmfmac brcmutil sha256_generic cfg80211 i2c_mux_pinctrl i2c_mux raspberrypi_hwmon rfkill bcm2835_isp(C) snd_bcm2835(C) bcm2835_unicam v4l2_dv_timings bcm2835_codec(C) v4l2_fwnode snd_pcm bcm2835_v4l2(C) v4l2_async v4l2_mem2mem videobuf2_vmalloc bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_memops snd_timer videobuf2_v4l2 videobuf2_common snd videodev vc_sm_cma(C) i2c_bcm2835 mc uio_pdrv_genirq fixed uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[  104.872038] CPU: 2 PID: 964 Comm: gst-launch-1.0 Tainted: G        WC        5.15.84-v7+ #1613
[  104.872055] Hardware name: BCM2835
[  104.872064] Backtrace: 
[  104.872077] [<80a47ec8>] (dump_backtrace) from [<80a48110>] (show_stack+0x20/0x24)
[  104.872117]  r7:000007cb r6:80d19fc0 r5:00000000 r4:60000013
[  104.872125] [<80a480f0>] (show_stack) from [<80a4c6dc>] (dump_stack_lvl+0x70/0x94)
[  104.872155] [<80a4c66c>] (dump_stack_lvl) from [<80a4c718>] (dump_stack+0x18/0x1c)
[  104.872191]  r7:000007cb r6:00000009 r5:7f20268c r4:7f208064
[  104.872198] [<80a4c700>] (dump_stack) from [<80120b30>] (__warn+0xfc/0x114)
[  104.872228] [<80120a34>] (__warn) from [<80a486c8>] (warn_slowpath_fmt+0x70/0xd8)
[  104.872259]  r7:000007cb r6:7f208064 r5:81005008 r4:00000000
[  104.872266] [<80a4865c>] (warn_slowpath_fmt) from [<7f20268c>] (__vb2_queue_cancel+0x1e0/0x258 [videobuf2_common])
[  104.872361]  r9:81415bd0 r8:00000001 r7:7f1b0140 r6:8bc29814 r5:8bc29814 r4:8bc29814
[  104.872369] [<7f2024ac>] (__vb2_queue_cancel [videobuf2_common]) from [<7f203668>] (vb2_core_streamoff+0x28/0xbc [videobuf2_common])
[  104.872516]  r10:7f22d90c r9:81415bd0 r8:00000001 r7:7f1b0140 r6:00000009 r5:8bc29814
[  104.872527]  r4:8bc29814 r3:00000009
[  104.872534] [<7f203640>] (vb2_core_streamoff [videobuf2_common]) from [<7f0980f0>] (vb2_streamoff+0x24/0x64 [videobuf2_v4l2])
[  104.872656]  r5:8bc29814 r4:8bc29800
[  104.872664] [<7f0980cc>] (vb2_streamoff [videobuf2_v4l2]) from [<7f260c3c>] (v4l2_m2m_streamoff+0x40/0x10c [v4l2_mem2mem])
[  104.872765] [<7f260bfc>] (v4l2_m2m_streamoff [v4l2_mem2mem]) from [<7f260d28>] (v4l2_m2m_ioctl_streamoff+0x20/0x24 [v4l2_mem2mem])
[  104.872876]  r10:7f22d90c r9:81415bd0 r8:00000001 r7:7f1b0140 r6:81005008 r5:40045613
[  104.872886]  r4:7f260d08
[  104.872893] [<7f260d08>] (v4l2_m2m_ioctl_streamoff [v4l2_mem2mem]) from [<7f1b016c>] (v4l_streamoff+0x2c/0x30 [videodev])
[  104.873175] [<7f1b0140>] (v4l_streamoff [videodev]) from [<7f1b5470>] (__video_do_ioctl+0x234/0x460 [videodev])
[  104.873609]  r5:40045613 r4:814158a0
[  104.873617] [<7f1b523c>] (__video_do_ioctl [videodev]) from [<7f1b5c30>] (video_usercopy+0x140/0x630 [videodev])
[  104.874058]  r10:00000000 r9:00000000 r8:87c09e34 r7:00000000 r6:81005008 r5:40045613
[  104.874067]  r4:40045613
[  104.874074] [<7f1b5af0>] (video_usercopy [videodev]) from [<7f1b6140>] (video_ioctl2+0x20/0x24 [videodev])
[  104.874511]  r10:00000015 r9:0212df08 r8:83c7eb40 r7:00000000 r6:76543844 r5:81005008
[  104.874521]  r4:7f1b6120
[  104.874528] [<7f1b6120>] (video_ioctl2 [videodev]) from [<7f1ae1f4>] (v4l2_ioctl+0x4c/0x60 [videodev])
[  104.874961] [<7f1ae1a8>] (v4l2_ioctl [videodev]) from [<80366908>] (sys_ioctl+0x12c/0xa20)
[  104.875198]  r5:81005008 r4:40045613
[  104.875206] [<803667dc>] (sys_ioctl) from [<80100040>] (ret_fast_syscall+0x0/0x1c)
[  104.875234] Exception stack(0x87c09fa8 to 0x87c09ff0)
[  104.875252] 9fa0:                   0215aeb0 76543000 00000015 40045613 0212df08 76b3ed40
[  104.875270] 9fc0: 0215aeb0 76543000 76543844 00000036 75a0ff30 766fba30 01f6df18 0215625c
[  104.875284] 9fe0: 76c45c58 7e94ecb4 76508264 76b3ed4c
[  104.875301]  r10:00000036 r9:87c08000 r8:80100244 r7:00000036 r6:76543844 r5:76543000
[  104.875311]  r4:0215aeb0
[  104.875320] ---[ end trace 0b47d1b1d2e2b574 ]---
[  104.875335] videobuf2_common: driver bug: stop_streaming operation is leaving buf 7d41fbf6 in active state
[  104.875358] videobuf2_common: driver bug: stop_streaming operation is leaving buf d6b5e2dc in active state
[  104.875378] videobuf2_common: driver bug: stop_streaming operation is leaving buf 1dae005b in active state
[  104.875396] videobuf2_common: driver bug: stop_streaming operation is leaving buf c55b39dc in active state
[  107.910903] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  110.950920] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  113.990894] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  113.990925] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling o/p port, ret -62
[  116.070871] bcm2835-codec bcm2835-codec: bcm2835_codec_flush_buffers: Timeout waiting for buffers to be returned - 2 outstanding
[  116.070905] ------------[ cut here ]------------
[  116.070918] WARNING: CPU: 2 PID: 964 at drivers/media/common/videobuf2/videobuf2-core.c:1995 __vb2_queue_cancel+0x1e0/0x258 [videobuf2_common]
[  116.071019] Modules linked in: xt_MASQUERADE xt_mark nft_compat nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nft_counter nf_tables cmac algif_hash aes_arm_bs crypto_simd cryptd algif_skcipher af_alg bnep hci_uart btbcm bluetooth ecdh_generic ecc nfnetlink tun imx219 8021q garp stp llc brcmfmac brcmutil sha256_generic cfg80211 i2c_mux_pinctrl i2c_mux raspberrypi_hwmon rfkill bcm2835_isp(C) snd_bcm2835(C) bcm2835_unicam v4l2_dv_timings bcm2835_codec(C) v4l2_fwnode snd_pcm bcm2835_v4l2(C) v4l2_async v4l2_mem2mem videobuf2_vmalloc bcm2835_mmal_vchiq(C) videobuf2_dma_contig videobuf2_memops snd_timer videobuf2_v4l2 videobuf2_common snd videodev vc_sm_cma(C) i2c_bcm2835 mc uio_pdrv_genirq fixed uio drm fuse drm_panel_orientation_quirks backlight ip_tables x_tables ipv6
[  116.071812] CPU: 2 PID: 964 Comm: gst-launch-1.0 Tainted: G        WC        5.15.84-v7+ #1613
[  116.071829] Hardware name: BCM2835
[  116.071840] Backtrace: 
[  116.071853] [<80a47ec8>] (dump_backtrace) from [<80a48110>] (show_stack+0x20/0x24)
[  116.071894]  r7:000007cb r6:80d19fc0 r5:00000000 r4:60000013
[  116.071902] [<80a480f0>] (show_stack) from [<80a4c6dc>] (dump_stack_lvl+0x70/0x94)
[  116.071932] [<80a4c66c>] (dump_stack_lvl) from [<80a4c718>] (dump_stack+0x18/0x1c)
[  116.071967]  r7:000007cb r6:00000009 r5:7f20268c r4:7f208064
[  116.071975] [<80a4c700>] (dump_stack) from [<80120b30>] (__warn+0xfc/0x114)
[  116.072004] [<80120a34>] (__warn) from [<80a486c8>] (warn_slowpath_fmt+0x70/0xd8)
[  116.072034]  r7:000007cb r6:7f208064 r5:81005008 r4:00000000
[  116.072042] [<80a4865c>] (warn_slowpath_fmt) from [<7f20268c>] (__vb2_queue_cancel+0x1e0/0x258 [videobuf2_common])
[  116.072137]  r9:00000000 r8:823d8aa0 r7:824c50d0 r6:8bc28014 r5:8bc28074 r4:8bc28014
[  116.072146] [<7f2024ac>] (__vb2_queue_cancel [videobuf2_common]) from [<7f204cf0>] (vb2_core_queue_release+0x28/0x48 [videobuf2_common])
[  116.072293]  r10:85e81500 r9:00000000 r8:823d8aa0 r7:824c50d0 r6:814163d0 r5:8bc28074
[  116.072304]  r4:8bc28014 r3:977f7b4c
[  116.072311] [<7f204cc8>] (vb2_core_queue_release [videobuf2_common]) from [<7f09662c>] (vb2_queue_release+0x18/0x1c [videobuf2_v4l2])
[  116.072433]  r5:86b16000 r4:8bc28000
[  116.072440] [<7f096614>] (vb2_queue_release [videobuf2_v4l2]) from [<7f261314>] (v4l2_m2m_ctx_release+0x24/0x38 [v4l2_mem2mem])
[  116.072542] [<7f2612f0>] (v4l2_m2m_ctx_release [v4l2_mem2mem]) from [<7f228e24>] (bcm2835_codec_release+0x7c/0xc8 [bcm2835_codec])
[  116.072640]  r5:86b16000 r4:81416040
[  116.072648] [<7f228da8>] (bcm2835_codec_release [bcm2835_codec]) from [<7f1ae6f0>] (v4l2_release+0xd8/0xe4 [videodev])
[  116.072925]  r7:824c50d0 r6:83f607d8 r5:83c7e300 r4:814160a0
[  116.072933] [<7f1ae618>] (v4l2_release [videodev]) from [<80350874>] (__fput+0x8c/0x274)
[  116.073165]  r5:000e001f r4:83c7e300
[  116.073174] [<803507e8>] (__fput) from [<80350a74>] (____fput+0x18/0x1c)
[  116.073206]  r9:00000000 r8:8114fd00 r7:85e88fc0 r6:85e8952c r5:829970c0 r4:83c7e300
[  116.073214] [<80350a5c>] (____fput) from [<80143138>] (task_work_run+0xb4/0xe4)
[  116.073244] [<80143084>] (task_work_run) from [<8012592c>] (do_exit+0x4ac/0xb88)
[  116.073282]  r9:00000000 r8:87c09f44 r7:87c09e9c r6:87c08000 r5:8243dc00 r4:85e88fc0
[  116.073290] [<80125480>] (do_exit) from [<801260a4>] (do_group_exit+0x50/0xe0)
[  116.073318]  r7:ffffe000
[  116.073325] [<80126054>] (do_group_exit) from [<801340cc>] (get_signal+0x1e8/0xb38)
[  116.073360]  r7:ffffe000 r6:00000009 r5:00418004 r4:00000008
[  116.073368] [<80133ee4>] (get_signal) from [<8010b728>] (do_work_pending+0x158/0x5a4)
[  116.073404]  r10:81005008 r9:fffffe30 r8:87c09f44 r7:76b3ed4c r6:76b3ed48 r5:87c09fb0
[  116.073413]  r4:ffffe000
[  116.073420] [<8010b5d0>] (do_work_pending) from [<80100068>] (slow_work_pending+0xc/0x20)
[  116.073445] Exception stack(0x87c09fb0 to 0x87c09ff8)
[  116.073460] 9fa0:                                     00000000 40045613 0212df08 76b3ed40
[  116.073478] 9fc0: 0215aeb0 76543000 76543844 00000036 75a0ff30 766fba30 01f6df18 0215625c
[  116.073494] 9fe0: 76c45c58 7e94ecb4 76508264 76b3ed4c 80000010 00000015
[  116.073511]  r10:00000036 r9:87c08000 r8:80100244 r7:00000036 r6:76543844 r5:76543000
[  116.073521]  r4:0215aeb0
[  116.073529] ---[ end trace 0b47d1b1d2e2b575 ]---
[  116.073545] videobuf2_common: driver bug: stop_streaming operation is leaving buf 39c303f8 in active state
[  116.073569] videobuf2_common: driver bug: stop_streaming operation is leaving buf dfda7380 in active state
[  119.110863] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  119.110894] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed disabling i/p port, ret -62
[  122.150873] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  122.150902] bcm2835-codec bcm2835-codec: bcm2835_codec_stop_streaming: Failed enabling component, ret -62
[  125.190876] bcm2835_mmal_vchiq: timed out waiting for sync completion
[  128.230859] bcm2835_mmal_vchiq: timed out waiting for sync completion
stephendade commented 1 year ago

CABAC is incompatible with CBR because of the way the encoder is pipelined. Drop to the baseline profile and it works.

Is CABAC only applicable at higher resolutions (1080p)? I ask because smaller resolutions (720p, for example) worked with no issues with the main profile in CBR mode.

6by9 commented 1 year ago

Is CABAC only applicable at higher resolutions (1080p)? I ask because smaller resolutions (720p, for example) worked with no issues with the main profile in CBR mode.

I suspect it is the pipelining that is the issue - CABAC is done after the main encode. Rate control needs to know the size of the final encoded frame, and that includes CABAC. 720p at the same framerate is likely to get the frame through the whole pipeline in less than the frame time, therefore rate control has all the required information. 1080p will overlap the encode and CABAC, so rate control gets confused.

CBR with high profile is blocked in the firmware, but for some reason main profile with CBR isn't even though it also supports CABAC. I have a patch prepared to block this too (stream_on will fail in the encoder), but I would like to understand the limitation before just pushing it.