[libcamera-devel] [PATCH v2 00/27] libcamera: Handle fallout of FrameBuffer offset support

Mon Sep 6 13:06:27 CEST 2021

On 9/6/21 4:13 PM, Kieran Bingham wrote:
> On 06/09/2021 11:08, Umang Jain wrote:
>> Hi Laurent
>>
>> On 9/6/21 7:30 AM, Laurent Pinchart wrote:
>>> Hello everybody,
>>>
>>> This patch series started as an investigation of a qcam failure with
>>> IPU3 after the merge of the FrameBuffer offset support. While a hack in
>>> qcam would be possible, I decided to instead address the core issue and
>>> fix it in V4L2VideoDevice.
>>>
>>> Compared to v1, the series now includes fixes for cam and qcam in
>>> addition to the changes needed in the libcamera core. They have been
>>> tested with the Raspberry Pi, IPU3, VIMC and UVC pipeline handlers.
>>>
>>> The GStreamer element seems to work fine without any change required.
>>> The V4L2 compatibility layer is still broken, and I haven't tested the
>>> Android HAL yet (any volunteer ?).
>>
>> I am applied this series on top of master and tested on nautilus.
>> Streaming seems fine to me, although it was appearing more choppy than
>> usual.
>>
>> Now that I see, entire nautilus seems laggy to respond in general. One
>> "Chrome" process hogging 50% CPU, seems like a transient issue.
>>
>> So, streaming seems fine on multiple runs, with multiple resolutions
>> selections (from the camera-app menu), however, requesting MJPEG
>> (shutter-click) results in a segfault.
>>
>> The stack trace is below:
>>
>> [0:24:11.415660787] [10635] DEBUG HAL camera_device.cpp:941
>> '\_SB_.PCI0.I2C2.CAM0': Queueing request 140736750235824 with 2 streams
>> [0:24:11.415858538] [10635] DEBUG Buffer framebuffer.cpp:249 Buffer is
>> not contiguous
>> [0:24:11.415905500] [10635] DEBUG HAL camera_device.cpp:980
>> '\_SB_.PCI0.I2C2.CAM0': 0 - (4160x3104)[0x00000023] -> (4160x3104)[NV12]
>> (direct)
>> [0:24:11.415943620] [10635] DEBUG HAL camera_device.cpp:966
>> '\_SB_.PCI0.I2C2.CAM0': 1 - (4160x3104)[0x00000021] -> (4160x3104)[NV12]
>> (mapped)
>> [0:24:11.416461639] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video0[37:cap]: Queueing buffer 3
>> [0:24:11.428903141] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video0[37:cap]: Dequeuing buffer 2
>> [0:24:11.429095316] [10643] DEBUG IPU3Awb awb.cpp:331 Color temperature
>> estimated: 6644
>> [0:24:11.429563781] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:237 frame 193 started
>> [0:24:11.429627478] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:272 Setting Exposure to 269 at index 193
>> [0:24:11.429683048] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video6[25:cap]: Queueing buffer 1
>> [0:24:11.436615191] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video5[27:out]: Queueing buffer 2
>> [0:24:11.436718629] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video8[28:cap]: Queueing buffer 2
>> [0:24:11.436799420] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video4[24:out]: Queueing buffer 2
>> [0:24:11.457388821] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video4[24:out]: Dequeuing buffer 1
>> [0:24:11.457948159] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video6[25:cap]: Dequeuing buffer 0
>> [0:24:11.458257692] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video5[27:out]: Dequeuing buffer 2
>> [0:24:11.458525315] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video8[28:cap]: Dequeuing buffer 1
>> [0:24:11.458968848] [10643] DEBUG IPU3Awb awb.cpp:270 Valid zones: 186
>> [0:24:11.459005634] [10643] DEBUG IPU3Awb awb.cpp:224 Grey world AWB
>> [0:24:11.459082715] [10643] DEBUG IPU3Awb awb.cpp:273 Gain found for
>> red: 1.16864 and for blue: 1.14863
>> [0:24:11.459325998] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Exposure to 269 at index 194
>> [0:24:11.459562485] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Analogue Gain to 477 at index 194
>> [0:24:11.459815347] [10629] DEBUG Request request.cpp:291
>> Request(129:C:0/1:140736750229136)
>> [0:24:11.460390126] [10629] DEBUG HAL camera_device.cpp:1117
>> '\_SB_.PCI0.I2C2.CAM0': Request 140736750229136 completed with 1 streams
>> [0:24:11.461855854] [10635] DEBUG Request request.cpp:94 Created request
>> - cookie: 140736750230064
>> [0:24:11.461939858] [10635] DEBUG HAL camera_device.cpp:941
>> '\_SB_.PCI0.I2C2.CAM0': Queueing request 140736750230064 with 1 streams
>> [0:24:11.462057435] [10635] DEBUG Buffer framebuffer.cpp:249 Buffer is
>> not contiguous
>> [0:24:11.462098906] [10635] DEBUG HAL camera_device.cpp:980
>> '\_SB_.PCI0.I2C2.CAM0': 0 - (4160x3104)[0x00000023] -> (4160x3104)[NV12]
>> (direct)
>> [0:24:11.463164722] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:237 frame 194 started
>> [0:24:11.463730946] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:272 Setting Analogue Gain to 477 at index 193
>> [0:24:11.464033686] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:272 Setting Exposure to 269 at index 194
>> [0:24:11.464329869] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video0[37:cap]: Queueing buffer 0
>> [0:24:11.495739092] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:237 frame 195 started
>> [0:24:11.496489311] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:272 Setting Analogue Gain to 477 at index 194
>> [0:24:11.496737385] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:285 Queue is empty, auto queue no-op.
>> [0:24:11.497044311] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video0[37:cap]: Dequeuing buffer 3
>> [0:24:11.497335155] [10643] DEBUG IPU3Awb awb.cpp:331 Color temperature
>> estimated: 6658
>> [0:24:11.497528845] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video6[25:cap]: Queueing buffer 2
>> [0:24:11.503589322] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video5[27:out]: Queueing buffer 3
>> [0:24:11.504027344] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video8[28:cap]: Queueing buffer 3
>> [0:24:11.504287330] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video4[24:out]: Queueing buffer 3
>> [0:24:11.504712501] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video4[24:out]: Dequeuing buffer 2
>> [0:24:11.505005096] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video6[25:cap]: Dequeuing buffer 1
>> [0:24:11.505260331] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video5[27:out]: Dequeuing buffer 3
>> [0:24:11.505506837] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video8[28:cap]: Dequeuing buffer 2
>> [0:24:11.505940926] [10643] DEBUG IPU3Awb awb.cpp:270 Valid zones: 186
>> [0:24:11.505976974] [10643] DEBUG IPU3Awb awb.cpp:224 Grey world AWB
>> [0:24:11.506057427] [10643] DEBUG IPU3Awb awb.cpp:273 Gain found for
>> red: 1.16797 and for blue: 1.14978
>> [0:24:11.506297848] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Exposure to 269 at index 196
>> [0:24:11.506547021] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Analogue Gain to 477 at index 196
>> [0:24:11.506796456] [10629] DEBUG Request request.cpp:291
>> Request(130:C:0/1:140736750225984)
>> [0:24:11.507374522] [10629] DEBUG HAL camera_device.cpp:1117
>> '\_SB_.PCI0.I2C2.CAM0': Request 140736750225984 completed with 1 streams
>> [0:24:11.509426987] [10635] DEBUG Request request.cpp:94 Created request
>> - cookie: 140736750227664
>> [0:24:11.509507039] [10635] DEBUG HAL camera_device.cpp:941
>> '\_SB_.PCI0.I2C2.CAM0': Queueing request 140736750227664 with 1 streams
>> [0:24:11.509630706] [10635] DEBUG Buffer framebuffer.cpp:249 Buffer is
>> not contiguous
>> [0:24:11.509675200] [10635] DEBUG HAL camera_device.cpp:980
>> '\_SB_.PCI0.I2C2.CAM0': 0 - (4160x3104)[0x00000023] -> (4160x3104)[NV12]
>> (direct)
>> [0:24:11.511309605] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1582
>> /dev/video0[37:cap]: Queueing buffer 1
>> [0:24:11.528984601] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:237 frame 196 started
>> [0:24:11.529446048] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:272 Setting Exposure to 269 at index 196
>> [0:24:11.548431632] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video4[24:out]: Dequeuing buffer 3
>> [0:24:11.548993830] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video6[25:cap]: Dequeuing buffer 2
>> [0:24:11.549320802] [10629] DEBUG V4L2 v4l2_videodevice.cpp:1650
>> /dev/video8[28:cap]: Dequeuing buffer 3
>> [0:24:11.549807736] [10643] DEBUG IPU3Awb awb.cpp:270 Valid zones: 186
>> [0:24:11.549846777] [10643] DEBUG IPU3Awb awb.cpp:224 Grey world AWB
>> [0:24:11.549927350] [10643] DEBUG IPU3Awb awb.cpp:273 Gain found for
>> red: 1.16841 and for blue: 1.14912
>> [0:24:11.550170924] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Exposure to 269 at index 197
>> [0:24:11.550405629] [10629] DEBUG DelayedControls
>> delayed_controls.cpp:179 Queuing Analogue Gain to 477 at index 197
>> [0:24:11.550646460] [10629] DEBUG Request request.cpp:291
>> Request(131:C:0/1:140736750235824)
>> [0:24:11.551245104] [10629] DEBUG HAL camera_device.cpp:1117
>> '\_SB_.PCI0.I2C2.CAM0': Request 140736750235824 completed with 2 streams
>> [0:24:11.562307680] [10629] DEBUG EXIF exif.cpp:522 Created EXIF
>> instance (536 bytes)
>> [0:24:11.634800113] [10629] DEBUG JPEG encoder_libjpeg.cpp:220 JPEG
>> Encode Starting:4160x3104
>>
>> Thread 6 "CameraModuleThr" received signal SIGSEGV, Segmentation fault.
>> [Switching to Thread 0x7fffe7fff640 (LWP 10629)]
>> 0x00007ffff597ead5 in
>> EncoderLibJpeg::compressNV(libcamera::Span<unsigned char const,
>> 18446744073709551615ul>) () from /usr/lib64/camera_hal/libcamera-hal.so
>> (gdb) bt
>> #0  0x00007ffff597ead5 in
>> EncoderLibJpeg::compressNV(libcamera::Span<unsigned char const,
>> 18446744073709551615ul>) () from /usr/lib64/camera_hal/libcamera-hal.so
>> #1  0x00007ffff597eda0 in
>> EncoderLibJpeg::encode(libcamera::Span<unsigned char const,
>> 18446744073709551615ul>, libcamera::Span<unsigned char,
>> 18446744073709551615ul>, libcamera::Span<unsigned char const,
>> 18446744073709551615ul>, unsigned int) () from
>> /usr/lib64/camera_hal/libcamera-hal.so
>> #2  0x00007ffff597ec53 in EncoderLibJpeg::encode(libcamera::FrameBuffer
>> const&, libcamera::Span<unsigned char, 18446744073709551615ul>,
> 18446744073709551615ul is -1, so we've certainly missed
> capturing/preventing an error code from getting assigned to the span at
> some point, where it then got stored as an unsigned long.
>
>
> Does this happen repeatably? or only on some specific event?

It happens repeatably on every run of camera-service when you try to 
capture the frame. The service will segfault on shutter-click and you 
need to re-run it again.

> --
> Kieran