CSI camera driver syncpt timeout error

Hi,

We made a custom camera module based on OV9734 chip, and we wrote the driver for it, based off of the OV5693 driver. The driver passes v4l2-compliance, and we verified the I2C/SCCB communication to be correct, and stuff is going over the CSI pins. It’s a single-CSI-lane camera, 360Mbps lane, we’re using port C, the clock is 24MHz, and the mode is 1280x720@30fps, 10-bit RGGB raw Bayer.

When I try to run it, I get an error:

nvidia@tegra-ubuntu:~$ v4l2-ctl --set-fmt-video=width=1280,height=720,pixelformat=RG10 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=100 -d /dev/video0
VIDIOC_DQBUF: failed: Input/output error

Do you have any ideas what the issue might be? we’re pretty certain the resolution is correct, are there any other timing parameters that we have to tune?

The kernel log looks like this:

[  112.820797] ov9734 2-0036: camera_common_mclk_enable: enable MCLK with 24000000 Hz
[  112.828574] ov9734 2-0036: camera_common_dpd_disable: csi 2
[  112.834331] ov9734 2-0036: ov9734_power_on
[  112.851658] ov9734 2-0036: ov9734_power_on: return 0
[  112.856704] tegra_mipi_cal 3990000.mipical: tegra_mipi_bias_pad_enable
[  112.864821] nvcsi 150c0000.nvcsi: csi port:2
[  112.869211] tegra_mipi_cal 3990000.mipical: tegra_mipi_calibration
[  112.876238] ov9734 2-0036: try: ov9734_set_fmt
[  112.880764] ov9734 2-0036: camera_common_try_fmt: size 1280 x 720
[  112.886943] ov9734 2-0036: ov9734_set_fmt: return 0
[  112.891265] ov9734 2-0036: set: ov9734_set_fmt
[  112.895750] ov9734 2-0036: camera_common_s_fmt(12303) size 1280 x 720
[  112.902282] ov9734 2-0036: camera_common_try_fmt: size 1280 x 720
[  112.908410] ov9734 2-0036: ov9734_set_fmt: return 0
[  112.916941] ov9734 2-0036: ov9734_get_fmt
[  112.920975] ov9734 2-0036: camera_common_g_fmt++
[  112.926370] tegra-vi4 15700000.vi: Create Surface with imgW=1280, imgH=720, memFmt=32
[  112.935128] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=2, lanes=1
[  112.942290] nvcsi 150c0000.nvcsi: csi4_stream_init
[  112.947094] nvcsi 150c0000.nvcsi: csi4_stream_config
[  112.952064] nvcsi 150c0000.nvcsi: csi4_stream_config (2) read VC0_DPCM_CTRL = 00000000
[  112.959976] nvcsi 150c0000.nvcsi: csi4_phy_config
[  112.964684] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
[  112.970434] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
[  112.977064] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
[  112.983504] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
[  112.989855] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
[  112.996733] ov9734 2-0036: ov9734_s_stream
[  113.810681] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0018
[  113.816951] tegra-vi4 15700000.vi:          timestamp sof 123679467232 eof 123709022816 data 0x00400062
[  113.826343] tegra-vi4 15700000.vi:          capture_id 1 stream  2 vchan  0
[  114.780230] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  115.784289] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
[  115.790241] ov9734 2-0036: ov9734_s_stream
[  115.794544] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=1
[  115.801676] nvcsi 150c0000.nvcsi: csi4_phy_config
[  115.806500] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000001
[  115.812327] nvcsi 150c0000.nvcsi: csi4_stream_check_status
[  115.817913] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) ERROR_STATUS2VI_VC0 = 0x00000004
[  115.826711] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) INTR_STATUS 0x00000006
[  115.834582] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) ERR_INTR_STATUS 0x00000006
[  115.842820] nvcsi 150c0000.nvcsi: csi4_cil_check_status 340
[  115.851351] ov9734 2-0036: ov9734_power_off
[  115.856233] ov9734 2-0036: ov9734_power_off: return 0
[  115.861237] ov9734 2-0036: camera_common_dpd_enable: csi 2
[  115.866799] ov9734 2-0036: camera_common_mclk_disable: disable MCLK
[  115.873327] tegra_mipi_cal 3990000.mipical: tegra_mipi_bias_pad_disable

Trace looks like this:

root@tegra-ubuntu:~# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 49/49   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/4:1-151   [004] ...1   112.977053: rtos_queue_peek_from_isr_failed: tstamp:3838266369 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   112.977058: rtcpu_start: tstamp:3838267458
     kworker/4:1-151   [004] ...1   113.080190: rtcpu_vinotify_handle_msg: tstamp:3842241398 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:3842240968 data:0x00400062
     kworker/4:1-151   [004] ...1   113.132194: rtos_queue_peek_from_isr_failed: tstamp:3843267226 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   113.132195: rtcpu_vinotify_handle_msg: tstamp:3843270346 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:3843269924 data:0x00400062
     kworker/4:1-151   [004] ...1   113.132196: rtcpu_vinotify_handle_msg: tstamp:3844299299 tag:CSIMUX_FRAME channel:0x00 frame:3 vi_tstamp:3844298880 data:0x00400062
     kworker/4:1-151   [004] ...1   113.184192: rtcpu_vinotify_handle_msg: tstamp:3845328268 tag:CSIMUX_FRAME channel:0x00 frame:4 vi_tstamp:3845327837 data:0x00400062
     kworker/4:1-151   [004] ...1   113.236193: rtcpu_vinotify_handle_msg: tstamp:3846357209 tag:CSIMUX_FRAME channel:0x00 frame:5 vi_tstamp:3846356793 data:0x00400062
     kworker/4:1-151   [004] ...1   113.236194: rtcpu_vinotify_handle_msg: tstamp:3847386168 tag:CSIMUX_FRAME channel:0x00 frame:6 vi_tstamp:3847385749 data:0x00400062
     kworker/4:1-151   [004] ...1   113.292198: rtos_queue_peek_from_isr_failed: tstamp:3848267734 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   113.292200: rtcpu_vinotify_handle_msg: tstamp:3848415144 tag:CSIMUX_FRAME channel:0x00 frame:7 vi_tstamp:3848414706 data:0x00400062
     kworker/4:1-151   [004] ...1   113.292201: rtcpu_vinotify_handle_msg: tstamp:3849444069 tag:CSIMUX_FRAME channel:0x00 frame:8 vi_tstamp:3849443662 data:0x00400062
     kworker/4:1-151   [004] ...1   113.344193: rtcpu_vinotify_handle_msg: tstamp:3850473038 tag:CSIMUX_FRAME channel:0x00 frame:9 vi_tstamp:3850472619 data:0x00400062
     kworker/4:1-151   [004] ...1   113.396192: rtcpu_vinotify_handle_msg: tstamp:3851501992 tag:CSIMUX_FRAME channel:0x00 frame:10 vi_tstamp:3851501574 data:0x00400062
     kworker/4:1-151   [004] ...1   113.396193: rtcpu_vinotify_handle_msg: tstamp:3852530948 tag:CSIMUX_FRAME channel:0x00 frame:11 vi_tstamp:3852530531 data:0x00400062
     kworker/4:1-151   [004] ...1   113.448194: rtos_queue_peek_from_isr_failed: tstamp:3853268239 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   113.448196: rtcpu_vinotify_handle_msg: tstamp:3853559905 tag:CSIMUX_FRAME channel:0x00 frame:12 vi_tstamp:3853559487 data:0x00400062
     kworker/4:1-151   [004] ...1   113.500191: rtcpu_vinotify_handle_msg: tstamp:3854588860 tag:CSIMUX_FRAME channel:0x00 frame:13 vi_tstamp:3854588443 data:0x00400062
     kworker/4:1-151   [004] ...1   113.500192: rtcpu_vinotify_handle_msg: tstamp:3855617815 tag:CSIMUX_FRAME channel:0x00 frame:14 vi_tstamp:3855617399 data:0x00400062
     kworker/4:1-151   [004] ...1   113.552197: rtcpu_vinotify_handle_msg: tstamp:3856646772 tag:CSIMUX_FRAME channel:0x00 frame:15 vi_tstamp:3856646356 data:0x00400062
     kworker/4:1-151   [004] ...1   113.552198: rtcpu_vinotify_handle_msg: tstamp:3857675728 tag:CSIMUX_FRAME channel:0x00 frame:16 vi_tstamp:3857675312 data:0x00400062
     kworker/4:1-151   [004] ...1   113.604196: rtos_queue_peek_from_isr_failed: tstamp:3858268748 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   113.604197: rtcpu_vinotify_handle_msg: tstamp:3858704686 tag:CSIMUX_FRAME channel:0x00 frame:17 vi_tstamp:3858704268 data:0x00400062
     kworker/4:1-151   [004] ...1   113.656195: rtcpu_vinotify_handle_msg: tstamp:3859733641 tag:CSIMUX_FRAME channel:0x00 frame:18 vi_tstamp:3859733224 data:0x00400062
     kworker/4:1-151   [004] ...1   113.656196: rtcpu_vinotify_handle_msg: tstamp:3860762598 tag:CSIMUX_FRAME channel:0x00 frame:19 vi_tstamp:3860762181 data:0x00400062
     kworker/4:1-151   [004] ...1   113.708192: rtcpu_vinotify_handle_msg: tstamp:3861791554 tag:CSIMUX_FRAME channel:0x00 frame:20 vi_tstamp:3861791137 data:0x00400062
     kworker/4:1-151   [004] ...1   113.760198: rtcpu_vinotify_handle_msg: tstamp:3862820515 tag:CSIMUX_FRAME channel:0x00 frame:21 vi_tstamp:3862820093 data:0x00400062
     kworker/4:1-151   [004] ...1   113.760199: rtos_queue_peek_from_isr_failed: tstamp:3863269256 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   113.760200: rtcpu_vinotify_handle_msg: tstamp:3863849469 tag:CSIMUX_FRAME channel:0x00 frame:22 vi_tstamp:3863849050 data:0x00400062
     kworker/4:1-151   [004] ...1   113.808206: rtcpu_vinotify_handle_msg: tstamp:3864878425 tag:CSIMUX_FRAME channel:0x00 frame:23 vi_tstamp:3864878006 data:0x00400062
     kworker/4:1-151   [004] ...1   113.808208: rtcpu_vinotify_handle_msg: tstamp:3864983900 tag:CHANSEL_PXL_SOF channel:0x00 frame:24 vi_tstamp:3864983351 data:0x00000001
     kworker/4:1-151   [004] ...1   113.808209: rtcpu_vinotify_handle_msg: tstamp:3864984046 tag:ATOMP_FS channel:0x00 frame:24 vi_tstamp:3864983371 data:0x00000000
     kworker/4:1-151   [004] ...1   113.808210: rtcpu_vinotify_handle_msg: tstamp:3864986286 tag:CHANSEL_LOAD_FRAMED channel:0x04 frame:24 vi_tstamp:3864985864 data:0x08000000
     kworker/4:1-151   [004] ...1   113.860213: rtcpu_vinotify_handle_msg: tstamp:3865907637 tag:CHANSEL_PXL_EOF channel:0x00 frame:24 vi_tstamp:3865906920 data:0x02cf0002
     kworker/4:1-151   [004] ...1   113.860217: rtcpu_vinotify_handle_msg: tstamp:3865907740 tag:CSIMUX_FRAME channel:0x00 frame:24 vi_tstamp:3865906963 data:0x00400062
     kworker/4:1-151   [004] ...1   113.860218: rtcpu_vinotify_handle_msg: tstamp:3865907925 tag:ATOMP_FE channel:0x00 frame:24 vi_tstamp:3865906966 data:0x00000000
     kworker/4:1-151   [004] ...1   113.912212: rtos_queue_peek_from_isr_failed: tstamp:3868269781 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.068207: rtos_queue_peek_from_isr_failed: tstamp:3873270289 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.224208: rtos_queue_peek_from_isr_failed: tstamp:3878270791 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.380207: rtos_queue_peek_from_isr_failed: tstamp:3883271299 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.536208: rtos_queue_peek_from_isr_failed: tstamp:3888271804 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.692209: rtos_queue_peek_from_isr_failed: tstamp:3893272313 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   114.848251: rtos_queue_peek_from_isr_failed: tstamp:3898272821 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.056247: rtos_queue_peek_from_isr_failed: tstamp:3903273325 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.212245: rtos_queue_peek_from_isr_failed: tstamp:3908273829 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.368244: rtos_queue_peek_from_isr_failed: tstamp:3913274339 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.524245: rtos_queue_peek_from_isr_failed: tstamp:3918274848 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.680246: rtos_queue_peek_from_isr_failed: tstamp:3923275352 queue:0x0b4a3c58
     kworker/4:1-151   [004] ...1   115.844216: rtos_queue_peek_from_isr_failed: tstamp:3927767492 queue:0x0b4a3c58

Our camera DTSI looks like this:

/ {
	host1x {
		vi@15700000 {
			num-channels = <1>;
			ports {
				#address-cells = <1>;
				#size-cells = <0>;
				port@0 {
					reg = <0>;
					focure_cb7_vi_in0: endpoint {
						csi-port = <2>;
						bus-width = <1>;
						remote-endpoint = <&focure_cb7_csi_out0>;
					};
				};
			};
		};

		nvcsi@150c0000 {
			num-channels = <1>;
			#address-cells = <1>;
			#size-cells = <0>;
			channel@0 {
				reg = <0>;
				ports {
					#address-cells = <1>;
					#size-cells = <0>;
					port@0 {
						reg = <0>;
						focure_cb7_csi_in0: endpoint@0 {
							csi-port = <2>;
							bus-width = <1>;
							remote-endpoint = <&focure_cb7_ov9734_out0>;
						};
					};
					port@1 {
						reg = <1>;
						focure_cb7_csi_out0: endpoint@1 {
							remote-endpoint = <&focure_cb7_vi_in0>;
						};
					};
				};
			};
		};
	};

	i2c@3180000 {
		ov9734_c@36 {
			compatible = "nvidia,ov9734";
			/* I2C device address */
			reg = <0x36>;

			/* V4L2 device node location */
			devnode = "video0";

			/* Physical dimensions of sensor */
			physical_w = "3.674";
			physical_h = "2.738";

			/* Define any required hw resources needed by driver */
			/* ie. clocks, io pins, power sources */
			avdd-reg = "vana";
			dvdd-reg = "vdig";
			iovdd-reg = "vif";

			/* Sensor output flip settings */
			vertical-flip = "true";

			/**
			* A modeX node is required to support v4l2 driver
			* implementation with NVIDIA camera software stack
			*
			* mclk_khz = "";
			* Standard MIPI driving clock, typically 24MHz
			*
			* num_lanes = "";
			* Number of lane channels sensor is programmed to output
			*
			* tegra_sinterface = "";
			* The base tegra serial interface lanes are connected to
			*
			* discontinuous_clk = "";
			* The sensor is programmed to use a discontinuous clock on MIPI lanes
			*
			* dpcm_enable = "true";
			* The sensor is programmed to use a DPCM modes
			*
			* cil_settletime = "";
			* MIPI lane settle time value.
			* A "0" value attempts to autocalibrate based on mclk_multiplier
			*
			*
			*
			*
			* active_w = "";
			* Pixel active region width
			*
			* active_h = "";
			* Pixel active region height
			*
			* pixel_t = "";
			* The sensor readout pixel pattern
			*
			* readout_orientation = "0";
			* Based on camera module orientation.
			* Only change readout_orientation if you specifically
			* Program a different readout order for this mode
			*
			* line_length = "";
			* Pixel line length (width) for sensor mode.
			* This is used to calibrate features in our camera stack.
			*
			* mclk_multiplier = "";
			* Multiplier to MCLK to help time hardware capture sequence
			* TODO: Assign to PLL_Multiplier as well until fixed in core
			*
			* pix_clk_hz = "";
			* Sensor pixel clock used for calculations like exposure and framerate
			*
			*
			*
			*
			* inherent_gain = "";
			* Gain obtained inherently from mode (ie. pixel binning)
			*
			* min_gain_val = ""; (floor to 6 decimal places)
			* max_gain_val = ""; (floor to 6 decimal places)
			* Gain limits for mode
			*
			* min_exp_time = ""; (ceil to integer)
			* max_exp_time = ""; (ceil to integer)
			* Exposure Time limits for mode (us)
			*
			*
			* min_hdr_ratio = "";
			* max_hdr_ratio = "";
			* HDR Ratio limits for mode
			*
			* min_framerate = "";
			* max_framerate = "";
			* Framerate limits for mode (fps)
			*/
			mode0 { // OV9734_MODE_1280X720
				mclk_khz = "24000";
				num_lanes = "1";
				tegra_sinterface = "serial_c";
				discontinuous_clk = "no";
				dpcm_enable = "false";
				cil_settletime = "0";

				active_w = "1280";
				active_h = "720";
				pixel_t = "bayer_bggr10";
				readout_orientation = "0";
				line_length = "1478";
				inherent_gain = "1";
				mclk_multiplier = "6.67";
				pix_clk_hz = "160000000";

				min_gain_val = "1.0";
				max_gain_val = "16";
				min_hdr_ratio = "1";
				max_hdr_ratio = "64";
				min_framerate = "1.816577";
				max_framerate = "30";
				min_exp_time = "34";
				max_exp_time = "550385";
			};

			ports {
				#address-cells = <1>;
				#size-cells = <0>;

				port@0 {
					reg = <0>;
					focure_cb7_ov9734_out0: endpoint {
						csi-port = <2>;
						bus-width = <1>;
						remote-endpoint = <&focure_cb7_csi_in0>;
					};
				};
			};
		};
	};

	focure_cb7_lens_ov9734@OV9734 {
		min_focus_distance = "0.0";
		hyper_focal = "0.0";
		focal_length = "2.67";
		f_number = "2.0";
		aperture = "2.0";
	};

	tegra-camera-platform {
		compatible = "nvidia, tegra-camera-platform";
		/**
		* Physical settings to calculate max ISO BW
		*
		* num_csi_lanes = <>;
		* Total number of CSI lanes when all cameras are active
		*
		* max_lane_speed = <>;
		* Max lane speed in Kbit/s
		*
		* min_bits_per_pixel = <>;
		* Min bits per pixel
		*
		* vi_peak_byte_per_pixel = <>;
		* Max byte per pixel for the VI ISO case
		*
		* vi_bw_margin_pct = <>;
		* Vi bandwidth margin in percentage
		*
		* max_pixel_rate = <>;
		* Max pixel rate in Kpixel/s for the ISP ISO case
		*
		* isp_peak_byte_per_pixel = <>;
		* Max byte per pixel for the ISP ISO case
		*
		* isp_bw_margin_pct = <>;
		* Isp bandwidth margin in percentage
		*/
		num_csi_lanes = <1>;
		max_lane_speed = <1500000>;
		min_bits_per_pixel = <10>;
		vi_peak_byte_per_pixel = <2>;
		vi_bw_margin_pct = <25>;
		max_pixel_rate = <160000>;
		isp_peak_byte_per_pixel = <5>;
		isp_bw_margin_pct = <25>;

		/**
		* The general guideline for naming badge_info contains 3 parts, and is as follows,
		* The first part is the camera_board_id for the module; if the module is in a FFD
		* platform, then use the platform name for this part.
		* The second part contains the position of the module, ex. “rear” or “front”.
		* The third part contains the last 6 characters of a part number which is found
		* in the module's specsheet from the vender.
		*/
		modules {
			module0 {
				badge = "focure_cb7_front_OV9734";
				position = "rear";
				orientation = "1";
				drivernode0 {
					/* Declare PCL support driver (classically known as guid)  */
					pcl_id = "v4l2_sensor";
					/* Driver v4l2 device name */
					devname = "ov9734 2-0036";
					/* Declare the device-tree hierarchy to driver instance */
					proc-device-tree = "/proc/device-tree/i2c@3180000/ov9734_c@36";
				};
				drivernode1 {
					/* Declare PCL support driver (classically known as guid)  */
					pcl_id = "v4l2_lens";
					proc-device-tree = "/proc/device-tree/focure_cb7_lens_ov9734@OV9734/";
				};
			};
		};
	};
};

And the Quill-specific part:

// Quill-specific camera module definitions.

#include <t18x-common-modules/tegra186-camera-focure-CameraBreakout-r7.dtsi>
#include "dt-bindings/clock/tegra186-clock.h"

#define CAM0_PWDN TEGRA_MAIN_GPIO(R, 0)
/*
#define CAM0_RST_L  TEGRA_MAIN_GPIO(R, 5)
#define CAM1_RST_L  TEGRA_MAIN_GPIO(R, 1)
#define CAM1_PWDN TEGRA_MAIN_GPIO(L, 6)
*/

/* camera control gpio definitions */

/ {
  i2c@3180000 {
    ov9734_c@36 {
      /* Define any required hw resources needed by driver */
      /* ie. clocks, io pins, power sources */
      /* mclk-index indicates the index of the */
      /* mclk-name with in the clock-names array */

      clocks = <&tegra_car TEGRA186_CLK_EXTPERIPH1>,
           <&tegra_car TEGRA186_CLK_PLLP_OUT0>;
      clock-names = "extperiph1", "pllp_grtba";
      mclk = "extperiph1";
      clock-frequency = <24000000>;
      pwdn-gpios = <&tegra_main_gpio CAM0_PWDN GPIO_ACTIVE_HIGH>;
      vana-supply = <&en_vdd_cam_hv_2v8>;
      vdig-supply = <&en_vdd_cam_1v2>;
      vif-supply = <&en_vdd_cam>;
    };
  };

  gpio@2200000 {
    camera-control-output-low {
      gpio-hog;
      output-low;
      gpios = <CAM0_PWDN 0>;
      label = "cam0-pwdn";
    };
  };
};

I’ve also verified that it looks the same on the live system by running:

nvidia@tegra-ubuntu:~$ dtc -I fs -O dts -o current.dts /proc/device-tree

Thank you,
Neb

…also, increasing cil_settletime to 40 results in a bit different failure:

nvidia@tegra-ubuntu:~$ v4l2-ctl --set-fmt-video=width=1280,height=720,pixelformat=RG10 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=100 -d /dev/video0 --stream-to=t.raw
<< 1.00 fps
< 1.00 fps
< 1.00 fps

The file t.raw is actually generated this time. The trace is full of these:

kworker/3:1-104   [003] ...1   191.415184: rtcpu_start: tstamp:6291470886
     kworker/3:1-104   [003] ...1   191.571185: rtos_queue_peek_from_isr_failed: tstamp:6296471011 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   191.727188: rtos_queue_peek_from_isr_failed: tstamp:6301471517 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   191.935259: rtos_queue_peek_from_isr_failed: tstamp:6306472037 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.091224: rtos_queue_peek_from_isr_failed: tstamp:6311472544 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.247226: rtos_queue_peek_from_isr_failed: tstamp:6316473054 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.403222: rtos_queue_peek_from_isr_failed: tstamp:6321473558 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.559227: rtos_queue_peek_from_isr_failed: tstamp:6326474066 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.715222: rtos_queue_peek_from_isr_failed: tstamp:6331474570 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   192.871223: rtos_queue_peek_from_isr_failed: tstamp:6336475079 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   193.027256: rtos_queue_peek_from_isr_failed: tstamp:6341475588 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   193.183223: rtos_queue_peek_from_isr_failed: tstamp:6346476092 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   193.339222: rtos_queue_peek_from_isr_failed: tstamp:6351476600 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   193.495237: rtos_queue_peek_from_isr_failed: tstamp:6356477106 queue:0x0b4a3c58
     kworker/3:1-104   [003] ...1   193.651224: rtos_queue_peek_from_isr_failed: tstamp:6361477643 queue:0x0b4a3c58

And the log:

[  191.405156] tegra-vi4 15700000.vi: Create Surface with imgW=1280, imgH=720, memFmt=32
[  191.413623] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=2, lanes=1
[  191.420756] nvcsi 150c0000.nvcsi: csi4_stream_init
[  191.425558] nvcsi 150c0000.nvcsi: csi4_stream_config
[  191.430528] nvcsi 150c0000.nvcsi: csi4_stream_config (2) read VC0_DPCM_CTRL = 00000000
[  191.438443] nvcsi 150c0000.nvcsi: csi4_phy_config
[  191.443149] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
[  191.448898] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
[  191.455508] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
[  191.461948] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 40
[  191.468821] ov9734 2-0036: ov9734_s_stream
[  192.471286] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  193.475256] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  194.479251] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  195.483260] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  196.487258] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  197.491257] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  198.495255] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
[  198.501262] ov9734 2-0036: ov9734_s_stream
[  198.505556] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=1
[  198.512684] nvcsi 150c0000.nvcsi: csi4_phy_config
[  198.517471] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000001
[  198.523308] nvcsi 150c0000.nvcsi: csi4_stream_check_status
[  198.528879] nvcsi 150c0000.nvcsi: csi4_cil_check_status 340
[  198.547613] ov9734 2-0036: ov9734_power_off
[  198.552412] ov9734 2-0036: ov9734_power_off: result 0
[  198.557548] ov9734 2-0036: camera_common_dpd_enable: csi 2
[  198.563112] ov9734 2-0036: camera_common_mclk_disable: disable MCLK
[  198.569642] tegra_mipi_cal 3990000.mipical: tegra_mipi_bias_pad_disable

What is cil_settle_time? I have the datasheet for the sensor, there’s no mention of CIL, but there are tons of cryptic configurables such as HS_ZERO_MIN, HS_TRAIL_MIN, CLK_ZERO_MIN, CLK_PREPARE_MIN, CLK_PREPARE_MAX, CLK_POST_MIN, CLK_TRAIL_MIN, LPX_P_MIN, HS_PREPARE_MIN, HS_EXIT_MIN… and the unit is nanoseconds.

From your first log show only the 24s frame are get normally. Get a good frame should be like this. After you increase the settle time it get worse. You may try the #define T18X_BYPASS_LP_SEQ to configure the continuous/noncontinuous clock mode to try. Also the settle is from MIPI spec you may need Vendor’s help to change the sensor timing if the root cause is the sensor output not as MIPI spec.

kworker/4:1-151   [004] ...1   113.808208: rtcpu_vinotify_handle_msg: tstamp:3864983900 tag:CHANSEL_PXL_SOF channel:0x00 frame:24 vi_tstamp:3864983351 data:0x00000001
     kworker/4:1-151   [004] ...1   113.808209: rtcpu_vinotify_handle_msg: tstamp:3864984046 tag:ATOMP_FS channel:0x00 frame:24 vi_tstamp:3864983371 data:0x00000000
     kworker/4:1-151   [004] ...1   113.808210: rtcpu_vinotify_handle_msg: tstamp:3864986286 tag:CHANSEL_LOAD_FRAMED channel:0x04 frame:24 vi_tstamp:3864985864 data:0x08000000
     kworker/4:1-151   [004] ...1   113.860213: rtcpu_vinotify_handle_msg: tstamp:3865907637 tag:CHANSEL_PXL_EOF channel:0x00 frame:24 vi_tstamp:3865906920 data:0x02cf0002
     kworker/4:1-151   [004] ...1   113.860217: rtcpu_vinotify_handle_msg: tstamp:3865907740 tag:CSIMUX_FRAME channel:0x00 frame:24 vi_tstamp:3865906963 data:0x00400062
     kworker/4:1-151   [004] ...1   113.860218: rtcpu_vinotify_handle_msg: tstamp:3865907925 tag:ATOMP_FE channel:0x00 frame:24 vi_tstamp:3865906966 data:0x00000000

Thank you for your help!

For my current phase, getting just one frame would be enough. However, I cannot get even a single frame out. I tried:

v4l2-ctl --set-fmt-video=width=1280,height=720,pixelformat=RG10 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=1

I also tried gstreamer, using a 10-bit-bayer modified v4l2src:

gst-launch-1.0 -vvv v4l2src num-buffers=1 ! 'video/x-bayer, width=(int)1280, height=(int)720, format=(string)rggb, framerate=(fraction)30/1' ! multifilesink location=test%d.raw

…but I get the same error:

[  558.148661] tegra-vi4 15700000.vi: Create Surface with imgW=1280, imgH=720, memFmt=32
[  558.157119] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=2, lanes=1
[  558.164256] nvcsi 150c0000.nvcsi: csi4_stream_init
[  558.169055] nvcsi 150c0000.nvcsi: csi4_stream_config
[  558.174025] nvcsi 150c0000.nvcsi: csi4_stream_config (2) read VC0_DPCM_CTRL = 00000000
[  558.181937] nvcsi 150c0000.nvcsi: csi4_phy_config
[  558.186643] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
[  558.192397] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
[  558.199020] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
[  558.205461] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
[  558.211812] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
[  558.218688] ov9734 2-0036: ov9734_s_stream
[  558.275315] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0001
[  558.281586] tegra-vi4 15700000.vi:          timestamp sof 568187330272 eof 568216885792 data 0x00400062
[  558.290996] tegra-vi4 15700000.vi:          capture_id 1 stream  2 vchan  0
[  559.245623] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  560.249635] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
[  560.255725] ov9734 2-0036: ov9734_s_stream
[  560.260024] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=1
[  560.267159] nvcsi 150c0000.nvcsi: csi4_phy_config
[  560.271978] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000001
[  560.277807] nvcsi 150c0000.nvcsi: csi4_stream_check_status
[  560.283395] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) ERROR_STATUS2VI_VC0 = 0x00000004
[  560.292187] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) INTR_STATUS 0x00000004
[  560.300056] nvcsi 150c0000.nvcsi: csi4_stream_check_status (2) ERR_INTR_STATUS 0x00000004
[  560.308258] nvcsi 150c0000.nvcsi: csi4_cil_check_status 340

I’ve never again managed to see frame 24 in the logs, it always fails on the first one, which is confusing.

From the trace, I don’t see what’s the problem:

kworker/3:2-272   [003] ...1   184.160563: rtos_queue_peek_from_isr_failed: tstamp:6064880501 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   184.160570: rtcpu_start: tstamp:6064881601
     kworker/3:2-272   [003] ...1   184.264548: rtcpu_vinotify_handle_msg: tstamp:6067938587 tag:CHANSEL_PXL_SOF channel:0x00 frame:1 vi_tstamp:1772970728 data:0x00000001
     kworker/3:2-272   [003] ...1   184.264550: rtcpu_vinotify_handle_msg: tstamp:6067938744 tag:ATOMP_FS channel:0x00 frame:1 vi_tstamp:1772970748 data:0x00000000
     kworker/3:2-272   [003] ...1   184.264551: rtcpu_vinotify_handle_msg: tstamp:6067940842 tag:CHANSEL_LOAD_FRAMED channel:0x04 frame:1 vi_tstamp:1772973122 data:0x08000000
     kworker/3:2-272   [003] ...1   184.264553: rtcpu_vinotify_handle_msg: tstamp:6068862309 tag:CHANSEL_PXL_EOF channel:0x00 frame:1 vi_tstamp:1773894296 data:0x02cf0002
     kworker/3:2-272   [003] ...1   184.264554: rtcpu_vinotify_handle_msg: tstamp:6068862413 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:1773894339 data:0x00400062
     kworker/3:2-272   [003] ...1   184.264555: rtcpu_vinotify_handle_msg: tstamp:6068862600 tag:ATOMP_FE channel:0x00 frame:1 vi_tstamp:1773894342 data:0x00000000
     kworker/3:2-272   [003] ...1   184.316568: rtos_queue_peek_from_isr_failed: tstamp:6069881361 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   184.472561: rtos_queue_peek_from_isr_failed: tstamp:6074881865 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   184.628595: rtos_queue_peek_from_isr_failed: tstamp:6079882371 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   184.784593: rtos_queue_peek_from_isr_failed: tstamp:6084882875 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   184.940593: rtos_queue_peek_from_isr_failed: tstamp:6089883385 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.096592: rtos_queue_peek_from_isr_failed: tstamp:6094883898 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.252598: rtos_queue_peek_from_isr_failed: tstamp:6099884398 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.460591: rtos_queue_peek_from_isr_failed: tstamp:6104884906 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.616594: rtos_queue_peek_from_isr_failed: tstamp:6109885411 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.772592: rtos_queue_peek_from_isr_failed: tstamp:6114885920 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   185.928593: rtos_queue_peek_from_isr_failed: tstamp:6119886424 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   186.084593: rtos_queue_peek_from_isr_failed: tstamp:6124886932 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   186.248599: rtos_queue_peek_from_isr_failed: tstamp:6129887437 queue:0x0b4a3c58
     kworker/3:2-272   [003] ...1   186.248606: rtos_queue_peek_from_isr_failed: tstamp:6130631998 queue:0x0b4a3c58

My questions:

  1. What's the rtos_queue_peek_from_isr_failed? It looks like it happens all the time.
  2. What is the vi_tstamp field in the trace? It seems to me that no matter what size I set in the DTB, the timestamps are always exactly 923,568 apart, which is 1280*720 + 1968. Can I use this to determine the timing?
  3. Similarly, in the kernel message, what are the timestamp sof/timestamp eof fields?
  4. What is the meaning of the data field in the trace? In particular, for the CHANSEL_PXL_EOF message.

Thank you so much!

Hi,

I think that the pixel parser available in the TX1 is only for two lanes (up to 6 two MIPI CSI lanes cameras) or you can use two of them together to support 4 MIPI CSI lanes cameras (up to 3). I think it is not possible to use cameras with one single lane. Have you verified this with NVIDIA?

Hi David,

Just wanted to copy our email discussion here:

We’re using TX2. Reading the SoC docs, TX1 is ambiguous on the issue, but TX2 (Parker) docs say explicitly:

28.1.1.1

NVCSI provides a combination host that supports both the D-PHY v1.2 and the C-PHY v1.0 physical layer option, with three 4- lane, six 2-lane, or 6 1-lane configurations. Each lane can support up to four VCs and supports data type interleaving.

28.3.2

The NVCSI SCIL (also known as “SCIL” or “super CIL”) module controls the individual lanes of a NVCSI combo brick (or “brick”). It aggregates data from individual lanes while supporting the following brick configuration modes:
• D-PHY: 1x 4 lanes, 2x 2 lanes, 2x 1 lane, 1x 1 lane, 1x 2 lanes, 1x 1 lane + 1x 2 lanes
• C-PHY: 1x 4 trios, 1x 3 trios + 1x 1 trio, 2x 2 trios, 2x 1 trio, 1x 1 trio, 1x 3 trios, 1x 1 trio + 1x 2 trios

I’ve seen in the forums (https://devtalk.nvidia.com/default/topic/1027450/jetson-tx2-single-lane-mipi-camera/) that OV5693 driver supports one-lane configuration.

Our best guess is that no one tested an one-lane camera, and that we’ve hit a bug. The trace shows that SOF/EOF is received without errors, but for some reason or another the EOF sync point is not hit even though EOF is emitted.

Hi nsabovic,

Thanks for the information, nice upgrade on the TX2 capture subsystem, I know the limitation was in TX1. We have normally seen those problems when the color space expected by VI according to the configuration is not the same that the camera is putting on the Jetson inputs. I would recommend you to double check this.

-David

I see ERROR_STATUS2VI_VC0 is 0x04, which the manual says is a CRC packet error. I’m going to find a 6GHz scope and double check signal integrity, but just to check—is there any software mismatch that can produce this?

David, thanks for the hint. I tried playing with the colorspace, V4L2_COLORSPACE_RAW vs. V4L2_COLORSPACE_SRGB, but it seems to make no difference, and I haven’t seen any part of the code where this field is used.

About the pixel format, I also tried getting the sensor to RAW8 mode (and updating the driver & the dts), but the result is the same. I was concerned that throughout Tegra code V4L2_PIX_FMT_SRGGB10 [1] is used to mean 10-bit raw Bayer, but V4L2 docs say that this is 10-bit in 16-bit, zero-padded encoding, which TX2 doesn’t even support. V4L2_PIX_FMT_SRGGB10P [2] (notice P at the end) is what I believe OV sensors send, where 4 samples are packed into 5 bytes.

[1] https://www.kernel.org/doc/html/v4.11/media/uapi/v4l/pixfmt-srggb10.html
[2] https://www.kernel.org/doc/html/v4.11/media/uapi/v4l/pixfmt-srggb10p.html