Skip to content

Instantly share code, notes, and snippets.

@lu4
Created October 23, 2023 12:38
Show Gist options
  • Select an option

  • Save lu4/d45e405e96f087a3586016045a46a94c to your computer and use it in GitHub Desktop.

Select an option

Save lu4/d45e405e96f087a3586016045a46a94c to your computer and use it in GitHub Desktop.
libcamera-raw debug log
lu4@rp020:~/Projects/libcamera $ LIBCAMERA_LOG_LEVELS=*:0 libcamera-raw --nopreview --mode 640:400:8:U
[180:29:40.698116362] [5036] DEBUG IPAModule ipa_module.cpp:334 ipa_rkisp1.so: IPA module /usr/lib/arm-linux-gnueabihf/libcamera/ipa_rkisp1.so is signed
[180:29:40.698427195] [5036] DEBUG IPAManager ipa_manager.cpp:245 Loaded IPA module '/usr/lib/arm-linux-gnueabihf/libcamera/ipa_rkisp1.so'
[180:29:40.698742456] [5036] DEBUG IPAModule ipa_module.cpp:334 ipa_rpi_pisp.so: IPA module /usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_pisp.so is signed
[180:29:40.698887508] [5036] DEBUG IPAManager ipa_manager.cpp:245 Loaded IPA module '/usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_pisp.so'
[180:29:40.699182716] [5036] DEBUG IPAModule ipa_module.cpp:334 ipa_rpi_vc4.so: IPA module /usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_vc4.so is signed
[180:29:40.699318445] [5036] DEBUG IPAManager ipa_manager.cpp:245 Loaded IPA module '/usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_vc4.so'
[180:29:40.699502456] [5036] DEBUG IPAModule ipa_module.cpp:334 ipa_vimc.so: IPA module /usr/lib/arm-linux-gnueabihf/libcamera/ipa_vimc.so is signed
[180:29:40.699599175] [5036] DEBUG IPAManager ipa_manager.cpp:245 Loaded IPA module '/usr/lib/arm-linux-gnueabihf/libcamera/ipa_vimc.so'
[180:29:40.699718185] [5036] INFO Camera camera_manager.cpp:284 libcamera v0.1.0+52-a858d20b
[180:29:40.700149435] [5039] DEBUG Camera camera_manager.cpp:69 Starting camera manager
[180:29:40.726740903] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:224 New media device "bcm2835-codec" created from /dev/media3
[180:29:40.727225747] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media3 due to 5 missing dependencies
[180:29:40.730795644] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media3 found
[180:29:40.730873873] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:252 Added device /dev/media3: bcm2835-codec
[180:29:40.731983301] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:224 New media device "bcm2835-isp" created from /dev/media0
[180:29:40.734002520] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media0 due to 4 missing dependencies
[180:29:40.734926427] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:224 New media device "bcm2835-isp" created from /dev/media1
[180:29:40.735245021] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media1 due to 4 missing dependencies
[180:29:40.738770387] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media0 found
[180:29:40.738877105] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:252 Added device /dev/media0: bcm2835-isp
[180:29:40.746326848] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media1 found
[180:29:40.746439764] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:252 Added device /dev/media1: bcm2835-isp
[180:29:40.747803723] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:224 New media device "unicam" created from /dev/media2
[180:29:40.749098724] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:96 Defer media device /dev/media2 due to 1 missing dependencies
[180:29:40.750221120] [5039] DEBUG DeviceEnumerator device_enumerator_udev.cpp:322 All dependencies for media device /dev/media2 found
[180:29:40.750505860] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:252 Added device /dev/media2: unicam
[180:29:40.751693725] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerISI'
[180:29:40.753261954] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerRkISP1'
[180:29:40.753915652] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerPiSP'
[180:29:40.754266173] [5039] DEBUG RPI pisp.cpp:837 Unable to acquire a CFE instance
[180:29:40.754552788] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerVc4'
[180:29:40.754783674] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:312 Successful match for media device "unicam"
[180:29:40.755060757] [5039] DEBUG DeviceEnumerator device_enumerator.cpp:312 Successful match for media device "bcm2835-isp"
[180:29:40.755511591] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Exposure (0x00980911)
[180:29:40.755802789] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Horizontal Flip (0x00980914)
[180:29:40.756004872] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Vertical Flip (0x00980915)
[180:29:40.756199872] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Camera Orientation (0x009a0922)
[180:29:40.756406747] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Camera Sensor Rotation (0x009a0923)
[180:29:40.757326175] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Vertical Blanking (0x009e0901)
[180:29:40.757563154] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Horizontal Blanking (0x009e0902)
[180:29:40.757759508] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Analogue Gain (0x009e0903)
[180:29:40.757952373] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Link Frequency (0x009f0901)
[180:29:40.760199301] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Pixel Rate (0x009f0902)
[180:29:40.760400863] [5039] DEBUG V4L2 v4l2_device.cpp:636 'ov9281 10-0060': Control: Test Pattern (0x009f0903)
[180:29:40.764629823] [5039] WARN CameraSensorProperties camera_sensor_properties.cpp:249 No static properties available for 'ov9281'
[180:29:40.764727792] [5039] WARN CameraSensorProperties camera_sensor_properties.cpp:251 Please consider updating the camera sensor properties database
[180:29:40.781243944] [5039] DEBUG IPAManager ipa_manager.cpp:316 IPA module /usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_vc4.so signature is valid
[180:29:40.781599256] [5039] DEBUG IPAProxy raspberrypi_ipa_proxy.cpp:45 initializing raspberrypi proxy: loading IPA from /usr/lib/arm-linux-gnueabihf/libcamera/ipa_rpi_vc4.so
[180:29:40.791287176] [5039] DEBUG RPiBlackLevel black_level.cpp:41 Read black levels red 4096 green 4096 blue 4096
[180:29:40.791499781] [5039] WARN RPiSdn sdn.cpp:39 Using legacy SDN tuning - please consider moving SDN inside rpi.denoise
[180:29:40.791592593] [5039] DEBUG RPiAgc agc.cpp:240 Agc
[180:29:40.791635406] [5039] DEBUG RPiAgc agc.cpp:178 AgcConfig
[180:29:40.792503791] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 1 for Vertical Blanking
[180:29:40.792606187] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Horizontal Blanking
[180:29:40.792658896] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Exposure
[180:29:40.792707958] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:103 Set a delay of 2 and priority write flag 0 for Analogue Gain
[180:29:40.794838271] [5039] DEBUG V4L2 v4l2_videodevice.cpp:632 /dev/video0[24:cap]: Opened device platform:3f801000.csi: unicam: unicam
[180:29:40.795162021] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Red Balance (0x0098090e)
[180:29:40.795248688] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Blue Balance (0x0098090f)
[180:29:40.795319105] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Colour Correction Matrix (0x009819e1)
[180:29:40.795388167] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Lens Shading (0x009819e2)
[180:29:40.795453949] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Black Level (0x009819e3)
[180:29:40.795521813] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Green Equalisation (0x009819e4)
[180:29:40.795589626] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Gamma (0x009819e5)
[180:29:40.795655147] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Denoise (0x009819e6)
[180:29:40.795721136] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Sharpen (0x009819e7)
[180:29:40.795815147] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Defective Pixel Correction (0x009819e8)
[180:29:40.795922230] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Colour Denoise (0x009819e9)
[180:29:40.796028063] [5039] DEBUG V4L2 v4l2_device.cpp:636 /dev/video13[26:cap]: Control: Digital Gain (0x009f0905)
[180:29:40.796178480] [5039] DEBUG V4L2 v4l2_videodevice.cpp:632 /dev/video13[26:out]: Opened device platform:bcm2835-isp: bcm2835-isp: bcm2835-isp
[180:29:40.796537803] [5039] DEBUG V4L2 v4l2_videodevice.cpp:632 /dev/video14[27:cap]: Opened device platform:bcm2835-isp: bcm2835-isp: bcm2835-isp
[180:29:40.796721449] [5039] DEBUG V4L2 v4l2_videodevice.cpp:632 /dev/video15[28:cap]: Opened device platform:bcm2835-isp: bcm2835-isp: bcm2835-isp
[180:29:40.796883741] [5039] DEBUG V4L2 v4l2_videodevice.cpp:632 /dev/video16[29:cap]: Opened device platform:bcm2835-isp: bcm2835-isp: bcm2835-isp
[180:29:40.797056137] [5039] INFO RPI vc4.cpp:387 Registered camera /base/soc/i2c0mux/i2c@1/ov9281@60 to Unicam device /dev/media2 and ISP device /dev/media0
[180:29:40.797182022] [5039] DEBUG Camera camera_manager.cpp:125 Pipeline handler "PipelineHandlerVc4" matched
[180:29:40.797279939] [5039] DEBUG RPI vc4.cpp:179 Unable to acquire a Unicam instance
[180:29:40.797356501] [5039] DEBUG RPI vc4.cpp:179 Unable to acquire a Unicam instance
[180:29:40.797435356] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'SimplePipelineHandler'
[180:29:40.797566970] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerUVC'
[180:29:40.797654418] [5039] DEBUG Camera camera_manager.cpp:113 Found registered pipeline handler 'PipelineHandlerVimc'
[180:29:40.798183741] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R8 Score: 4080 (best 4080)
[180:29:40.798305200] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R8 Score: 2226.67 (best 2226.67)
[180:29:40.798371710] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R8 Score: 2000 (best 2000)
[180:29:40.798434366] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R10 Score: 3080 (best 2000)
[180:29:40.798494106] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R10 Score: 1226.67 (best 1226.67)
[180:29:40.798557075] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R10 Score: 1000 (best 1000)
[180:29:40.798680252] [5036] DEBUG RPI pipeline_base.cpp:151 RGB colour space Rec709/Rec709/None/Full YUV colour space Rec709
[180:29:40.798765929] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R8 Score: 3080 (best 3080)
[180:29:40.798828169] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R8 Score: 1226.67 (best 1226.67)
[180:29:40.798890096] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R8 Score: 1000 (best 1000)
[180:29:40.798950200] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R10 Score: 2080 (best 1000)
[180:29:40.799008794] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R10 Score: 226.667 (best 226.667)
[180:29:40.799069992] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R10 Score: 0 (best 0)
[180:29:40.799177231] [5036] DEBUG RPI pipeline_base.cpp:261 Try color space Rec709
[180:29:40.799286763] [5036] DEBUG Camera camera.cpp:1148 streams configuration: (0) 1920x1080-YUV420 (1) 1280x800-R10_CSI2P
[180:29:40.799468533] [5036] DEBUG RPI pipeline_base.cpp:151 RGB colour space SMPTE170M/Rec709/None/Full YUV colour space SMPTE170M
[180:29:40.799551398] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R8 Score: 0 (best 0)
[180:29:40.799623638] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R8 Score: 306.667 (best 0)
[180:29:40.799688794] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R8 Score: 260 (best 0)
[180:29:40.799750929] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R10 Score: 1000 (best 0)
[180:29:40.799811242] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R10 Score: 1306.67 (best 0)
[180:29:40.799873586] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R10 Score: 1260 (best 0)
[180:29:40.799974732] [5036] DEBUG RPI pipeline_base.cpp:261 Try color space SMPTE170M
Stream configuration adjusted
[180:29:40.800227284] [5036] DEBUG RPI pipeline_base.cpp:151 RGB colour space SMPTE170M/Rec709/None/Full YUV colour space SMPTE170M
[180:29:40.800338013] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R8 Score: 0 (best 0)
[180:29:40.800422544] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R8 Score: 306.667 (best 0)
[180:29:40.800492492] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R8 Score: 260 (best 0)
[180:29:40.800556971] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 640x400 fmt R10 Score: 1000 (best 0)
[180:29:40.800617596] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x720 fmt R10 Score: 1306.67 (best 0)
[180:29:40.800679263] [5036] DEBUG RPI pipeline_base.cpp:958 Format: 1280x800 fmt R10 Score: 1260 (best 0)
[180:29:40.800782076] [5036] DEBUG RPI pipeline_base.cpp:261 Try color space SMPTE170M
[180:29:40.800883378] [5036] INFO Camera camera.cpp:1213 configuring streams: (0) 640x480-YUV420 (1) 640x400-R8
[180:29:40.803329837] [5039] INFO RPI vc4.cpp:549 Sensor: /base/soc/i2c0mux/i2c@1/ov9281@60 - Selected sensor format: 640x400-Y8_1X8 - Selected unicam format: 640x400-GREY
[180:29:40.803462858] [5039] DEBUG RPI vc4.cpp:564 Setting ISP Output0 to 640x480-YU12
[180:29:40.804044525] [5039] DEBUG RPI vc4.cpp:571 Stream ISP Output0 has color space SMPTE170M
[180:29:40.804146087] [5039] DEBUG RPI vc4.cpp:635 Setting ISP Output1 (internal) to 320x240-YU12
[180:29:40.806572130] [5039] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 19998.16us (Shutter lines: 2747, AGC requested 20000.00us) Gain: 1 (Gain Code: 16)
[180:29:40.814131299] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video14[27:cap]: 6 buffers requested.
[180:29:40.814354737] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814457445] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814532393] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814602601] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814671039] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814741612] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.814825622] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video14[27:cap]: 0 buffers requested.
[180:29:40.818572759] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[24:cap]: 6 buffers requested.
[180:29:40.818769842] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.818856665] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.818925207] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.818990572] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.819059270] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.819127082] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.819194843] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[24:cap]: 0 buffers requested.
[180:29:40.820939895] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821079375] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821136458] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821188698] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821240989] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821291093] [5036] DEBUG Request request.cpp:361 Created request - cookie: 0
[180:29:40.821394739] [5036] DEBUG Camera camera.cpp:1371 Starting capture
[180:29:40.821934739] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: Sharpness = 1.000000
[180:29:40.822079010] [5043] WARN IPARPI ipa_base.cpp:1013 Could not set SHARPNESS - no sharpen algorithm
[180:29:40.822126094] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: Saturation = 1.000000
[180:29:40.822179635] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: Contrast = 1.000000
[180:29:40.822239792] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: Brightness = 0.000000
[180:29:40.822294323] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: ExposureValue = 0.000000
[180:29:40.822351198] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: AeExposureMode = 0
[180:29:40.822403646] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: FrameDurationLimits = [ 33333, 33333 ]
[180:29:40.822467969] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: AwbMode = 0
[180:29:40.822515469] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: AeMeteringMode = 0
[180:29:40.822564636] [5043] DEBUG IPARPI ipa_base.cpp:698 Request ctrl: NoiseReductionMode = 3
[180:29:40.822620261] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:40.822702292] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:40.822757084] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 0.00us
[180:29:40.822813438] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 1000.00us analogue gain 1
[180:29:40.822908334] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:40.822976042] [5043] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.823028073] [5043] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.823124740] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 997.36us (Shutter lines: 137, AGC requested 1000.00us) Gain: 1 (Gain Code: 16)
[180:29:40.823503594] [5043] DEBUG IPARPI ipa_base.cpp:334 Drop 7 frames on startup
[180:29:40.825575991] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[24:cap]: 3 buffers requested.
[180:29:40.825750991] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.825826303] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.825935730] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[24:cap]: 0 buffers requested.
[180:29:40.826021876] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video0[24:cap]: 16 buffers requested.
[180:29:40.826075939] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1521 /dev/video0[24:cap]: Prepared to import 16 buffers
[180:29:40.826435939] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video13[26:out]: 16 buffers requested.
[180:29:40.826492137] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1521 /dev/video13[26:out]: Prepared to import 16 buffers
[180:29:40.827413387] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video14[27:cap]: 1 buffers requested.
[180:29:40.827550419] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.827615419] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video14[27:cap]: 0 buffers requested.
[180:29:40.827917033] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video14[27:cap]: 14 buffers requested.
[180:29:40.827973492] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1521 /dev/video14[27:cap]: Prepared to import 14 buffers
[180:29:40.829113700] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video15[28:cap]: 1 buffers requested.
[180:29:40.829356878] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.829441617] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video15[28:cap]: 0 buffers requested.
[180:29:40.829834534] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video15[28:cap]: 1 buffers requested.
[180:29:40.829914638] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1521 /dev/video15[28:cap]: Prepared to import 1 buffers
[180:29:40.830725003] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video16[29:cap]: 1 buffers requested.
[180:29:40.830910628] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.830985836] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video16[29:cap]: 0 buffers requested.
[180:29:40.831304795] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1254 /dev/video16[29:cap]: 1 buffers requested.
[180:29:40.831369587] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1521 /dev/video16[29:cap]: Prepared to import 1 buffers
[180:29:40.831437087] [5039] DEBUG Buffer framebuffer.cpp:346 Buffer is contiguous
[180:29:40.831578701] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for Unicam Image
[180:29:40.831666774] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 0
[180:29:40.831761358] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 8 for Unicam Image
[180:29:40.831815628] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 1
[180:29:40.831882608] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for Unicam Image
[180:29:40.831929326] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for Unicam Image
[180:29:40.831972816] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for Unicam Image
[180:29:40.832015681] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for Unicam Image
[180:29:40.832058493] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for Unicam Image
[180:29:40.832102556] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:40.832155420] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:40.832231879] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832278806] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832322191] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832365577] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832408545] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832451410] [5039] DEBUG RPISTREAM rpi_stream.cpp:159 No buffers available for ISP Output0
[180:29:40.832495993] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:40.832550316] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:40.832638025] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:40.832691514] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:40.891152837] [5039] DEBUG RPI vc4.cpp:892 Setting Unicam timeout to 1000000.00us
[180:29:40.891409973] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:41.891388827
[180:29:40.891532837] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.891631848] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.891717681] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.891802265] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.891886327] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.891975129] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:40.892068358] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999332916
[180:29:40.892209921] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 0
[180:29:40.892300234] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:41.892294765
[180:29:40.892392004] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 7, timestamp: 649780882810000
[180:29:40.892489765] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 0
[180:29:40.892576119] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 137 at index 0
[180:29:40.892660286] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 0
[180:29:40.892740650] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 0
[180:29:40.892807734] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 7
[180:29:40.892908150] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 0
[180:29:40.892954505] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 0 started
[180:29:40.892947525] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 997.36us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:40.893010338] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999289323
[180:29:40.893105182] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:40.893164973] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:40.893223046] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:40.893286848] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:40.893330130] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 1 speed 1
[180:29:40.894922214] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 7, timestamp: 649780882810000
[180:29:40.895024870] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:40.895091745] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 0
[180:29:40.895346589] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.996956405
[180:29:40.898288673] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 0
[180:29:40.898398204] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 7, timestamp: 649780882810000
[180:29:40.898453517] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for Unicam Image
[180:29:40.898510809] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 0
[180:29:40.898597892] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:40.898653413] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649780882810000
[180:29:40.898702996] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:40.898755132] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:40.898850496] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:40.898904298] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649780882810000
[180:29:40.898951278] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:40.899001903] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:40.899078361] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:40.899130705] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649780882810000
[180:29:40.899204976] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993095154
[180:29:40.899334090] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:40.899389924] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:40.899470757] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (6 left)
[180:29:40.899525444] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.992774216
[180:29:40.917639722] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 1
[180:29:40.917749305] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 1 started
[180:29:40.917801493] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:283 Queue is empty, auto queue no-op.
[180:29:40.917867847] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.974432231
[180:29:40.920705556] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 1
[180:29:40.920771233] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:41.920765140
[180:29:40.920833577] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 8, timestamp: 649780917535000
[180:29:40.920892536] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 0
[180:29:40.920945608] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 137 at index 0
[180:29:40.920993733] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 0
[180:29:40.921042483] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 0
[180:29:40.921112588] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 8
[180:29:40.921191911] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999578698
[180:29:40.921245921] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 997.36us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:40.921389723] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:40.921448525] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:40.921506442] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:40.921570400] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:40.921614515] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 2 speed 1
[180:29:40.922553630] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 8, timestamp: 649780917535000
[180:29:40.922627849] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:40.922691963] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 1
[180:29:40.922898578] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997874010
[180:29:40.925771131] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 1
[180:29:40.925888839] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 8, timestamp: 649780917535000
[180:29:40.925944621] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 8 for Unicam Image
[180:29:40.926003527] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 1
[180:29:40.926091756] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:40.926148423] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649780917535000
[180:29:40.926198162] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:40.926250767] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:40.926351704] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:40.926407642] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649780917535000
[180:29:40.926454985] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:40.926506756] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:40.926599152] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:40.926656704] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649780917535000
[180:29:40.926992173] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993786300
[180:29:40.927545975] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 36.9356
[180:29:40.927670611] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:40.927746080] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:40.927802903] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.00457219 target 0.160185 gives gain 10
[180:29:40.927870142] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.0457219 target 0.160185 gives gain 34.2847
[180:29:40.927932486] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.156756 target 0.160185 gives gain 34.8125
[180:29:40.927993788] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.159169 target 0.160185 gives gain 34.8159
[180:29:40.928068007] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 13.0475
[180:29:40.928123371] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 34.8159 (target_Y 0.160185 ev 1 base_ev 1)
[180:29:40.928187642] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 34723.94us
[180:29:40.928246705] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 34.8159 target_Y 0.160185
[180:29:40.928306601] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:40.928355403] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 34723.94us
[180:29:40.928413424] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 34723.94us no dg 34723.94us
[180:29:40.928485455] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 17361.97us and 2
[180:29:40.928556184] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 34723.94us
[180:29:40.928613997] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 17361.97us analogue gain 2
[180:29:40.928681184] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 12
[180:29:40.928724361] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:40.928768788] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:40.929000663] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.929256132] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.929653528] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 17355.52us (Shutter lines: 2384, AGC requested 17361.97us) Gain: 2 (Gain Code: 32)
[180:29:40.929942487] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 32 at index 2
[180:29:40.930064362] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 2384 at index 2
[180:29:40.930118789] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 2
[180:29:40.930176549] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990595101
[180:29:40.930380404] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990390622
[180:29:40.930498529] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:40.930562851] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:40.930671185] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (5 left)
[180:29:40.930725456] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990044632
[180:29:40.952355724] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 2
[180:29:40.952459526] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 2 started
[180:29:40.952520984] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 32 at index 2
[180:29:40.952576245] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 2384 at index 2
[180:29:40.952664995] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 2
[180:29:40.954159579] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.966614572
[180:29:40.955428746] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 0
[180:29:40.955491142] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:41.955485256
[180:29:40.955553850] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 7, timestamp: 649780952258000
[180:29:40.955610829] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 0
[180:29:40.955662288] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 137 at index 0
[180:29:40.955709944] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 0
[180:29:40.955759267] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 0
[180:29:40.955832131] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 7
[180:29:40.955919944] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999571041
[180:29:40.956052652] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 997.36us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:40.956190777] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:40.956249059] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:40.956305361] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:40.956368330] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:40.956412392] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 34723.94us
[180:29:40.956469371] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 997.36us
[180:29:40.956523955] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 4
[180:29:40.956569007] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 3989.44us
[180:29:40.956624423] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:40.956672809] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 3 speed 1
[180:29:40.956721611] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:40.957660570] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 7, timestamp: 649780952258000
[180:29:40.957730361] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:40.957793122] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 0
[180:29:40.957887601] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997603228
[180:29:40.957970882] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997519113
[180:29:40.960848123] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 0
[180:29:40.960962862] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 7, timestamp: 649780952258000
[180:29:40.961022498] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for Unicam Image
[180:29:40.961080310] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 0
[180:29:40.961166612] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:40.961222550] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649780952258000
[180:29:40.961271352] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:40.961323488] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:40.961422342] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:40.961477863] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649780952258000
[180:29:40.961525415] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:40.961576873] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:40.961665467] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:40.962504530] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649780952258000
[180:29:40.962648540] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.992843122
[180:29:40.963144269] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 32.6073
[180:29:40.963258749] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:40.963336145] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:40.963396249] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.00345133 target 0.160163 gives gain 10
[180:29:40.963463957] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.0345133 target 0.160163 gives gain 45.0994
[180:29:40.963527238] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.155653 target 0.160163 gives gain 46.1099
[180:29:40.963590988] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.159141 target 0.160163 gives gain 46.1163
[180:29:40.963666509] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 14.0037
[180:29:40.963723697] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 46.1163 (target_Y 0.160163 ev 1 base_ev 1)
[180:29:40.963790311] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 45994.59us
[180:29:40.963852968] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 46.1163 target_Y 0.160163
[180:29:40.963911770] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:40.963960416] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 45994.59us
[180:29:40.964018072] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 45994.59us no dg 45994.59us
[180:29:40.964089582] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 22997.29us and 2
[180:29:40.964161666] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 45994.59us
[180:29:40.964221197] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 22997.29us analogue gain 2
[180:29:40.964284114] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:40.964326093] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:40.964368905] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:40.964561197] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.964620468] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.964937760] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 22990.24us (Shutter lines: 3158, AGC requested 22997.29us) Gain: 2 (Gain Code: 32)
[180:29:40.965149895] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 32 at index 3
[180:29:40.965212864] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 3158 at index 3
[180:29:40.965263385] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 3
[180:29:40.965317864] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990172913
[180:29:40.965502187] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989988486
[180:29:40.965612552] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:40.965675364] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:40.965822239] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (4 left)
[180:29:40.965879531] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989610465
[180:29:40.987089226] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 3
[180:29:40.987199747] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 3 started
[180:29:40.987263028] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 32 at index 3
[180:29:40.987320111] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 3158 at index 3
[180:29:40.987412507] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 3
[180:29:40.988108289] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967386811
[180:29:40.990149175] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 1
[180:29:40.990210685] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:41.990205060
[180:29:40.990271727] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 8, timestamp: 649780986984000
[180:29:40.990328133] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 1
[180:29:40.990380008] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 137 at index 1
[180:29:40.990428081] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 1
[180:29:40.990477040] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 1
[180:29:40.990548394] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 8
[180:29:40.990633342] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999577239
[180:29:40.990832977] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 997.36us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:40.990975738] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:40.991033707] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:40.991089644] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:40.991152717] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:40.991195842] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 45994.59us
[180:29:40.991252405] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 997.36us
[180:29:40.991306155] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 4
[180:29:40.991351415] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 3989.44us
[180:29:40.991405894] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:40.991453342] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 4 speed 1
[180:29:40.991502092] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:40.992369280] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 8, timestamp: 649780986984000
[180:29:40.992440270] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:40.992502405] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 1
[180:29:40.992595686] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997615467
[180:29:40.992681259] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997528801
[180:29:40.995514177] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 1
[180:29:40.995622927] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 8, timestamp: 649780986984000
[180:29:40.995677250] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 8 for Unicam Image
[180:29:40.995734385] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 1
[180:29:40.995815375] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:40.995868917] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649780986984000
[180:29:40.995917667] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:40.995969021] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:40.996069385] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:40.996124438] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649780986984000
[180:29:40.996172458] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:40.996751834] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:40.996926834] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:40.996997563] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649780986984000
[180:29:40.997092355] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993119580
[180:29:40.997576469] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 33.6329
[180:29:40.997704542] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:40.997779751] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:40.997840167] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.00387913 target 0.160168 gives gain 10
[180:29:40.997906261] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.0387913 target 0.160168 gives gain 40.252
[180:29:40.997969438] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.156143 target 0.160168 gives gain 41.0269
[180:29:40.998031365] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.159149 target 0.160168 gives gain 41.0318
[180:29:40.998105220] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 13.5627
[180:29:40.998163292] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 41.0318 (target_Y 0.160168 ev 1 base_ev 1)
[180:29:40.998229074] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 40923.52us
[180:29:40.998290272] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 41.0318 target_Y 0.160168
[180:29:40.998349647] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:40.998401313] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 40923.52us
[180:29:40.998460168] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 40923.52us no dg 40923.52us
[180:29:40.998531626] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 20461.76us and 2
[180:29:40.998602511] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 40923.52us
[180:29:40.998660116] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 20461.76us analogue gain 2
[180:29:40.998722199] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:40.998765116] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:40.998808605] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:40.998976470] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 20456.80us (Shutter lines: 2810, AGC requested 20461.76us) Gain: 2 (Gain Code: 32)
[180:29:40.999018709] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.999113605] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:40.999279803] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 32 at index 4
[180:29:40.999346157] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 2810 at index 4
[180:29:40.999396730] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 4
[180:29:40.999489960] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:40.999553033] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:40.999675012] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (3 left)
[180:29:40.999735949] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990475204
[180:29:41.021826218] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 4
[180:29:41.021946791] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 4 started
[180:29:41.022012155] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 32 at index 4
[180:29:41.022070801] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 2810 at index 4
[180:29:41.022170749] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 4
[180:29:41.022905176] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967318946
[180:29:41.024919500] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 0
[180:29:41.025064500] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.025056010
[180:29:41.025135854] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 7, timestamp: 649781021710000
[180:29:41.025201427] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 32 at index 2
[180:29:41.025258563] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 2384 at index 2
[180:29:41.025309448] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 2
[180:29:41.025360906] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 2
[180:29:41.025433354] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 7
[180:29:41.025533979] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999528176
[180:29:41.025687261] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 17355.52us Frame length: 4578 Line length: 7.28us Gain: 2
[180:29:41.025842313] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.76777
[180:29:41.025900334] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.76777
[180:29:41.025958459] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 5.65685 strength 0.75
[180:29:41.026022782] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.026066584] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 40923.52us
[180:29:41.026124344] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 34711.04us
[180:29:41.026178407] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.17898
[180:29:41.026223615] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 40923.52us
[180:29:41.026278719] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.026327626] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 5 speed 1
[180:29:41.026377313] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.027396063] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 7, timestamp: 649781021710000
[180:29:41.027469553] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.027532730] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 0
[180:29:41.027626116] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997435988
[180:29:41.030522783] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 0
[180:29:41.030636481] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 7, timestamp: 649781021710000
[180:29:41.030690492] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for Unicam Image
[180:29:41.030748148] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 0
[180:29:41.030817888] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for Unicam Image
[180:29:41.030871169] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 2
[180:29:41.030941586] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for Unicam Image
[180:29:41.030993617] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 3
[180:29:41.031061898] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 3 for Unicam Image
[180:29:41.031114971] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 4
[180:29:41.031178304] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 4 for Unicam Image
[180:29:41.031230596] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 5
[180:29:41.031294398] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 5 for Unicam Image
[180:29:41.031346534] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 6
[180:29:41.031407159] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 6 for Unicam Image
[180:29:41.031459294] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 7
[180:29:41.031542107] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:41.031603305] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649781021710000
[180:29:41.031653721] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:41.031704711] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:41.031800648] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.031854867] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781021710000
[180:29:41.031902263] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.031953565] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.032032107] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.032086534] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781021710000
[180:29:41.032178721] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.992883434
[180:29:41.032916795] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 144.273
[180:29:41.033068409] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.033149399] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.033209711] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.99369 target 0.160721 gives gain 0.161579
[180:29:41.033279347] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.401569
[180:29:41.033334972] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.033377472] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.401569 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.033439659] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 13938.86us
[180:29:41.033506066] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.401569 target_Y 0.4
[180:29:41.033564295] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.033613253] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 13938.86us
[180:29:41.033671066] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 13938.86us no dg 13938.86us
[180:29:41.033742576] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 13938.86us and 1
[180:29:41.033811951] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 13938.86us
[180:29:41.033868930] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 13938.86us analogue gain 1
[180:29:41.033931326] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.033973149] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.034016170] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.034171222] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 13933.92us (Shutter lines: 1914, AGC requested 13938.86us) Gain: 1 (Gain Code: 16)
[180:29:41.034204868] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.034303305] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.034457368] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 5
[180:29:41.034518722] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 1914 at index 5
[180:29:41.034569347] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 5
[180:29:41.034655337] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.034717733] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.034830285] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (2 left)
[180:29:41.034887733] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990173590
[180:29:41.056560918] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 5
[180:29:41.056678678] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 5 started
[180:29:41.056741334] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 5
[180:29:41.056798574] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 1914 at index 5
[180:29:41.056895032] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 5
[180:29:41.058463887] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.966612904
[180:29:41.059621023] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 1
[180:29:41.059705346] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.059699148
[180:29:41.059770502] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 8, timestamp: 649781056435000
[180:29:41.059833002] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 32 at index 3
[180:29:41.059887377] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 3158 at index 3
[180:29:41.059936752] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 3
[180:29:41.059987325] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 3
[180:29:41.060155815] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 8
[180:29:41.060244200] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999460625
[180:29:41.060383836] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 22990.24us Frame length: 4578 Line length: 7.28us Gain: 2
[180:29:41.060522273] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.76777
[180:29:41.060579982] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.76777
[180:29:41.060637325] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 5.65685 strength 0.75
[180:29:41.060700919] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.060745294] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 13938.86us
[180:29:41.060802169] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 45980.48us
[180:29:41.060857013] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1
[180:29:41.060902898] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 45980.48us
[180:29:41.060957898] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.061006232] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 6 speed 1
[180:29:41.061055086] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.061981076] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 8, timestamp: 649781056435000
[180:29:41.062049826] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.062114409] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 1
[180:29:41.062210920] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997494062
[180:29:41.065098733] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 1
[180:29:41.065210452] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 8, timestamp: 649781056435000
[180:29:41.065279983] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:41.065336962] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649781056435000
[180:29:41.065389150] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 7 for ISP Output0
[180:29:41.065447379] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 0
[180:29:41.065540452] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output0
[180:29:41.065598004] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 1
[180:29:41.065843525] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for ISP Output0
[180:29:41.065925817] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 2
[180:29:41.066117692] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 3 for ISP Output0
[180:29:41.066178525] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 3
[180:29:41.066338942] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 4 for ISP Output0
[180:29:41.066399202] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 4
[180:29:41.066556390] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 5 for ISP Output0
[180:29:41.066617588] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 5
[180:29:41.066780609] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 6 for ISP Output0
[180:29:41.066841755] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 6
[180:29:41.067039932] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.067110765] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781056435000
[180:29:41.067163682] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.067217224] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.067299828] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.067353682] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781056435000
[180:29:41.067438369] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.992266820
[180:29:41.067869724] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 109.909
[180:29:41.067953838] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.068024724] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.068081234] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.995954 target 0.16055 gives gain 0.16104
[180:29:41.068144255] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.401569
[180:29:41.068198734] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.068239516] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.401569 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.068581807] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 18464.32us
[180:29:41.068667172] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.401569 target_Y 0.4
[180:29:41.068727849] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.068776547] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 18464.32us
[180:29:41.068833162] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 18464.32us no dg 18464.32us
[180:29:41.068903630] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 15000.00us and 1.23095
[180:29:41.068973266] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 18464.32us
[180:29:41.069030297] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 15000.00us analogue gain 1.23095
[180:29:41.069092901] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.069136703] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.069180818] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.069372954] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.069347797] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 14996.80us (Shutter lines: 2060, AGC requested 15000.00us) Gain: 1.23095 (Gain Code: 19)
[180:29:41.069448370] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.069713787] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 19 at index 6
[180:29:41.069787381] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 2060 at index 6
[180:29:41.069840037] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 6
[180:29:41.069930350] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.069994100] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.070194725] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (1 left)
[180:29:41.070258058] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989447392
[180:29:41.091259576] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 6
[180:29:41.091383170] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 6 started
[180:29:41.091457701] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 19 at index 6
[180:29:41.091518951] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 2060 at index 6
[180:29:41.091631451] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 6
[180:29:41.093161452] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.966551551
[180:29:41.094323535] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 0
[180:29:41.094385775] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.094379838
[180:29:41.094448171] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 7, timestamp: 649781091155000
[180:29:41.094505879] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 32 at index 4
[180:29:41.094558952] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 2810 at index 4
[180:29:41.094608431] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 4
[180:29:41.094658015] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 4
[180:29:41.094729265] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 7
[180:29:41.094816556] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999568802
[180:29:41.094948327] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 20456.80us Frame length: 4578 Line length: 7.28us Gain: 2
[180:29:41.095089213] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.76777
[180:29:41.095146609] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.76777
[180:29:41.095203432] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 5.65685 strength 0.75
[180:29:41.095266036] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.095309577] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 18464.32us
[180:29:41.095366088] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 40913.60us
[180:29:41.095419838] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1
[180:29:41.095464994] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 40913.60us
[180:29:41.095519369] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.095567442] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 7 speed 1
[180:29:41.095616453] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.096494370] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 7, timestamp: 649781091155000
[180:29:41.096570932] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.096634526] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 0
[180:29:41.096728693] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997657031
[180:29:41.099654527] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 0
[180:29:41.099773225] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 7, timestamp: 649781091155000
[180:29:41.099839579] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 0
[180:29:41.099893017] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 7, timestamp: 649781091155000
[180:29:41.099952756] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.100091975] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781091155000
[180:29:41.100144319] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.100201454] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.100305517] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.100358642] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781091155000
[180:29:41.100436611] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993948540
[180:29:41.100885517] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 120.668
[180:29:41.100993954] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.101067913] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.101126142] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.985335 target 0.160603 gives gain 0.162828
[180:29:41.101191819] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.401569
[180:29:41.101246350] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.101287809] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.401569 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.101351350] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 16429.62us
[180:29:41.101414059] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.401569 target_Y 0.4
[180:29:41.101471142] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.101519528] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 16429.62us
[180:29:41.101577601] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 16429.62us no dg 16429.62us
[180:29:41.101648694] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 15000.00us and 1.09531
[180:29:41.101719736] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 16429.62us
[180:29:41.101777705] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 15000.00us analogue gain 1.09531
[180:29:41.101839267] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.101882288] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.101925517] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.102091924] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 14996.80us (Shutter lines: 2060, AGC requested 15000.00us) Gain: 1.09531 (Gain Code: 17)
[180:29:41.102138851] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.102246872] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.102424997] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 17 at index 7
[180:29:41.102492028] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 2060 at index 7
[180:29:41.102543486] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 7
[180:29:41.102636924] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.102703174] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.102819580] [5039] DEBUG RPI pipeline_base.cpp:1484 Dropping frame at the request of the IPA (0 left)
[180:29:41.102879320] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991506560
[180:29:41.125963391] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 7
[180:29:41.126058547] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 7 started
[180:29:41.126117714] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 17 at index 7
[180:29:41.126173026] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 2060 at index 7
[180:29:41.126262453] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 7
[180:29:41.127168287] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967219312
[180:29:41.129075006] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 2
[180:29:41.129172402] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.129166308
[180:29:41.129237819] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 1, timestamp: 649781125877000
[180:29:41.129297558] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 5
[180:29:41.129351986] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 1914 at index 5
[180:29:41.129400163] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 5
[180:29:41.129449329] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 5
[180:29:41.129521308] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 1
[180:29:41.129608861] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999563177
[180:29:41.129746361] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 13933.92us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.129884173] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.129940736] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.129997871] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.130108184] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.130152090] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 16429.62us
[180:29:41.130211309] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 13933.92us
[180:29:41.130265163] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.17911
[180:29:41.130310215] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 16429.62us
[180:29:41.130365371] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.130412923] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 8 speed 1
[180:29:41.130461517] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.131480736] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 1, timestamp: 649781125877000
[180:29:41.131557090] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.131621726] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 2
[180:29:41.131826361] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997348020
[180:29:41.134762560] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 2
[180:29:41.134884279] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 1, timestamp: 649781125877000
[180:29:41.134962196] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 1
[180:29:41.135019488] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 1, timestamp: 649781125877000
[180:29:41.135082352] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.135134331] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781125877000
[180:29:41.135180321] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.135239071] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.135350842] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.135404279] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781125877000
[180:29:41.135495321] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993678122
[180:29:41.135962040] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 250.453
[180:29:41.136074019] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.136148290] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.136205217] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.664982 target 0.161252 gives gain 0.242127
[180:29:41.136269019] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.401569
[180:29:41.136323290] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.136364748] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.401569 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.136427978] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 5595.43us
[180:29:41.136489332] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.401569 target_Y 0.4
[180:29:41.136546624] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.136596103] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 5595.43us
[180:29:41.136654540] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 5595.43us no dg 5595.43us
[180:29:41.136726572] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 5595.43us and 1
[180:29:41.136797405] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 5595.43us
[180:29:41.136855582] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 5595.43us analogue gain 1
[180:29:41.136920738] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.136965530] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.137009332] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.137183968] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 5591.04us (Shutter lines: 768, AGC requested 5595.43us) Gain: 1 (Gain Code: 16)
[180:29:41.137288707] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.137359124] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.137499593] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 8
[180:29:41.137565634] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 768 at index 8
[180:29:41.137617666] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 8
[180:29:41.137708759] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.137772770] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.137897978] [5039] DEBUG Request request.cpp:122 Request(0:C:0/2:0)
Raw stream: 640x[180:29:41.138073395] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991102184
400 stride 640 format R8
[180:29:41.138646676] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.138740322] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for Unicam Image
[180:29:41.138805531] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 2
[180:29:41.138891729] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output0
[180:29:41.138947510] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 1
[180:29:41.139050374] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990123017
[180:29:41.160693038] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 8
[180:29:41.160790851] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 8 started
[180:29:41.160851528] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 8
[180:29:41.160906372] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 768 at index 8
[180:29:41.160993768] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 8
[180:29:41.162483820] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.966690873
[180:29:41.163765123] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 3
[180:29:41.163823404] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.163817675
[180:29:41.163884550] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 2, timestamp: 649781160604000
[180:29:41.163937883] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 19 at index 6
[180:29:41.163988300] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 2060 at index 6
[180:29:41.164035904] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 6
[180:29:41.164085488] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 6
[180:29:41.164152102] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 2
[180:29:41.164270279] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 14996.80us Frame length: 4578 Line length: 7.28us Gain: 1.1875
[180:29:41.164426009] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.36216
[180:29:41.164485592] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.36216
[180:29:41.164544915] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4.3589 strength 0.75
[180:29:41.164613352] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.164657207] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 5595.43us
[180:29:41.164713717] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 17808.70us
[180:29:41.164767259] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1
[180:29:41.164812311] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 17808.70us
[180:29:41.164866790] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.164916373] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 9 speed 1
[180:29:41.164965071] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.165189394] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.998636302
[180:29:41.171146376] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 2, timestamp: 649781160604000
[180:29:41.171257209] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.171324240] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 3
[180:29:41.172030699] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991802549
[180:29:41.174985231] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 3
[180:29:41.175116273] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 2, timestamp: 649781160604000
[180:29:41.175208617] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 2
[180:29:41.175266065] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 2, timestamp: 649781160604000
[180:29:41.175329762] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.175382835] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781160604000
[180:29:41.175431221] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.175488148] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.175598408] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.175654763] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781160604000
[180:29:41.175745856] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.988077912
[180:29:41.176242471] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 240.431
[180:29:41.176372471] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.176445909] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.176505284] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.847884 target 0.161202 gives gain 0.189899
[180:29:41.176571169] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.401569
[180:29:41.176625857] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.176664034] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.401569 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.176724763] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 7151.42us
[180:29:41.176787159] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.401569 target_Y 0.4
[180:29:41.176845023] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.176893982] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 7151.42us
[180:29:41.176952159] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 7151.42us no dg 7151.42us
[180:29:41.177023409] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 7151.42us and 1
[180:29:41.177096221] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 7151.42us
[180:29:41.177153565] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 7151.42us analogue gain 1
[180:29:41.177216482] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.177258617] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.177301794] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.177465336] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 7148.96us (Shutter lines: 982, AGC requested 7151.42us) Gain: 1 (Gain Code: 16)
[180:29:41.177545909] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.177615597] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.177768045] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 9
[180:29:41.177832836] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 982 at index 9
[180:29:41.177883930] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 9
[180:29:41.177973045] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.178041274] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.178170284] [5039] DEBUG Request request.cpp:122 Request(1:C:0/2:0)
[180:29:41.178319243] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.985507078
[180:29:41.178542628] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.178602628] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for Unicam Image
[180:29:41.178664816] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 3
[180:29:41.178746170] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for ISP Output0
[180:29:41.178801691] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 2
[180:29:41.178903826] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.984920567
[180:29:41.195437218] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 9
[180:29:41.195549197] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 9 started
[180:29:41.195612999] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 9
[180:29:41.195668207] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 982 at index 9
[180:29:41.195762843] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 9
[180:29:41.196488728] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967345978
[180:29:41.198526438] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 4
[180:29:41.198629875] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.198622479
[180:29:41.198698625] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 3, timestamp: 649781195327000
[180:29:41.198761333] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 17 at index 7
[180:29:41.198816646] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 2060 at index 7
[180:29:41.198865292] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 7
[180:29:41.198915031] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 7
[180:29:41.198993938] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 3
[180:29:41.199093000] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999537656
[180:29:41.199236229] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 14996.80us Frame length: 4578 Line length: 7.28us Gain: 1.0625
[180:29:41.199412011] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.28847
[180:29:41.199471386] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.28847
[180:29:41.199529407] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4.12311 strength 0.75
[180:29:41.199596542] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.199640657] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 5595.43us
[180:29:41.199698469] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 15934.10us
[180:29:41.199751334] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1
[180:29:41.199796386] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 15934.10us
[180:29:41.199850969] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.199900500] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.199950657] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.200970761] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 3, timestamp: 649781195327000
[180:29:41.201047324] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.201111907] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 4
[180:29:41.201311959] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997318280
[180:29:41.204242690] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 4
[180:29:41.204370346] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 3, timestamp: 649781195327000
[180:29:41.204465710] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 3
[180:29:41.204526283] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 3, timestamp: 649781195327000
[180:29:41.204594461] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.204651440] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781195327000
[180:29:41.204700763] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.204758940] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.204884721] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.204944721] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781195327000
[180:29:41.205041023] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993587602
[180:29:41.205435398] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 82.7582
[180:29:41.205528055] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.205598940] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.205655763] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.250026 target 0.160414 gives gain 0.639033
[180:29:41.205724513] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.867868
[180:29:41.205778107] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.205818888] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.867868 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.205879617] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 13828.70us
[180:29:41.205936076] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.867868 target_Y 0.4
[180:29:41.205991753] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.206047221] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 13828.70us
[180:29:41.206104617] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 13828.70us no dg 13828.70us
[180:29:41.206173628] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 13828.70us and 1
[180:29:41.206240659] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 13828.70us
[180:29:41.206296909] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 13828.70us analogue gain 1
[180:29:41.206358367] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.206400242] [5043] DEBUG RPiAlsc alsc.cpp:362 Starting ALSC calculation
[180:29:41.206442222] [5043] DEBUG RPiAlsc alsc.cpp:332 no AWB results found, using 4500
[180:29:41.206600242] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 13824.72us (Shutter lines: 1899, AGC requested 13828.70us) Gain: 1 (Gain Code: 16)
[180:29:41.206691961] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.206755815] [5040] DEBUG RPiAlsc alsc.cpp:471 no calibrations found
[180:29:41.206779930] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 10
[180:29:41.206840607] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 1899 at index 10
[180:29:41.206891493] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 10
[180:29:41.206979513] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.207040555] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.207166649] [5039] DEBUG Request request.cpp:122 Request(2:C:0/2:0)
[180:29:41.207283628] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991345361
[180:29:41.207476962] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.207528576] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 3 for Unicam Image
[180:29:41.207586857] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 4
[180:29:41.207660868] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 3 for ISP Output0
[180:29:41.207713628] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 3
[180:29:41.207801180] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.990826767
[180:29:41.230149626] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 10
[180:29:41.230258480] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 10 started
[180:29:41.230320824] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 10
[180:29:41.230376397] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 1899 at index 10
[180:29:41.230466032] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 10
[180:29:41.231151189] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967478634
[180:29:41.233235721] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 5
[180:29:41.233326502] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.233319888
[180:29:41.233390825] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 4, timestamp: 649781230048000
[180:29:41.233450148] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 8
[180:29:41.233503950] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 768 at index 8
[180:29:41.233552336] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 8
[180:29:41.233601346] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 8
[180:29:41.233669419] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 4
[180:29:41.233753325] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999572500
[180:29:41.233803638] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 5591.04us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.233973169] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.234032961] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.234090617] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.234157804] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.234202127] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 5595.43us
[180:29:41.234259263] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 5591.04us
[180:29:41.234312440] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.00078
[180:29:41.234357544] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 5595.43us
[180:29:41.234412388] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.234460617] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.234510825] [5043] DEBUG RPiAlsc alsc.cpp:321 Fetch ALSC results
[180:29:41.235558170] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 4, timestamp: 649781230048000
[180:29:41.235674159] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.235743482] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 5
[180:29:41.236022180] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997307343
[180:29:41.239381504] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 5
[180:29:41.239530046] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 4, timestamp: 649781230048000
[180:29:41.239614525] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 4
[180:29:41.239669056] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 4, timestamp: 649781230048000
[180:29:41.239730567] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.239782963] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781230048000
[180:29:41.239830775] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.239888640] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.239993432] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.240096765] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781230048000
[180:29:41.240181869] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993143904
[180:29:41.241565776] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 220.244
[180:29:41.241702391] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.241776297] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.241836349] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.233549 target 0.161101 gives gain 0.686856
[180:29:41.241909682] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.926061
[180:29:41.241964161] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.242005516] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.926061 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.242069109] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 5177.64us
[180:29:41.242131505] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.926061 target_Y 0.4
[180:29:41.242188172] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.242234734] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 5177.64us
[180:29:41.242289110] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 5177.64us no dg 5177.64us
[180:29:41.242366245] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 5177.64us and 1
[180:29:41.242442703] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 5177.64us
[180:29:41.242502026] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 5177.64us analogue gain 1
[180:29:41.242661089] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 1
[180:29:41.242737078] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 5176.08us (Shutter lines: 711, AGC requested 5177.64us) Gain: 1 (Gain Code: 16)
[180:29:41.242965881] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 11
[180:29:41.243033797] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 711 at index 11
[180:29:41.243085047] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 11
[180:29:41.243172079] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.243233224] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.243346662] [5039] DEBUG Request request.cpp:122 Request(3:C:0/2:0)
[180:29:41.243467183] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989859111
[180:29:41.243554006] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989771351
[180:29:41.243794527] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.243858902] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 4 for Unicam Image
[180:29:41.243928173] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 5
[180:29:41.244009631] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 4 for ISP Output0
[180:29:41.244063381] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 4
[180:29:41.244155360] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.989169997
[180:29:41.264883753] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 11
[180:29:41.264996253] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 11 started
[180:29:41.265070107] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 11
[180:29:41.265125159] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 711 at index 11
[180:29:41.265212816] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 11
[180:29:41.265964639] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967378635
[180:29:41.267961983] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 6
[180:29:41.268041202] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.268035317
[180:29:41.268116567] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 5, timestamp: 649781264775000
[180:29:41.268177608] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 9
[180:29:41.268232036] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 982 at index 9
[180:29:41.268278702] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 9
[180:29:41.268326619] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 9
[180:29:41.268398286] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 5
[180:29:41.268487244] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999553229
[180:29:41.268540890] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 7148.96us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.268714327] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.268772973] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.268832921] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.268966150] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.269011775] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 7151.42us
[180:29:41.269071984] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 7148.96us
[180:29:41.269126932] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.00034
[180:29:41.269172713] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 7151.42us
[180:29:41.269227869] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.269276775] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.270266359] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 5, timestamp: 649781264775000
[180:29:41.270367661] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.270432974] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 6
[180:29:41.270660474] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997382395
[180:29:41.273527767] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 6
[180:29:41.273640058] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 5, timestamp: 649781264775000
[180:29:41.273713548] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 5
[180:29:41.273768600] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 5, timestamp: 649781264775000
[180:29:41.273828965] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.273880996] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781264775000
[180:29:41.273929173] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.273985110] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.274085319] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.274138288] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781264775000
[180:29:41.274210006] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.993830623
[180:29:41.274608444] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 232.086
[180:29:41.274722350] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.274798809] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.274858236] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.31414 target 0.16116 gives gain 0.511394
[180:29:41.274926413] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 0.702801
[180:29:41.274980319] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.275020840] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 0.702801 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.275082142] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 5024.29us
[180:29:41.275141778] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 0.702801 target_Y 0.4
[180:29:41.275197819] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.275245580] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 5024.29us
[180:29:41.275302663] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 5109.06us no dg 5109.06us
[180:29:41.275371621] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 5109.06us and 1
[180:29:41.275440267] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 5109.06us
[180:29:41.275496674] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 5109.06us analogue gain 1
[180:29:41.275557455] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 2
[180:29:41.275616778] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 5103.28us (Shutter lines: 701, AGC requested 5109.06us) Gain: 1 (Gain Code: 16)
[180:29:41.275825944] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 12
[180:29:41.275894070] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 701 at index 12
[180:29:41.275943184] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 12
[180:29:41.276025892] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.276087820] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.276195736] [5039] DEBUG Request request.cpp:122 Request(4:C:0/2:0)
[180:29:41.276327143] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991714633
[180:29:41.276588809] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.276653184] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 5 for Unicam Image
[180:29:41.276713184] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 6
[180:29:41.276789174] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 5 for ISP Output0
[180:29:41.276841205] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 5
[180:29:41.276931570] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991109268
[180:29:41.299604026] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 12
[180:29:41.299711318] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 12 started
[180:29:41.299785432] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 12
[180:29:41.299841266] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 701 at index 12
[180:29:41.299928922] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 12
[180:29:41.300615016] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967428947
[180:29:41.302662360] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 7
[180:29:41.302721475] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.302715433
[180:29:41.302782308] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 6, timestamp: 649781299496000
[180:29:41.302837152] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 10
[180:29:41.302888298] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 1899 at index 10
[180:29:41.302936788] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 10
[180:29:41.302985381] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 10
[180:29:41.303052933] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 6
[180:29:41.303131111] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999589322
[180:29:41.303174183] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 13824.72us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.303333246] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.303392309] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.303449236] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.303515329] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.303559444] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 13828.70us
[180:29:41.303616788] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 13824.72us
[180:29:41.303670850] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.00029
[180:29:41.303716371] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 13828.70us
[180:29:41.303770902] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.303820434] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.304680747] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 6, timestamp: 649781299496000
[180:29:41.304747465] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.304810278] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 7
[180:29:41.305037257] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997686301
[180:29:41.307920435] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 7
[180:29:41.308033300] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 6, timestamp: 649781299496000
[180:29:41.308107623] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 6
[180:29:41.308161529] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 6, timestamp: 649781299496000
[180:29:41.308222362] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.308274185] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781299496000
[180:29:41.308321477] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.308378612] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.308484342] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.308538404] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781299496000
[180:29:41.308614915] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.994106195
[180:29:41.309009238] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 80.7269
[180:29:41.309115644] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.309191321] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.309251009] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.211993 target 0.160404 gives gain 0.753093
[180:29:41.309323561] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 1.01352
[180:29:41.309376529] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.309417363] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 1.01352 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.309561998] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 14011.67us
[180:29:41.309633821] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 1.01352 target_Y 0.4
[180:29:41.309691478] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.309740332] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 14011.67us
[180:29:41.309800019] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 6889.59us no dg 6889.59us
[180:29:41.309872415] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 6889.59us and 1
[180:29:41.309943769] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 6889.59us
[180:29:41.310107415] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 6889.59us analogue gain 1
[180:29:41.310177676] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 3
[180:29:41.310242624] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 6886.88us (Shutter lines: 946, AGC requested 6889.59us) Gain: 1 (Gain Code: 16)
[180:29:41.310438092] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 13
[180:29:41.310503353] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 946 at index 13
[180:29:41.310553978] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 13
[180:29:41.310642988] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.310705384] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.310825853] [5039] DEBUG Request request.cpp:122 Request(5:C:0/2:0)
[180:29:41.311035697] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991688018
[180:29:41.311161113] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.311212311] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 6 for Unicam Image
[180:29:41.311277103] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 7
[180:29:41.311372416] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 6 for ISP Output0
[180:29:41.311432364] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 6
[180:29:41.311548926] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991174215
[180:29:41.334309559] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 13
[180:29:41.334407372] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 13 started
[180:29:41.334470809] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 13
[180:29:41.334525184] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 946 at index 13
[180:29:41.334613414] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 13
[180:29:41.335298883] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967423998
[180:29:41.337383571] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 2
[180:29:41.337442737] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.337436956
[180:29:41.337502060] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 1, timestamp: 649781334220000
[180:29:41.337556540] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 11
[180:29:41.337607217] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 711 at index 11
[180:29:41.337656071] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 11
[180:29:41.337705081] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 11
[180:29:41.337771279] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 1
[180:29:41.337848623] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999593229
[180:29:41.337903779] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 5176.08us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.338062894] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.338123831] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.338181384] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.338248102] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.338292269] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 5177.64us
[180:29:41.338349248] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 5176.08us
[180:29:41.338403102] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.0003
[180:29:41.338449352] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 5177.64us
[180:29:41.338503936] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.338552217] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.339418884] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 1, timestamp: 649781334220000
[180:29:41.339485707] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.339548155] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 2
[180:29:41.339639926] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997802499
[180:29:41.342567739] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 2
[180:29:41.342697010] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 1, timestamp: 649781334220000
[180:29:41.342776750] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 1
[180:29:41.342833885] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 1, timestamp: 649781334220000
[180:29:41.342898000] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.342951385] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781334220000
[180:29:41.343001229] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.343060552] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.343173937] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.343225917] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781334220000
[180:29:41.343301854] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.994140883
[180:29:41.343756334] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 211.17
[180:29:41.343881281] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.343957323] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.344021542] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.207529 target 0.161056 gives gain 0.772342
[180:29:41.344093000] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 1.03257
[180:29:41.344146490] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.344187740] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 1.03257 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.344249094] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 5344.65us
[180:29:41.344309563] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 1.03257 target_Y 0.4
[180:29:41.344364563] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.344412323] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 5344.65us
[180:29:41.344469823] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 6580.60us no dg 6580.60us
[180:29:41.344539823] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 6580.60us and 1
[180:29:41.344608573] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 6580.60us
[180:29:41.344664719] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 6580.60us analogue gain 1
[180:29:41.344727480] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 4
[180:29:41.344785709] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 6573.84us (Shutter lines: 903, AGC requested 6580.60us) Gain: 1 (Gain Code: 16)
[180:29:41.345018417] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 14
[180:29:41.345091699] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 903 at index 14
[180:29:41.345140917] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 14
[180:29:41.345235084] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.345299355] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.345423834] [5039] DEBUG Request request.cpp:122 Request(6:C:0/2:0)
[180:29:41.345604303] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991840309
[180:29:41.345708365] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.345758938] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for Unicam Image
[180:29:41.345817116] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 2
[180:29:41.345887949] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output0
[180:29:41.345941126] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 1
[180:29:41.346021647] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991420622
[180:29:41.369053738] [5039] DEBUG RPI pipeline_base.cpp:1357 Frame start 14
[180:29:41.369163791] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:240 frame 14 started
[180:29:41.369237697] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Analogue Gain to 16 at index 14
[180:29:41.369293114] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Exposure to 903 at index 14
[180:29:41.369380301] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:270 Setting Vertical Blanking to 4178 at index 14
[180:29:41.370082489] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.967363113
[180:29:41.372108010] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video0[24:cap]: Dequeuing buffer 3
[180:29:41.372165927] [5039] DEBUG Timer timer.cpp:95 Starting timer 0x73e19dd0: deadline 180:29:42.372160406
[180:29:41.372227333] [5039] DEBUG RPI vc4.cpp:745 Stream Unicam Image buffer dequeue, buffer id 2, timestamp: 649781368944000
[180:29:41.372281760] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Analogue Gain to 16 at index 12
[180:29:41.372332385] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Exposure to 701 at index 12
[180:29:41.372378479] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Horizontal Blanking to 816 at index 12
[180:29:41.372426813] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:220 Reading Vertical Blanking to 4178 at index 12
[180:29:41.372491865] [5039] DEBUG RPI vc4.cpp:928 Signalling prepareIsp: Bayer buffer id: 2
[180:29:41.372572646] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.999592916
[180:29:41.372633479] [5043] DEBUG IPARPI ipa_base.cpp:1202 Metadata - Exposure: 5103.28us Frame length: 4578 Line length: 7.28us Gain: 1
[180:29:41.372796188] [5043] DEBUG RPiNoise noise.cpp:77 constant 0 slope 1.25
[180:29:41.372854729] [5043] DEBUG RPiSdn sdn.cpp:56 Noise profile: constant 0 slope 1.25
[180:29:41.372912125] [5043] DEBUG RPiSdn sdn.cpp:65 programmed constant 0 slope 4 strength 0.75
[180:29:41.372979157] [5043] DEBUG RPiAgc agc.cpp:598 No AWB status found
[180:29:41.373023063] [5043] DEBUG RPiAgc agc.cpp:437 Want total exposure 5109.06us
[180:29:41.373080511] [5043] DEBUG RPiAgc agc.cpp:443 Actual exposure 5103.28us
[180:29:41.373134990] [5043] DEBUG RPiAgc agc.cpp:444 Use digitalGain 1.00113
[180:29:41.373180407] [5043] DEBUG RPiAgc agc.cpp:445 Effective exposure 5109.06us
[180:29:41.373235302] [5043] DEBUG RPiAgc agc.cpp:523 Lock count updated to 0
[180:29:41.373284365] [5043] DEBUG RPiAlsc alsc.cpp:402 frame count 10 speed 0.05
[180:29:41.374222803] [5039] DEBUG RPI vc4.cpp:851 Input re-queue to ISP, buffer id 2, timestamp: 649781368944000
[180:29:41.374288532] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 0 for ISP Input
[180:29:41.374352230] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video13[26:out]: Queueing buffer 3
[180:29:41.374445459] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.997721197
[180:29:41.377326137] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video13[26:out]: Dequeuing buffer 3
[180:29:41.377438846] [5039] DEBUG RPI vc4.cpp:773 Stream ISP Input buffer complete, buffer id 2, timestamp: 649781368944000
[180:29:41.377513481] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video14[27:cap]: Dequeuing buffer 2
[180:29:41.377566971] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output0 buffer complete, buffer id 2, timestamp: 649781368944000
[180:29:41.377626346] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video15[28:cap]: Dequeuing buffer 0
[180:29:41.377677700] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Output1 buffer complete, buffer id 1, timestamp: 649781368944000
[180:29:41.377725200] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Output1
[180:29:41.377781294] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video15[28:cap]: Queueing buffer 0
[180:29:41.377877856] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1764 /dev/video16[29:cap]: Dequeuing buffer 0
[180:29:41.377930669] [5039] DEBUG RPI vc4.cpp:801 Stream ISP Stats buffer complete, buffer id 1, timestamp: 649781368944000
[180:29:41.378002596] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.994163175
[180:29:41.378413533] [5043] DEBUG RPiLux lux.cpp:96 : estimated lux 215.328
[180:29:41.378519211] [5043] DEBUG RPiAgc agc.cpp:534 ev 1 fixedShutter 0.00us fixedAnalogueGain 0
[180:29:41.378591919] [5043] DEBUG RPiAgc agc.cpp:571 exposureMode normal constraintMode normal meteringMode centre-weighted
[180:29:41.378651242] [5043] DEBUG RPiAgc agc.cpp:702 Initial Y 0.208539 target 0.161077 gives gain 0.768718
[180:29:41.378722388] [5043] DEBUG RPiAgc agc.cpp:711 Constraint has target_Y 0.4 giving gain 1.02773
[180:29:41.378776554] [5043] DEBUG RPiAgc agc.cpp:714 Lower bound constraint adopted
[180:29:41.378817440] [5043] DEBUG RPiAgc agc.cpp:723 Final gain 1.02773 (target_Y 0.4 ev 1 base_ev 1)
[180:29:41.378879263] [5043] DEBUG RPiAgc agc.cpp:759 Target totalExposure 5244.79us
[180:29:41.378940721] [5043] DEBUG RPiAgc agc.cpp:771 after AWB, target dg 1 gain 1.02773 target_Y 0.4
[180:29:41.378995982] [5043] DEBUG RPiAgc agc.cpp:786 Digital gain 1 desaturate? 0
[180:29:41.379043377] [5043] DEBUG RPiAgc agc.cpp:788 Target totalExposureNoDG 5244.79us
[180:29:41.379100252] [5043] DEBUG RPiAgc agc.cpp:835 After filtering, totalExposure 6313.44us no dg 6313.44us
[180:29:41.379170200] [5043] DEBUG RPiAgc agc.cpp:877 Divided up shutter and gain are 6313.44us and 1
[180:29:41.379238013] [5043] DEBUG RPiAgc agc.cpp:917 Output written, total exposure requested is 6313.44us
[180:29:41.379294523] [5043] DEBUG RPiAgc agc.cpp:919 Camera exposure update: shutter time 6313.44us analogue gain 1
[180:29:41.379356607] [5043] DEBUG RPiAlsc alsc.cpp:437 frame_phase 5
[180:29:41.379411398] [5043] DEBUG IPARPI ipa_base.cpp:1372 Applying AGC Exposure: 6311.76us (Shutter lines: 867, AGC requested 6313.44us) Gain: 1 (Gain Code: 16)
[180:29:41.379596138] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Analogue Gain to 16 at index 15
[180:29:41.379663065] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Exposure to 867 at index 15
[180:29:41.379714992] [5039] DEBUG RPiDelayedControls delayed_controls.cpp:182 Queuing Vertical Blanking to 4178 at index 15
[180:29:41.379800201] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 1 for ISP Stats
[180:29:41.379860461] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video16[29:cap]: Queueing buffer 0
[180:29:41.379966607] [5039] DEBUG Request request.cpp:122 Request(7:C:0/2:0)
[180:29:41.380191503] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991978695
[180:29:41.380295097] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991870153
[180:29:41.380567024] [5039] DEBUG RPI pipeline_base.cpp:697 queueRequestDevice: New request.
[180:29:41.380633743] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for Unicam Image
[180:29:41.380696555] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video0[24:cap]: Queueing buffer 3
[180:29:41.380780982] [5039] DEBUG RPISTREAM rpi_stream.cpp:298 Queuing buffer 2 for ISP Output0
[180:29:41.380836607] [5039] DEBUG V4L2 v4l2_videodevice.cpp:1693 /dev/video14[27:cap]: Queueing buffer 2
[180:29:41.380937493] [5039] DEBUG Event event_dispatcher_poll.cpp:216 next timer 0x73e19dd0 expires in 0.991228955
^C
lu4@rp020:~/Projects/libcamera $
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment