[BUG] IMX462 long exposures broken when AWB disabled

aaronwmorris commented 1 year ago

Describe the bug Long exposures appear to be broken on imx462 cameras when AWB is disabled.

AWB enabled

I am not sure why the exposure is taking 20s in the first example. It could be the AWB code, but there should be enough illumination for this to not happen.

$ time libcamera-still --immediate --nopreview --raw --gain 31 --shutter 5000000  --metadata /tmp/foobar.json --output /tmp/foobar.dng [5:54:11.728762197] [4406]  INFO Camera camera_manager.cpp:297 libcamera v0.0.5+83-bde9b04f
[5:54:11.787281894] [4407]  INFO RPI vc4.cpp:437 Registered camera /base/soc/i2c0mux/i2c@1/imx290@1a to Unicam device /dev/media2 and ISP device /dev/media0
[5:54:11.787430956] [4407]  INFO RPI pipeline_base.cpp:1101 Using configuration file '/usr/share/libcamera/pipeline/rpi/vc4/rpi_apps.yaml'
[5:54:11.789650057] [4406]  INFO Camera camera.cpp:1033 configuring streams: (0) 1920x1080-YUV420 (1) 1920x1080-SRGGB12_CSI2P
[5:54:11.790346302] [4407]  INFO RPI vc4.cpp:565 Sensor: /base/soc/i2c0mux/i2c@1/imx290@1a - Selected sensor format: 1920x1080-SRGGB12_1X12 - Selected unicam format: 1920x1080-pRCC
Still capture image received
Bayer format is RGGB-12

real    0m21.210s
user    0m0.809s
sys     0m0.105s

$ json_pp < /tmp/foobar.json | grep ExposureTime
   "ExposureTime" : 4999977,

AWB Disabled

Exposure is received in less than 2 seconds. The same thing happens no matter how long of an exposure.

$ time libcamera-still --immediate --nopreview --raw --gain 31 --shutter 5000000  --metadata /tmp/foobar.json --output /tmp/foobar.dng --awbgains 1,1
[5:57:04.892732196] [4687]  INFO Camera camera_manager.cpp:297 libcamera v0.0.5+83-bde9b04f
[5:57:04.952279229] [4688]  INFO RPI vc4.cpp:437 Registered camera /base/soc/i2c0mux/i2c@1/imx290@1a to Unicam device /dev/media2 and ISP device /dev/media0
[5:57:04.952395582] [4688]  INFO RPI pipeline_base.cpp:1101 Using configuration file '/usr/share/libcamera/pipeline/rpi/vc4/rpi_apps.yaml'
[5:57:04.954211925] [4687]  INFO Camera camera.cpp:1033 configuring streams: (0) 1920x1080-YUV420 (1) 1920x1080-SRGGB12_CSI2P
[5:57:04.954860723] [4688]  INFO RPI vc4.cpp:565 Sensor: /base/soc/i2c0mux/i2c@1/imx290@1a - Selected sensor format: 1920x1080-SRGGB12_1X12 - Selected unicam format: 1920x1080-pRCC
Still capture image received
Bayer format is RGGB-12

real    0m1.210s
user    0m0.760s
sys     0m0.124s

$ json_pp < /tmp/foobar.json |grep ExposureTime
   "ExposureTime" : 4999214,

Bug report

--------------------------------------------------------------------------------
libcamera-apps Bug Report
--------------------------------------------------------------------------------
Date: 23-08-2023 (21:45:47)
Command: /usr/bin/camera-bug-report -t 5 -o bug.txt -c libcamera-still -t 1000 -o test.jpg

--------------------------------------------------------------------------------
Hardware information
--------------------------------------------------------------------------------
** hostname **
raspberrypi

** cat /proc/cpuinfo **
processor       : 0
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 1
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 2
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 3
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 76.80
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

Hardware        : BCM2835
Revision        : a02082
Serial          : 000000003e13cbf1
Model           : Raspberry Pi 3 Model B Rev 1.2

--------------------------------------------------------------------------------
Configuration
--------------------------------------------------------------------------------
** cat /boot/cmdline.txt **
console=serial0,115200 console=tty1 root=PARTUUID=d9804b11-02 rootfstype=ext4 fsck.repair=yes rootwait

** cat /boot/config.txt **
# For more options and information see
# http://rpf.io/configtxt
# Some settings may impact device functionality. See link above for details

# uncomment if you get no picture on HDMI for a default "safe" mode
#hdmi_safe=1

# uncomment the following to adjust overscan. Use positive numbers if console
# goes off screen, and negative if there is too much border
#overscan_left=16
#overscan_right=16
#overscan_top=16
#overscan_bottom=16

# uncomment to force a console size. By default it will be display's size minus
# overscan.
#framebuffer_width=1280
#framebuffer_height=720

# uncomment if hdmi display is not detected and composite is being output
#hdmi_force_hotplug=1

# uncomment to force a specific HDMI mode (this will force VGA)
#hdmi_group=1
#hdmi_mode=1

# uncomment to force a HDMI mode rather than DVI. This can make audio work in
# DMT (computer monitor) modes
#hdmi_drive=2

# uncomment to increase signal to HDMI, if you have interference, blanking, or
# no display
#config_hdmi_boost=4

# uncomment for composite PAL
#sdtv_mode=2

#uncomment to overclock the arm. 700 MHz is the default.
#arm_freq=800

# Uncomment some or all of these to enable the optional hardware interfaces
#dtparam=i2c_arm=on
#dtparam=i2s=on
#dtparam=spi=on

# Uncomment this to enable infrared communication.
#dtoverlay=gpio-ir,gpio_pin=17
#dtoverlay=gpio-ir-tx,gpio_pin=18

# Additional overlays and parameters are documented /boot/overlays/README

# Enable audio (loads snd_bcm2835)
dtparam=audio=on

# Automatically load overlays for detected cameras
camera_auto_detect=1

# Automatically load overlays for detected DSI displays
display_auto_detect=1

# Enable DRM VC4 V3D driver
dtoverlay=vc4-kms-v3d
max_framebuffers=2

# Disable compensation for displays with overscan
disable_overscan=1

[cm4]
# Enable host mode on the 2711 built-in XHCI USB controller.
# This line should be removed if the legacy DWC2 controller is required
# (e.g. for USB device mode) or if USB support is not required.
otg_mode=1

[all]

[pi4]
# Run as fast as firmware / board allows
arm_boost=1

[all]
dtoverlay=imx462,clock-frequency=74250000
#dtoverlay=imx290,clock-frequency=74250000
gpu_mem=32

--------------------------------------------------------------------------------
Logs
--------------------------------------------------------------------------------
** dmesg **
[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 6.1.21-v7+ (dom@buildbot) (arm-linux-gnueabihf-gcc-8 (Ubuntu/Linaro 8.4.0-3ubuntu1) 8.4.0, GNU ld (GNU Binutils for Ubuntu) 2.34) #1642 SMP Mon Apr  3 17:20:52 BST 2023
[    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 Rev 1.2
[    0.000000] random: crng init done
[    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] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000000000-0x000000003dffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x000000003dffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x000000003dffffff]
[    0.000000] percpu: Embedded 17 pages/cpu s36884 r8192 d24556 u69632
[    0.000000] pcpu-alloc: s36884 r8192 d24556 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 251720
[    0.000000] Kernel command line: coherent_pool=1M 8250.nr_uarts=0 snd_bcm2835.enable_headphones=0 snd_bcm2835.enable_headphones=1 snd_bcm2835.enable_hdmi=1 snd_bcm2835.enable_hdmi=0 video=HDMI-A-1:1024x768M@60 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  console=ttyS0,115200 console=tty1 root=PARTUUID=d9804b11-02 rootfstype=ext4 fsck.repair=yes rootwait
[    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: 725584K/1015808K available (10240K kernel code, 1452K rwdata, 2900K rodata, 1024K init, 613K bss, 28080K reserved, 262144K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 34800 entries in 103 pages
[    0.000000] ftrace: allocated 102 pages with 4 groups
[    0.000000] trace event string verifier disabled
[    0.000000] rcu: Hierarchical RCU implementation.
[    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 10 jiffies.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    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.000002] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000019] Switching to timer-based delay loop, resolution 52ns
[    0.000390] Console: colour dummy device 80x30
[    0.001015] printk: console [tty1] enabled
[    0.001079] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.001125] pid_max: default: 32768 minimum: 301
[    0.001288] LSM: Security Framework initializing
[    0.001525] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.001569] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.002789] cgroup: Disabling memory control group subsystem
[    0.003048] CPU: Testing write buffer coherency: ok
[    0.003513] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.004380] cblist_init_generic: Setting adjustable number of callback queues.
[    0.004419] cblist_init_generic: Setting shift to 2 and lim to 1.
[    0.004548] cblist_init_generic: Setting shift to 2 and lim to 1.
[    0.004702] Setting up static identity map for 0x100000 - 0x10003c
[    0.004859] rcu: Hierarchical SRCU implementation.
[    0.004883] rcu:     Max phase no-delay instances is 1000.
[    0.005613] smp: Bringing up secondary CPUs ...
[    0.006543] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.007501] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.008370] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.008474] smp: Brought up 1 node, 4 CPUs
[    0.008556] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.008584] CPU: All CPU(s) started in HYP mode.
[    0.008603] CPU: Virtualization extensions available.
[    0.009396] devtmpfs: initialized
[    0.024573] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.024815] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.024871] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.035244] pinctrl core: initialized pinctrl subsystem
[    0.036469] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.039715] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.044827] audit: initializing netlink subsys (disabled)
[    0.045087] audit: type=2000 audit(0.040:1): state=initialized audit_enabled=0 res=1
[    0.045706] thermal_sys: Registered thermal governor 'step_wise'
[    0.046634] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.046687] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.046955] Serial: AMBA PL011 UART driver
[    0.053316] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.057648] platform 3f801000.csi: Fixed dependency cycle(s) with /soc/i2c0mux/i2c@1/imx290@1a
[    0.070070] raspberrypi-firmware soc:firmware: Attached to firmware from 2023-03-17T10:52:42, variant start
[    0.080085] raspberrypi-firmware soc:firmware: Firmware hash is 82f3750a65fadae9a38077e3c2e217ad158c8d54
[    0.122781] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible.
[    0.128569] bcm2835-dma 3f007000.dma: DMA legacy API manager, dmachans=0x1
[    0.130291] SCSI subsystem initialized
[    0.130546] usbcore: registered new interface driver usbfs
[    0.130627] usbcore: registered new interface driver hub
[    0.130696] usbcore: registered new device driver usb
[    0.130944] usb_phy_generic phy: supply vcc not found, using dummy regulator
[    0.131133] usb_phy_generic phy: dummy supplies not allowed for exclusive requests
[    0.131418] pps_core: LinuxPPS API ver. 1 registered
[    0.131443] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.131492] PTP clock support registered
[    2.009836] clocksource: Switched to clocksource arch_sys_counter
[    2.108139] VFS: Disk quotas dquot_6.6.0
[    2.108267] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    2.108458] FS-Cache: Loaded
[    2.108740] CacheFiles: Loaded
[    2.117213] NET: Registered PF_INET protocol family
[    2.117529] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    2.120065] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 4096 bytes, linear)
[    2.120125] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    2.120236] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    2.120376] TCP bind hash table entries: 8192 (order: 5, 131072 bytes, linear)
[    2.120725] TCP: Hash tables configured (established 8192 bind 8192)
[    2.120885] UDP hash table entries: 512 (order: 2, 16384 bytes, linear)
[    2.120957] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes, linear)
[    2.121203] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    2.121770] RPC: Registered named UNIX socket transport module.
[    2.121800] RPC: Registered udp transport module.
[    2.121822] RPC: Registered tcp transport module.
[    2.121843] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    2.123525] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    2.126696] Initialise system trusted keyrings
[    2.126958] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    2.136203] zbud: loaded
[    2.138614] NFS: Registering the id_resolver key type
[    2.138674] Key type id_resolver registered
[    2.138697] Key type id_legacy registered
[    2.138836] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.138865] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    2.140180] Key type asymmetric registered
[    2.140209] Asymmetric key parser 'x509' registered
[    2.140407] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[    2.140441] io scheduler mq-deadline registered
[    2.140466] io scheduler kyber registered
[    2.145677] simple-framebuffer 3e8fa000.framebuffer: framebuffer at 0x3e8fa000, 0x300000 bytes
[    2.145742] simple-framebuffer 3e8fa000.framebuffer: format=a8r8g8b8, mode=1024x768x32, linelength=4096
[    2.155982] Console: switching to colour frame buffer device 128x48
[    2.165426] simple-framebuffer 3e8fa000.framebuffer: fb0: simplefb registered!
[    2.170374] bcm2835-rng 3f104000.rng: hwrng registered
[    2.170890] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    2.171888] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    2.183251] brd: module loaded
[    2.190726] loop: module loaded
[    2.191440] Loading iSCSI transport class v2.0-870.
[    2.193007] usbcore: registered new interface driver lan78xx
[    2.193193] usbcore: registered new interface driver smsc95xx
[    2.193346] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    2.921557] Core Release: 2.80a
[    2.921647] Setting default values for core params
[    2.921776] Finished setting default values for core params
[    3.126180] Using Buffer DMA mode
[    3.130285] Periodic Transfer Interrupt Enhancement - disabled
[    3.134393] Multiprocessor Interrupt Enhancement - disabled
[    3.138470] OTG VER PARAM: 0, OTG VER FLAG: 0
[    3.142576] Dedicated Tx FIFOs mode

[    3.147178] WARN::dwc_otg_hcd_init:1074: FIQ DMA bounce buffers: virt = 9ed04000 dma = 0xded04000 len=9024
[    3.155586] FIQ FSM acceleration enabled for :
               Non-periodic Split Transactions
               Periodic Split Transactions
               High-Speed Isochronous Endpoints
               Interrupt/Control Split Transaction hack enabled
[    3.176248] dwc_otg: Microframe scheduler enabled

[    3.176365] WARN::hcd_init_fiq:457: FIQ on core 1

[    3.184482] WARN::hcd_init_fiq:458: FIQ ASM at 807c4360 length 36

[    3.192663] WARN::hcd_init_fiq:497: MPHI regs_base at be810000
[    3.200808] dwc_otg 3f980000.usb: DWC OTG Controller
[    3.204928] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    3.209089] dwc_otg 3f980000.usb: irq 89, io mem 0x00000000
[    3.213239] Init: Port Power? op_state=1
[    3.217247] Init: Power Port (0)
[    3.221465] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
[    3.225613] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    3.229725] usb usb1: Product: DWC OTG Controller
[    3.233773] usb usb1: Manufacturer: Linux 6.1.21-v7+ dwc_otg_hcd
[    3.237784] usb usb1: SerialNumber: 3f980000.usb
[    3.242361] hub 1-0:1.0: USB hub found
[    3.246267] hub 1-0:1.0: 1 port detected
[    3.250730] dwc_otg: FIQ enabled
[    3.250740] dwc_otg: NAK holdoff enabled
[    3.250749] dwc_otg: FIQ split-transaction FSM enabled
[    3.250764] Module dwc_common_port init
[    3.251071] usbcore: registered new interface driver usb-storage
[    3.255129] mousedev: PS/2 mouse device common for all mice
[    3.261465] sdhci: Secure Digital Host Controller Interface driver
[    3.265229] sdhci: Copyright(c) Pierre Ossman
[    3.269181] sdhci-pltfm: SDHCI platform and OF driver helper
[    3.275077] ledtrig-cpu: registered to indicate activity on CPUs
[    3.279209] hid: raw HID events driver (C) Jiri Kosina
[    3.283175] usbcore: registered new interface driver usbhid
[    3.287006] usbhid: USB HID core driver
[    3.294966] Initializing XFRM netlink socket
[    3.298875] NET: Registered PF_PACKET protocol family
[    3.302801] Key type dns_resolver registered
[    3.307319] Registering SWP/SWPB emulation handler
[    3.311764] registered taskstats version 1
[    3.315527] Loading compiled-in X.509 certificates
[    3.320105] Key type .fscrypt registered
[    3.323793] Key type fscrypt-provisioning registered
[    3.338921] uart-pl011 3f201000.serial: cts_event_workaround enabled
[    3.342919] 3f201000.serial: ttyAMA0 at MMIO 0x3f201000 (irq = 114, base_baud = 0) is a PL011 rev2
[    3.348814] bcm2835-wdt bcm2835-wdt: Broadcom BCM2835 watchdog timer
[    3.352904] bcm2835-power bcm2835-power: Broadcom BCM2835 power domains driver
[    3.358022] mmc-bcm2835 3f300000.mmcnr: mmc_debug:0 mmc_debug2:0
[    3.361916] mmc-bcm2835 3f300000.mmcnr: DMA channel allocated
[    3.379965] Indeed it is in host mode hprt0 = 00021501
[    3.443956] sdhost: log_buf @ 906ba746 (ded07000)
[    3.497790] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1)
[    3.504012] of_cfs_init
[    3.507996] of_cfs_init: OK
[    3.513164] Waiting for root device PARTUUID=d9804b11-02...
[    3.551406] mmc1: new high speed SDIO card at address 0001
[    3.563531] mmc0: host does not support reading read-only switch, assuming write-enable
[    3.571826] mmc0: new high speed SDXC card at address aaaa
[    3.576546] mmcblk0: mmc0:aaaa SD128 119 GiB 
[    3.584096]  mmcblk0: p1 p2
[    3.588590] mmcblk0: mmc0:aaaa SD128 119 GiB (quirks 0x00004000)
[    3.589876] usb 1-1: new high-speed USB device number 2 using dwc_otg
[    3.596529] Indeed it is in host mode hprt0 = 00001101
[    3.647391] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Quota mode: none.
[    3.651483] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    3.663261] devtmpfs: mounted
[    3.673181] Freeing unused kernel image (initmem) memory: 1024K
[    3.680358] Run /sbin/init as init process
[    3.684411]   with arguments:
[    3.684419]     /sbin/init
[    3.684427]   with environment:
[    3.684433]     HOME=/
[    3.684440]     TERM=linux
[    3.840163] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[    3.844496] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.849464] hub 1-1:1.0: USB hub found
[    3.853808] hub 1-1:1.0: 5 ports detected
[    4.179870] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[    4.202352] systemd[1]: System time before build time, advancing clock.
[    4.310189] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[    4.314502] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    4.321526] smsc95xx v2.0.0
[    4.441814] SMSC LAN8700 usb-001:003:01: attached PHY driver (mii_bus:phy_addr=usb-001:003:01, irq=199)
[    4.447157] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:13:cb:f1
[    4.471234] NET: Registered PF_INET6 protocol family
[    4.477337] Segment Routing with IPv6
[    4.481966] In-situ OAM (IOAM) with IPv6
[    4.551042] systemd[1]: systemd 247.3-7+rpi1+deb11u2 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.566641] systemd[1]: Detected architecture arm.
[    4.610359] systemd[1]: Set hostname to <raspberrypi>.
[    4.749960] usb 1-1.4: new full-speed USB device number 4 using dwc_otg
[    4.889631] usb 1-1.4: New USB device found, idVendor=1997, idProduct=2433, bcdDevice=20.12
[    4.895105] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    4.900083] usb 1-1.4: Product: Mini Keyboard
[    4.905033] usb 1-1.4: Manufacturer:  
[    4.916651] input:   Mini Keyboard as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4:1.0/0003:1997:2433.0001/input/input0
[    4.990787] hid-generic 0003:1997:2433.0001: input,hidraw0: USB HID v1.01 Keyboard [  Mini Keyboard] on usb-3f980000.usb-1.4/input0
[    5.009491] input:   Mini Keyboard Mouse as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4:1.1/0003:1997:2433.0002/input/input1
[    5.021311] input:   Mini Keyboard System Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4:1.1/0003:1997:2433.0002/input/input2
[    5.100394] input:   Mini Keyboard Consumer Control as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.4/1-1.4:1.1/0003:1997:2433.0002/input/input3
[    5.112725] hid-generic 0003:1997:2433.0002: input,hidraw1: USB HID v1.01 Mouse [  Mini Keyboard] on usb-3f980000.usb-1.4/input1
[    5.787021] systemd[1]: Queued start job for default target Multi-User System.
[    5.833893] systemd[1]: Created slice system-getty.slice.
[    5.848292] systemd[1]: Created slice system-modprobe.slice.
[    5.862388] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    5.876278] systemd[1]: Created slice User and Session Slice.
[    5.889638] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    5.903044] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    5.917191] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    5.930635] systemd[1]: Reached target Local Encrypted Volumes.
[    5.944321] systemd[1]: Reached target Paths.
[    5.957369] systemd[1]: Reached target Slices.
[    5.970005] systemd[1]: Reached target Swap.
[    5.983683] systemd[1]: Listening on Syslog Socket.
[    5.997040] systemd[1]: Listening on fsck to fsckd communication Socket.
[    6.010115] systemd[1]: Listening on initctl Compatibility Named Pipe.
[    6.024040] systemd[1]: Listening on Journal Audit Socket.
[    6.037547] systemd[1]: Listening on Journal Socket (/dev/log).
[    6.050957] systemd[1]: Listening on Journal Socket.
[    6.064948] systemd[1]: Listening on udev Control Socket.
[    6.077324] systemd[1]: Listening on udev Kernel Socket.
[    6.089600] systemd[1]: Condition check resulted in Huge Pages File System being skipped.
[    6.140319] systemd[1]: Mounting POSIX Message Queue File System...
[    6.156586] systemd[1]: Mounting RPC Pipe File System...
[    6.173615] systemd[1]: Mounting Kernel Debug File System...
[    6.190462] systemd[1]: Mounting Kernel Trace File System...
[    6.202941] systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.
[    6.215421] systemd[1]: Starting Restore / save the current clock...
[    6.232952] systemd[1]: Starting Set the console keyboard layout...
[    6.251513] systemd[1]: Starting Create list of static device nodes for the current kernel...
[    6.271182] systemd[1]: Starting Load Kernel Module configfs...
[    6.288340] systemd[1]: Starting Load Kernel Module drm...
[    6.306189] systemd[1]: Starting Load Kernel Module fuse...
[    6.326231] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
[    6.337998] systemd[1]: Starting File System Check on Root Device...
[    6.363697] systemd[1]: Starting Journal Service...
[    6.384566] fuse: init (API version 7.37)
[    6.397737] systemd[1]: Starting Load Kernel Modules...
[    6.440846] systemd[1]: Starting Coldplug All udev Devices...
[    6.481943] systemd[1]: Mounted POSIX Message Queue File System.
[    6.494473] systemd[1]: Mounted RPC Pipe File System.
[    6.518083] systemd[1]: Mounted Kernel Debug File System.
[    6.530974] systemd[1]: Mounted Kernel Trace File System.
[    6.544012] systemd[1]: Finished Restore / save the current clock.
[    6.570000] systemd[1]: Finished Create list of static device nodes for the current kernel.
[    6.582761] systemd[1]: modprobe@configfs.service: Succeeded.
[    6.589117] systemd[1]: Finished Load Kernel Module configfs.
[    6.602359] systemd[1]: modprobe@drm.service: Succeeded.
[    6.608916] systemd[1]: Finished Load Kernel Module drm.
[    6.627126] systemd[1]: modprobe@fuse.service: Succeeded.
[    6.639462] systemd[1]: Finished Load Kernel Module fuse.
[    6.651888] systemd[1]: Finished Load Kernel Modules.
[    6.740662] systemd[1]: Mounting FUSE Control File System...
[    6.755760] systemd[1]: Mounting Kernel Configuration File System...
[    6.800302] systemd[1]: Started File System Check Daemon to report status.
[    6.825296] systemd[1]: Starting Apply Kernel Variables...
[    6.847195] systemd[1]: Started Journal Service.
[    7.201413] EXT4-fs (mmcblk0p2): re-mounted. Quota mode: none.
[    7.360203] systemd-journald[138]: Received client request to flush runtime journal.
[    8.599776] vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned.
[    8.608820] mc: Linux media interface: v0.10
[    8.630346] bcm2835_vc_sm_cma_probe: Videocore shared memory driver
[    8.630397] [vc_sm_connected_init]: start
[    8.650360] [vc_sm_connected_init]: installed successfully
[    8.842676] videodev: Linux video capture interface: v2.00
[    8.971412] snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned.
[    9.016585] bcm2835_audio bcm2835_audio: card created with 8 channels
[    9.027310] bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned.
[    9.046503] bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned.
[    9.067033] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13
[    9.067693] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14
[    9.068164] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15
[    9.068491] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16
[    9.068520] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    9.068542] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    9.068559] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    9.068577] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    9.073457] bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20
[    9.073984] bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21
[    9.074386] bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22
[    9.074705] bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23
[    9.074734] bcm2835-isp bcm2835-isp: Register output node 0 with media controller
[    9.074756] bcm2835-isp bcm2835-isp: Register capture node 1 with media controller
[    9.074773] bcm2835-isp bcm2835-isp: Register capture node 2 with media controller
[    9.074800] bcm2835-isp bcm2835-isp: Register capture node 3 with media controller
[    9.074982] bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp
[    9.100756] bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned.
[    9.112248] bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned.
[    9.146280] bcm2835-codec bcm2835-codec: Device registered as /dev/video10
[    9.146505] bcm2835-codec bcm2835-codec: Loaded V4L2 decode
[    9.163887] bcm2835-codec bcm2835-codec: Device registered as /dev/video11
[    9.164087] bcm2835-codec bcm2835-codec: Loaded V4L2 encode
[    9.180428] bcm2835-codec bcm2835-codec: Device registered as /dev/video12
[    9.180499] bcm2835-codec bcm2835-codec: Loaded V4L2 isp
[    9.183734] bcm2835-codec bcm2835-codec: Device registered as /dev/video18
[    9.183791] bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx
[    9.192163] bcm2835-codec bcm2835-codec: Device registered as /dev/video31
[    9.192229] bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image
[    9.291520] i2c i2c-11: Added multiplexed i2c bus 0
[    9.292145] i2c i2c-11: Added multiplexed i2c bus 10
[    9.683457] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    9.843889] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    9.919212] cfg80211: loaded regulatory.db is malformed or signature is missing/invalid
[   10.360203] brcmfmac: F1 signature read @0x18000000=0x1541a9a6
[   10.370390] brcmfmac: brcmf_fw_alloc_request: using brcm/brcmfmac43430-sdio for chip BCM43430/1
[   10.371196] usbcore: registered new interface driver brcmfmac
[   10.497204] Console: switching to colour dummy device 80x30
[   10.510794] vc4-drm soc:gpu: bound 3f400000.hvs (ops vc4_hvs_ops [vc4])
[   10.519466] Registered IR keymap rc-cec
[   10.537013] rc rc0: vc4-hdmi as /devices/platform/soc/3f902000.hdmi/rc/rc0
[   10.537421] input: vc4-hdmi as /devices/platform/soc/3f902000.hdmi/rc/rc0/input4
[   10.544190] vc4-drm soc:gpu: bound 3f902000.hdmi (ops vc4_hdmi_ops [vc4])
[   10.544789] vc4-drm soc:gpu: bound 3f004000.txp (ops vc4_txp_ops [vc4])
[   10.545366] vc4-drm soc:gpu: bound 3f206000.pixelvalve (ops vc4_crtc_ops [vc4])
[   10.545852] vc4-drm soc:gpu: bound 3f207000.pixelvalve (ops vc4_crtc_ops [vc4])
[   10.546326] vc4-drm soc:gpu: bound 3f807000.pixelvalve (ops vc4_crtc_ops [vc4])
[   10.546727] vc4-drm soc:gpu: bound 3fc00000.v3d (ops vc4_v3d_ops [vc4])
[   10.559443] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
[   10.627467] brcmfmac: brcmf_c_preinit_dcmds: Firmware: BCM43430/1 wl0: Jul 19 2021 03:24:18 version 7.45.98 (TOB) (56df937 CY) FWID 01-8e14b897
[   10.772040] Console: switching to colour frame buffer device 128x48
[   10.813622] vc4-drm soc:gpu: [drm] fb0: vc4drmfb frame buffer device
[   10.941011] 8021q: 802.1Q VLAN Support v1.8
[   11.103851] uart-pl011 3f201000.serial: no DMA platform data
[   11.179487] Adding 102396k swap on /var/swap.  Priority:-2 extents:1 across:102396k SSFS
[   11.293152] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[   11.298318] smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off
[   11.298428] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   12.506241] ICMPv6: process `dhcpcd' is using deprecated sysctl (syscall) net.ipv6.neigh.eth0.retrans_time - use net.ipv6.neigh.eth0.retrans_time_ms instead
[   12.591046] imx290 10-001a: Consider updating driver imx290 to match on endpoints
[   15.736619] Bluetooth: Core ver 2.22
[   15.736762] NET: Registered PF_BLUETOOTH protocol family
[   15.736768] Bluetooth: HCI device and connection manager initialized
[   15.739931] Bluetooth: HCI socket layer initialized
[   15.739954] Bluetooth: L2CAP socket layer initialized
[   15.739982] Bluetooth: SCO socket layer initialized
[   15.752900] Bluetooth: HCI UART driver ver 2.3
[   15.752920] Bluetooth: HCI UART protocol H4 registered
[   15.752996] Bluetooth: HCI UART protocol Three-wire (H5) registered
[   15.753145] Bluetooth: HCI UART protocol Broadcom registered
[   16.074178] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[   16.074199] Bluetooth: BNEP filters: protocol multicast
[   16.074217] Bluetooth: BNEP socket layer initialized
[   16.079721] Bluetooth: MGMT ver 1.22
[   16.093188] NET: Registered PF_ALG protocol family
[   16.117999] cryptd: max_cpu_qlen set to 1000

** sudo vcdbg log msg **
Failed to allocate -201253077 bytes for message buffer

** sudo vcdbg log assert **
Failed to allocate -201253077 bytes for message buffer

** sudo vcdbg log ex **
No exceptions found

--------------------------------------------------------------------------------
Memory
--------------------------------------------------------------------------------
** cat /proc/meminfo **
MemTotal:         988752 kB
MemFree:          349392 kB
MemAvailable:     744912 kB
Buffers:           46408 kB
Cached:           407652 kB
SwapCached:            0 kB
Active:           170548 kB
Inactive:         404016 kB
Active(anon):       1004 kB
Inactive(anon):   144332 kB
Active(file):     169544 kB
Inactive(file):   259684 kB
Unevictable:          32 kB
Mlocked:              32 kB
SwapTotal:        102396 kB
SwapFree:         102396 kB
Zswap:                 0 kB
Zswapped:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:        120588 kB
Mapped:            85656 kB
Shmem:             24832 kB
KReclaimable:      22696 kB
Slab:              39708 kB
SReclaimable:      22696 kB
SUnreclaim:        17012 kB
KernelStack:        1756 kB
PageTables:         3000 kB
SecPageTables:         0 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      596772 kB
Committed_AS:     963528 kB
VmallocTotal:    1064960 kB
VmallocUsed:        7724 kB
VmallocChunk:          0 kB
Percpu:              416 kB
CmaTotal:         262144 kB
CmaFree:          177956 kB

** sudo cat /sys/kernel/debug/dma_buf/bufinfo **

Dma-buf Objects:
size            flags           mode            count           exp_name        ino             name

Total 0 objects, 0 bytes

** sudo cat /sys/kernel/debug/vcsm-cma/state **

VC-ServiceHandle     0765b16f

Resources

Total resource count:   0

--------------------------------------------------------------------------------
Media Devices
--------------------------------------------------------------------------------
** media-ctl -d 0 -p **
Media controller API version 6.1.21

Media device information
------------------------
driver          bcm2835-isp
model           bcm2835-isp
serial          
bus info        platform:bcm2835-isp
hw revision     0x0
driver version  6.1.21

Device topology
- entity 1: bcm2835_isp0 (4 pads, 4 links)
            type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-isp0-output0":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-isp0-capture1":0 [ENABLED,IMMUTABLE]
        pad2: Source
                -> "bcm2835-isp0-capture2":0 [ENABLED,IMMUTABLE]
        pad3: Source
                -> "bcm2835-isp0-capture3":0 [ENABLED,IMMUTABLE]

- entity 6: bcm2835-isp0-output0 (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video13
        pad0: Source
                -> "bcm2835_isp0":0 [ENABLED,IMMUTABLE]

- entity 12: bcm2835-isp0-capture1 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video14
        pad0: Sink
                <- "bcm2835_isp0":1 [ENABLED,IMMUTABLE]

- entity 18: bcm2835-isp0-capture2 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video15
        pad0: Sink
                <- "bcm2835_isp0":2 [ENABLED,IMMUTABLE]

- entity 24: bcm2835-isp0-capture3 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video16
        pad0: Sink
                <- "bcm2835_isp0":3 [ENABLED,IMMUTABLE]

** media-ctl -d 1 -p **
Media controller API version 6.1.21

Media device information
------------------------
driver          bcm2835-isp
model           bcm2835-isp
serial          
bus info        platform:bcm2835-isp
hw revision     0x0
driver version  6.1.21

Device topology
- entity 1: bcm2835_isp0 (4 pads, 4 links)
            type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-isp0-output0":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-isp0-capture1":0 [ENABLED,IMMUTABLE]
        pad2: Source
                -> "bcm2835-isp0-capture2":0 [ENABLED,IMMUTABLE]
        pad3: Source
                -> "bcm2835-isp0-capture3":0 [ENABLED,IMMUTABLE]

- entity 6: bcm2835-isp0-output0 (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video20
        pad0: Source
                -> "bcm2835_isp0":0 [ENABLED,IMMUTABLE]

- entity 12: bcm2835-isp0-capture1 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video21
        pad0: Sink
                <- "bcm2835_isp0":1 [ENABLED,IMMUTABLE]

- entity 18: bcm2835-isp0-capture2 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video22
        pad0: Sink
                <- "bcm2835_isp0":2 [ENABLED,IMMUTABLE]

- entity 24: bcm2835-isp0-capture3 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video23
        pad0: Sink
                <- "bcm2835_isp0":3 [ENABLED,IMMUTABLE]

** media-ctl -d 2 -p **
Media controller API version 6.1.21

Media device information
------------------------
driver          unicam
model           unicam
serial          
bus info        platform:3f801000.csi
hw revision     0x0
driver version  6.1.21

Device topology
- entity 1: imx290 10-001a (1 pad, 1 link)
            type V4L2 subdev subtype Sensor flags 0
            device node name /dev/v4l-subdev0
        pad0: Source
                [fmt:SRGGB12_1X12/1920x1080 field:none colorspace:raw xfer:none ycbcr:601 quantization:full-range
                 crop.bounds:(0,0)/1945x1097
                 crop:(12,8)/1920x1080]
                -> "unicam-image":0 [ENABLED,IMMUTABLE]

- entity 3: unicam-image (1 pad, 1 link)
            type Node subtype V4L flags 1
            device node name /dev/video0
        pad0: Sink
                <- "imx290 10-001a":0 [ENABLED,IMMUTABLE]

** media-ctl -d 3 -p **
Media controller API version 6.1.21

Media device information
------------------------
driver          bcm2835-codec
model           bcm2835-codec
serial          0000
bus info        platform:bcm2835-codec
hw revision     0x1
driver version  6.1.21

Device topology
- entity 1: bcm2835-codec-decode-source (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video10
        pad0: Source
                -> "bcm2835-codec-decode-proc":0 [ENABLED,IMMUTABLE]

- entity 3: bcm2835-codec-decode-proc (2 pads, 2 links)
            type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-codec-decode-source":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-codec-decode-sink":0 [ENABLED,IMMUTABLE]

- entity 6: bcm2835-codec-decode-sink (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video10
        pad0: Sink
                <- "bcm2835-codec-decode-proc":1 [ENABLED,IMMUTABLE]

- entity 15: bcm2835-codec-encode-source (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video11
        pad0: Source
                -> "bcm2835-codec-encode-proc":0 [ENABLED,IMMUTABLE]

- entity 17: bcm2835-codec-encode-proc (2 pads, 2 links)
             type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-codec-encode-source":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-codec-encode-sink":0 [ENABLED,IMMUTABLE]

- entity 20: bcm2835-codec-encode-sink (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video11
        pad0: Sink
                <- "bcm2835-codec-encode-proc":1 [ENABLED,IMMUTABLE]

- entity 29: bcm2835-codec-isp-source (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video12
        pad0: Source
                -> "bcm2835-codec-isp-proc":0 [ENABLED,IMMUTABLE]

- entity 31: bcm2835-codec-isp-proc (2 pads, 2 links)
             type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-codec-isp-source":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-codec-isp-sink":0 [ENABLED,IMMUTABLE]

- entity 34: bcm2835-codec-isp-sink (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video12
        pad0: Sink
                <- "bcm2835-codec-isp-proc":1 [ENABLED,IMMUTABLE]

- entity 43: bcm2835-codec-image_fx-source (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video18
        pad0: Source
                -> "bcm2835-codec-image_fx-proc":0 [ENABLED,IMMUTABLE]

- entity 45: bcm2835-codec-image_fx-proc (2 pads, 2 links)
             type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-codec-image_fx-source":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-codec-image_fx-sink":0 [ENABLED,IMMUTABLE]

- entity 48: bcm2835-codec-image_fx-sink (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video18
        pad0: Sink
                <- "bcm2835-codec-image_fx-proc":1 [ENABLED,IMMUTABLE]

- entity 57: bcm2835-codec-encode_image-sour (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video31
        pad0: Source
                -> "bcm2835-codec-encode_image-proc":0 [ENABLED,IMMUTABLE]

- entity 59: bcm2835-codec-encode_image-proc (2 pads, 2 links)
             type Node subtype Unknown flags 0
        pad0: Sink
                <- "bcm2835-codec-encode_image-sour":0 [ENABLED,IMMUTABLE]
        pad1: Source
                -> "bcm2835-codec-encode_image-sink":0 [ENABLED,IMMUTABLE]

- entity 62: bcm2835-codec-encode_image-sink (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video31
        pad0: Sink
                <- "bcm2835-codec-encode_image-proc":1 [ENABLED,IMMUTABLE]

** media-ctl -d 4 -p **
Failed to enumerate /dev/media4 (-2)

--------------------------------------------------------------------------------
Cameras
--------------------------------------------------------------------------------
** libcamera-still --list-cameras **
Available cameras
-----------------
0 : imx290 [1920x1080] (/base/soc/i2c0mux/i2c@1/imx290@1a)
    Modes: 'SRGGB10_CSI2P' : 1280x720 [60.00 fps - (320, 180)/1280x720 crop]
                             1920x1080 [60.00 fps - (0, 0)/1920x1080 crop]
           'SRGGB12_CSI2P' : 1280x720 [60.00 fps - (320, 180)/1280x720 crop]
                             1920x1080 [60.00 fps - (0, 0)/1920x1080 crop]

--------------------------------------------------------------------------------
Versions
--------------------------------------------------------------------------------
** uname -a **
Linux raspberrypi 6.1.21-v7+ #1642 SMP Mon Apr  3 17:20:52 BST 2023 armv7l GNU/Linux

** cat /etc/os-release **
PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)"
NAME="Raspbian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

** vcgencmd version **
Mar 17 2023 10:52:42 
Copyright (c) 2012 Broadcom
version 82f3750a65fadae9a38077e3c2e217ad158c8d54 (clean) (release) (start)

** libcamera-still --version **
libcamera-apps build: 7e4d3d71867f 17-07-2023 (07:34:37)
libcamera build: v0.0.5+83-bde9b04f

--------------------------------------------------------------------------------
libcamera-still -t 1000 -o test.jpg
--------------------------------------------------------------------------------
Made DRM preview window
[5:47:31.146879922] [3611]  INFO Camera camera_manager.cpp:297 libcamera v0.0.5+83-bde9b04f
[5:47:31.187146092] [3612]  INFO RPI vc4.cpp:437 Registered camera /base/soc/i2c0mux/i2c@1/imx290@1a to Unicam device /dev/media2 and ISP device /dev/media0
[5:47:31.187242549] [3612]  INFO RPI pipeline_base.cpp:1101 Using configuration file '/usr/share/libcamera/pipeline/rpi/vc4/rpi_apps.yaml'
[5:47:31.188719260] [3611]  INFO Camera camera.cpp:1033 configuring streams: (0) 960x540-YUV420
[5:47:31.189837951] [3612]  INFO RPI vc4.cpp:565 Sensor: /base/soc/i2c0mux/i2c@1/imx290@1a - Selected sensor format: 1280x720-SRGGB12_1X12 - Selected unicam format: 1280x720-pRCC
[5:47:32.491639726] [3611]  INFO Camera camera.cpp:1033 configuring streams: (0) 1920x1080-YUV420 (1) 1920x1080-SRGGB12_CSI2P
[5:47:32.493379091] [3612]  INFO RPI vc4.cpp:565 Sensor: /base/soc/i2c0mux/i2c@1/imx290@1a - Selected sensor format: 1920x1080-SRGGB12_1X12 - Selected unicam format: 1920x1080-pRCC
Still capture image received

naushir commented 1 year ago

If either AWB or AGC is enabled, the algorithm consumes a number of frames (usually 5 or so) to converge on target R/B gain and shutter/analoge gain values (respectively). Now you've set a manual shutter speed of 5 seconds, so the 5 frames of convergence are going to take 25 seconds to complete.

As a side node, something looks to be wrong in either the imx462 device driver or the camera helper. In your AWB-off case, you asked for an exposure of 5 seconds, but the capture completes in just over 1 second. This implies the shutter speed calculations are wrong. You should raise this with Arducam.

6by9 commented 1 year ago

As a side node, something looks to be wrong in either the imx462 device driver or the camera helper. In your AWB-off case, you asked for an exposure of 5 seconds, but the capture completes in just over 1 second. This implies the shutter speed calculations are wrong. You should raise this with Arducam.

imx290 (supporting imx327, imx290, and imx462) is a native driver in our tree (and mainline), so one for me to look at. I suspect it may be a corrupt first frame issue.

Arducam do have a PiVariety version of imx462, and that we don't care about.

6by9 commented 1 year ago

Running an IMX327 as that came to hand first.

Setting bcm2835_unicam module parameter debug to 5, and dev_debug in /sys/class/video4linux/video0 to 0x0a (V4L2_DEV_DEBUG_IOCTL | V4L2_DEV_DEBUG_IOCTL_ARGS | V4L2_DEV_DEBUG_STREAMING - https://elixir.bootlin.com/linux/latest/source/include/media/v4l2-ioctl.h#L595) Logs:

[ 1386.118744] video0: VIDIOC_STREAMON: type=vid-cap
[ 1386.131183] unicam fe801000.csi: Running with 2 data lanes
[ 1386.307283] video0: VIDIOC_QBUF: 00:00:00.000000 index=0, type=vid-cap, request_fd=0, flags=0x00002002, field=any, sequence=0, memory=dmabuf, bytesused=3110400, offset/userptr=0x14, length=3112960
[ 1386.307312] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 1386.307410] unicam fe801000.csi: ISR: ISTA: 0x1, STA: 0x4002, sequence 0, lines done 0
[ 1386.307417] unicam fe801000.csi: Scheduling dummy buffer for node 0
[ 1386.307545] video0: VIDIOC_DQEVENT: type=0x4, pending=0, sequence=0, id=0, timestamp=1386.292559643
[ 1386.307563] frame_sequence=0
[ 1386.312804] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x5001, sequence 0, lines done 270
[ 1386.317954] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4003, sequence 0, lines done 540
[ 1386.323102] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4001, sequence 0, lines done 810
[ 1386.328251] unicam fe801000.csi: ISR: ISTA: 0x0, STA: 0xC002, sequence 0, lines done 1080
[ 1386.328290] video0: VIDIOC_DQBUF: 00:23:06.292554 index=0, type=vid-cap, request_fd=0, flags=0x00002000, field=any, sequence=0, memory=dmabuf, bytesused=3110400, offset/userptr=0x14, length=3112960
[ 1386.328314] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 1386.409017] video0: VIDIOC_STREAMOFF: type=vid-cap

118ms from STREAMON to frame start, so the sensor is doing the wrong thing.

If I stream with v4l2-ctl without changing any modes, then I get

[ 4119.024217] video0: VIDIOC_STREAMON: type=vid-cap
[ 4119.024300] video0: 
[ 4119.024298] unicam fe801000.csi: ISR: ISTA: 0x1, STA: 0x4002, sequence 0, lines done 0
[ 4119.024312] VIDIOC_G_FMT: 
[ 4119.024322] unicam fe801000.csi: Scheduling dummy buffer for node 0
[ 4119.024337] type=vid-cap, width=1920, height=1080, pixelformat=pRCC little-endian (0x43435270), field=none, bytesperline=2880, sizeimage=3110400, colorspace=11, flags=0x0, ycbcr_enc=0, quantization=0, xfer_func=0
[ 4119.029691] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x5001, sequence 0, lines done 270
[ 4119.034840] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4003, sequence 0, lines done 540
[ 4119.039989] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4001, sequence 0, lines done 810
[ 4119.045138] unicam fe801000.csi: ISR: ISTA: 0x0, STA: 0xC002, sequence 0, lines done 1080
[ 4119.045195] video0: VIDIOC_DQBUF: 01:08:38.985014 index=0, type=vid-cap, request_fd=0, flags=0x00002001, field=any, sequence=0, memory=mmap, bytesused=3110400, offset/userptr=0x0, length=3110400
[ 4119.045269] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4119.045401] video0: VIDIOC_QBUF: 00:00:00.000000 index=0, type=vid-cap, request_fd=0, flags=0x00002003, field=any, sequence=0, memory=mmap, bytesused=3110400, offset/userptr=0x0, length=3110400
[ 4119.045463] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4124.023602] unicam fe801000.csi: ISR: ISTA: 0x1, STA: 0x4000, sequence 1, lines done 0
[ 4124.023625] unicam fe801000.csi: Scheduling dummy buffer for node 0
[ 4124.028994] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x5003, sequence 1, lines done 270
[ 4124.034142] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4001, sequence 1, lines done 540
[ 4124.039291] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4003, sequence 1, lines done 810
[ 4124.044440] unicam fe801000.csi: ISR: ISTA: 0x0, STA: 0xC000, sequence 1, lines done 1080
[ 4124.044508] video0: VIDIOC_DQBUF: 01:08:43.984231 index=1, type=vid-cap, request_fd=0, flags=0x00002001, field=any, sequence=1, memory=mmap, bytesused=3110400, offset/userptr=0x2f8000, length=3110400
[ 4124.044582] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4124.044686] video0: VIDIOC_QBUF: 00:00:00.000000 index=1, type=vid-cap, request_fd=0, flags=0x00002003, field=any, sequence=0, memory=mmap, bytesused=3110400, offset/userptr=0x2f8000, length=3110400
[ 4124.044747] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4129.022902] unicam fe801000.csi: ISR: ISTA: 0x1, STA: 0x4002, sequence 2, lines done 0
[ 4129.022924] unicam fe801000.csi: Scheduling dummy buffer for node 0
[ 4129.028295] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x5001, sequence 2, lines done 270
[ 4129.033445] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4003, sequence 2, lines done 540
[ 4129.038593] unicam fe801000.csi: ISR: ISTA: 0x4, STA: 0x4001, sequence 2, lines done 810
[ 4129.043743] unicam fe801000.csi: ISR: ISTA: 0x0, STA: 0xC002, sequence 2, lines done 1080
[ 4129.043810] video0: VIDIOC_DQBUF: 01:08:48.983443 index=2, type=vid-cap, request_fd=0, flags=0x00002001, field=any, sequence=2, memory=mmap, bytesused=3110400, offset/userptr=0x5f0000, length=3110400
[ 4129.043884] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4129.043977] video0: VIDIOC_QBUF: 00:00:00.000000 index=2, type=vid-cap, request_fd=0, flags=0x00002003, field=any, sequence=0, memory=mmap, bytesused=3110400, offset/userptr=0x5f0000, length=3110400
[ 4129.044037] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000
[ 4129.525743] video0: VIDIOC_DQBUF: error -512: 00:00:00.000000 index=0, type=vid-cap, request_fd=0, flags=0x00000000, field=any, sequence=0, memory=mmap, bytesused=0, offset/userptr=0x0, length=0
[ 4129.525831] timecode=00:00:00 type=0, flags=0x00000000, frames=0, userbits=0x00000000

Timestamps of 01:08:38.985014 01:08:43.984231 01:08:48.983443 are almost spot on the 5second period requested, but again only 81ms from STREAMON to first frame.

Having looked at the captured frames from it, the first is recognizable, whilst the following frames are totally blown out, so that largely confirms that the exposure on the first frame is incorrect.

In the normal manner that datasheets are unhelpful on details, it does list that "After standby mode is canceled, a normal image is output from 9 frames after the internal regulator stabilzation (20ms or more). The 20ms regulator stabilization is compensated for by an msleep(30) in imx290_start_streaming, but nothing is done over the initial 8 frames.

https://git.linuxtv.org/libcamera.git/tree/src/ipa/rpi/cam_helper/cam_helper_imx290.cpp#n59 does set hideFramesModeSwitch to 1, so does that frame not get dropped?

6by9 commented 1 year ago

Patch to libcamera:

src/ipa/rpi/cam_helper/cam_helper_imx290.cpp | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/src/ipa/rpi/cam_helper/cam_helper_imx290.cpp b/src/ipa/rpi/cam_helper/cam_helper_imx290.cpp
index 7d6f5b549a73..b8914bf93ecb 100644
--- a/src/ipa/rpi/cam_helper/cam_helper_imx290.cpp
+++ b/src/ipa/rpi/cam_helper/cam_helper_imx290.cpp
@@ -19,6 +19,7 @@ public:
        double gain(uint32_t gainCode) const override;
        void getDelays(int &exposureDelay, int &gainDelay,
                       int &vblankDelay, int &hblankDelay) const override;
+       unsigned int hideFramesStartup() const override;
        unsigned int hideFramesModeSwitch() const override;

 private:
@@ -54,6 +55,12 @@ void CamHelperImx290::getDelays(int &exposureDelay, int &gainDelay,
        hblankDelay = 2;
 }

+unsigned int CamHelperImx290::hideFramesStartup() const
+{
+       /* On startup, we seem to get 1 bad frame. */
+       return 1;
+}
+
 unsigned int CamHelperImx290::hideFramesModeSwitch() const
 {
        /* After a mode switch, we seem to get 1 bad frame. */
-- 
2.34.1

fixes it for me so that the first frame is dropped on startup, as well as on mode switch. I'll leave it to naushir to upstream that.

naushir commented 1 year ago

I'll close this now as the fix should be merged into libcamera repos shortly.

raspberrypi / rpicam-apps

[BUG] IMX462 long exposures broken when AWB disabled #559

AWB enabled

AWB Disabled