Adding second camera to TX2 p3310

Henry.Lou · September 1, 2022, 9:15am

1 BSP environment:
TX2 jetpack 4.6 L4T R32.6.1 kernel 4.9 aarch64
TX2 p3310 custom board
2 background & operation:
We have ported one camera sensor on TX2 (please refer to this topic).
Now, our project need two cameras work simultaneously.
We referred to tegra186-camera-imx390-a00.dtsi, and modified DT to add second sensor.
The sensor driver probed successfully, nvcsi and vi bound.
i2c bus works well, which means that we can read and write both of two camera registers by i2c tools.
3 problems:
when run the command “v4l2-ctl --stream-mmap -d /dev/video1”, signals can be cought on the two data lanes and one clock lane by oscilloscope, but no frame cought on by v4l2.
we use i2c tools to read status register, it turns out 0x01, which means the sensor is streaming.
dmesg shows “PXL_SOF syncpt timeout! err = -11”, “ERROR_STATUS2VI_VC0”, “ERROR_STATUS2VI_VC2”.
We referred to this topic and merged the patch, but no help.

FYI
dmesg log

[    6.574527] tegra-vi4 15700000.vi: subdev 150c0000.nvcsi--2 bound
[    6.574539] tegra-vi4 15700000.vi: subdev ov9281 2-0060 bound
[    6.575142] tegra-vi4 15700000.vi: subdev 150c0000.nvcsi--1 bound
[    6.575147] tegra-vi4 15700000.vi: subdev ov9281 2-0010 bound
...
[13236.023697] ov9281 2-0010: ov9281_power_on: power on
[13236.034271] ov9281 2-0010: Using default I2C address 0x10
[13236.061974] ov9281 2-0010: ov9281_s_stream: write mode table 0
[13236.084541] ov9281 2-0010: ov9281_s_stream: write fsync table 2
[13236.159528] ov9281 2-0010: ov9281_s_stream: write fsync slave mode table 0
[13236.167190] ov9281 2-0010: ov9281_s_stream: stream on
[13236.386040] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[13236.392583] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[13236.403217] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC0 = 0x00000002
[13236.412068] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC2 = 0x00000006
[13236.420970] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) INTR_STATUS 0x00010602
[13236.428936] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERR_INTR_STATUS 0x00010602
[13236.437324] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x0000000a
[13236.445458] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x0000000a
[13236.658038] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[13236.664779] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[13236.675369] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC0 = 0x00000002
[13236.684261] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC2 = 0x00000006
[13236.693153] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) INTR_STATUS 0x00010602
[13236.701056] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERR_INTR_STATUS 0x00010602
[13236.709276] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x0400001e
[13236.717369] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x0400001e
[13236.930105] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[13236.936684] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[13236.947346] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC0 = 0x00000002
[13236.956236] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC2 = 0x00000006
[13236.965134] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) INTR_STATUS 0x00010002
[13236.973046] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERR_INTR_STATUS 0x00010002
[13236.981280] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x0400001e
[13236.989478] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x0400001e

trace log

        v4l2-ctl-8911  [000] ....   666.960249: tegra_channel_open: vi-output, ov9281 2-0010
        v4l2-ctl-8911  [000] ....   666.964166: tegra_channel_set_power: ov9281 2-0010 : 0x1
        v4l2-ctl-8911  [000] ....   666.964188: camera_common_s_power: status : 0x1
        v4l2-ctl-8911  [000] ....   666.974801: tegra_channel_set_power: 150c0000.nvcsi--1 : 0x1
        v4l2-ctl-8911  [000] ....   666.974990: csi_s_power: enable : 0x1
        v4l2-ctl-8911  [004] ....   666.988143: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [005] ....   666.988534: tegra_channel_set_stream: enable : 0x1
     kworker/4:2-1151  [004] ....   666.994941: rtcpu_start: tstamp:20992855716
 vi-output, ov92-8912  [000] ....   667.010013: tegra_channel_set_stream: 150c0000.nvcsi--1 : 0x1
 vi-output, ov92-8912  [000] ....   667.010018: csi_s_stream: enable : 0x1
 vi-output, ov92-8912  [000] ....   667.010050: tegra_channel_set_stream: ov9281 2-0010 : 0x1
     kworker/4:2-1151  [004] ....   667.162997: rtcpu_vinotify_event: tstamp:20997134969 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:20997134538 data:0x00000010
 vi-output, ov92-8912  [005] ....   667.399087: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [005] ....   667.399128: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   667.442951: rtcpu_vinotify_event: tstamp:21005790052 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21005787878 data:0x00000010
 vi-output, ov92-8912  [005] .n..   667.670075: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [005] ....   667.670143: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   667.722966: rtcpu_vinotify_event: tstamp:21014346095 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21014345668 data:0x00000010
 vi-output, ov92-8912  [000] ....   667.939222: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   667.939263: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   667.950926: rtcpu_vinotify_event: tstamp:21022690875 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21022690459 data:0x00000010
 vi-output, ov92-8912  [000] ....   668.210170: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   668.210201: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   668.230993: rtcpu_vinotify_event: tstamp:21031136266 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21031135351 data:0x00000010
 vi-output, ov92-8912  [000] ....   668.479497: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   668.479540: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   668.511003: rtcpu_vinotify_event: tstamp:21039641238 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21039640814 data:0x00000010
 vi-output, ov92-8912  [000] ....   668.751132: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   668.751170: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   668.795008: rtcpu_vinotify_event: tstamp:21048040736 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21048038784 data:0x00000010
 vi-output, ov92-8912  [000] ....   669.022129: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   669.022158: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   669.074892: rtcpu_vinotify_event: tstamp:21056592734 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21056592307 data:0x00000010
 vi-output, ov92-8912  [000] ....   669.291096: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   669.291137: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   669.298897: rtcpu_vinotify_event: tstamp:21064936941 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21064936529 data:0x00000010
 vi-output, ov92-8912  [000] ....   669.565487: tegra_channel_capture_setup: vnc_id 0 W 640 H 400 fmt 10
 vi-output, ov92-8912  [000] ....   669.565563: tegra_channel_capture_frame: sof:-549619126124.-268665623808
     kworker/4:2-1151  [004] ....   669.579102: rtcpu_vinotify_event: tstamp:21073543557 tag:CSIMUX_STREAM channel:0xff frame:8 vi_tstamp:21073542947 data:0x00000010

Regards
Henry

ShaneCCC · September 1, 2022, 11:00am

The CSIMUX_STREAM tell CSI receive some other package instead of FS at the begining.

Henry.Lou · September 1, 2022, 11:16am

Hi @ShaneCCC
Do you mean that the frame sent by sensor is not right?

There is one more thing consulsed us: dmesg shows nvcsi-2 bounded ov9281 2-0060, nvcsi-1 bounded ov9281 2-0010. But it does not match the following v4l2-compliance result.
Is the bound topology right?

Regards
FYI
v4l2-compliance log

t@t-desktop:~$ v4l2-compliance -d /dev/video0
v4l2-compliance SHA   : not available

Driver Info:
	Driver name   : tegra-video
	Card type     : vi-output, ov9281 2-0060
	Bus info      : platform:15700000.vi:0
	Driver version: 4.9.253
	Capabilities  : 0x84200001
		Video Capture
		Streaming
		Extended Pix Format
		Device Capabilities
	Device Caps   : 0x04200001
		Video Capture
		Streaming
		Extended Pix Format
...
t@t-desktop:~$ v4l2-compliance -d /dev/video1
v4l2-compliance SHA   : not available

Driver Info:
	Driver name   : tegra-video
	Card type     : vi-output, ov9281 2-0010
	Bus info      : platform:15700000.vi:1
	Driver version: 4.9.253
	Capabilities  : 0x84200001
		Video Capture
		Streaming
		Extended Pix Format
		Device Capabilities
	Device Caps   : 0x04200001
		Video Capture
		Streaming
		Extended Pix Format

t@t-desktop:~$ media-ctl -p -d /dev/media0
Media controller API version 0.1.0

Media device information
------------------------
driver          tegra-vi4
model           NVIDIA Tegra Video Input Device
serial          
bus info        
hw revision     0x3
driver version  0.0.0

Device topology
- entity 1: 150c0000.nvcsi--2 (2 pads, 2 links)
            type V4L2 subdev subtype Unknown flags 0
            device node name /dev/v4l-subdev0
	pad0: Sink
		<- "ov9281 2-0060":0 [ENABLED]
	pad1: Source
		-> "vi-output, ov9281 2-0060":0 [ENABLED]

- entity 4: ov9281 2-0060 (1 pad, 1 link)
            type V4L2 subdev subtype Sensor flags 0
            device node name /dev/v4l-subdev1
	pad0: Source
		[fmt:Y8_1X8/1280x800 field:none colorspace:unknown]
		-> "150c0000.nvcsi--2":0 [ENABLED]

- entity 6: vi-output, ov9281 2-0060 (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video0
	pad0: Sink
		<- "150c0000.nvcsi--2":1 [ENABLED]

- entity 18: 150c0000.nvcsi--1 (2 pads, 2 links)
             type V4L2 subdev subtype Unknown flags 0
             device node name /dev/v4l-subdev2
	pad0: Sink
		<- "ov9281 2-0010":0 [ENABLED]
	pad1: Source
		-> "vi-output, ov9281 2-0010":0 [ENABLED]

- entity 21: ov9281 2-0010 (1 pad, 1 link)
             type V4L2 subdev subtype Sensor flags 0
             device node name /dev/v4l-subdev3
	pad0: Source
		[fmt:Y8_1X8/1280x800 field:none colorspace:unknown]
		-> "150c0000.nvcsi--1":0 [ENABLED]

- entity 23: vi-output, ov9281 2-0010 (1 pad, 1 link)
             type Node subtype V4L flags 0
             device node name /dev/video1
	pad0: Sink
		<- "150c0000.nvcsi--1":1 [ENABLED]

ShaneCCC · September 1, 2022, 11:34am

Do you confuse with below, looks like it’s follow the video node. From the media-ctl looks like no problem.

platform:15700000.vi:1

Henry.Lou · September 2, 2022, 9:36am

Hi @ShaneCCC
We added some debugs in the tegra-rtcpu-trace.c

[ 2117.278499] ov9281 2-0010: ov9281_power_on: power on
[ 2117.289104] ov9281 2-0010: Using default I2C address 0x10 
[ 2117.302943] ov9281 2-0010: ov9281_s_stream: write mode table 0
[ 2117.323606] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2117.324341] ov9281 2-0010: ov9281_s_stream: write fsync table 2
[ 2117.338235] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.346993] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.355847] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.364747] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.373744] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.382534] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.391259] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.392425] ov9281 2-0010: ov9281_s_stream: write fsync slave mode table 0
[ 2117.392722] ov9281 2-0010: ov9281_s_stream: stream on
[ 2117.411962] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.420679] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2117.429428] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.438248] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.447106] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.455991] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.464706] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.473422] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.482133] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.490855] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.499628] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2117.563634] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2117.603651] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 2117.610054] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 2117.619958] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC0 = 0x00000002
[ 2117.627651] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2117.627661] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627668] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627674] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627680] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627686] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627691] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627697] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627702] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627708] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2117.627713] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627719] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627760] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627765] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627771] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627776] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627782] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627787] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.627793] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2117.795646] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2117.804923] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) INTR_STATUS 0x00010002
[ 2117.812985] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERR_INTR_STATUS 0x00010002
[ 2117.821216] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x0000000a
[ 2117.829380] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x0000000a
[ 2117.851647] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.860434] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.869164] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.877888] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.886635] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.895349] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.904064] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.912777] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.921525] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2117.930346] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.939236] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.948165] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.956921] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.965626] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.974341] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.983075] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2117.991935] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.000776] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2118.039611] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 2118.045983] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 2118.055755] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERROR_STATUS2VI_VC0 = 0x00000002
[ 2118.063600] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2118.063603] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063605] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063607] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063609] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063610] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063612] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063613] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063615] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063616] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2118.063618] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063619] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063621] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063623] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063624] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063626] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063627] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063629] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.063630] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131094
[ 2118.123587] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2118.239719] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) INTR_STATUS 0x00010002
[ 2118.247562] nvcsi 150c0000.nvcsi: csi4_stream_check_status (1) ERR_INTR_STATUS 0x00010002
[ 2118.255749] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x0400011e
[ 2118.263762] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x0400011e
[ 2118.287726] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131103
[ 2118.296682] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.306197] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.315297] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.324030] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.332791] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100
[ 2118.341515] (NULL device *): henry debug func=rtcpu_trace_array_event line=894 header_id=131100

update the trace log
the following log shows sensor is streaming, but v4l2 cannot get them, and config “W 1280 H 800” again and again.
We notice that sensor send fram on “channel:0x00”. Is the channel right? we think it should be channel 1 or channel b or something else.

       v4l2-ctl-8830  [000] ....  1689.990669: tegra_channel_open: vi-output, ov9281 2-0010
        v4l2-ctl-8830  [000] ....  1689.993277: tegra_channel_set_power: ov9281 2-0010 : 0x1 
        v4l2-ctl-8830  [000] ....  1689.993298: camera_common_s_power: status : 0x1 
        v4l2-ctl-8830  [000] ....  1690.004004: tegra_channel_set_power: 150c0000.nvcsi--1 : 0x1 
        v4l2-ctl-8830  [000] ....  1690.004009: csi_s_power: enable : 0x1 
        v4l2-ctl-8830  [000] ....  1690.017630: tegra_channel_capture_setup: vnc_id 0 W 1280 H 800 fmt 10
 vi-output, ov92-8831  [005] ....  1690.017779: tegra_channel_set_stream: enable : 0x1 
 vi-output, ov92-8831  [004] ....  1690.021670: tegra_channel_set_stream: 150c0000.nvcsi--1 : 0x1 
 vi-output, ov92-8831  [004] ....  1690.021674: csi_s_stream: enable : 0x1 
 vi-output, ov92-8831  [004] ....  1690.021702: tegra_channel_set_stream: ov9281 2-0010 : 0x1 
     kworker/3:1-8808  [003] ....  1690.067515: rtcpu_start: tstamp:52962595447
     kworker/3:1-8808  [003] ....  1690.158216: rtos_queue_send_failed: tstamp:52962689633 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1690.237158: rtos_queue_send_failed: tstamp:52962694634 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1690.316093: rtcpu_vinotify_event: tstamp:52966462093 tag:CSIMUX_FRAME channel:0x00 frame:3 vi_tstamp:52966461703 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.357528: rtcpu_vinotify_event: tstamp:52966677980 tag:CSIMUX_FRAME channel:0x00 frame:4 vi_tstamp:52966677592 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.382957: rtcpu_vinotify_event: tstamp:52966893865 tag:CSIMUX_FRAME channel:0x00 frame:5 vi_tstamp:52966893483 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.408336: rtcpu_vinotify_event: tstamp:52967109777 tag:CSIMUX_FRAME channel:0x00 frame:6 vi_tstamp:52967109373 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.433611: rtcpu_vinotify_event: tstamp:52967325733 tag:CSIMUX_FRAME channel:0x00 frame:7 vi_tstamp:52967325262 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.459235: rtcpu_vinotify_event: tstamp:52967541522 tag:CSIMUX_FRAME channel:0x00 frame:8 vi_tstamp:52967541153 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.493967: rtcpu_vinotify_event: tstamp:52967757442 tag:CSIMUX_FRAME channel:0x00 frame:9 vi_tstamp:52967757043 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.519454: rtcpu_vinotify_event: tstamp:52967973332 tag:CSIMUX_FRAME channel:0x00 frame:10 vi_tstamp:52967972933 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.544792: rtcpu_vinotify_event: tstamp:52968189221 tag:CSIMUX_FRAME channel:0x00 frame:11 vi_tstamp:52968188823 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.570158: rtcpu_vinotify_event: tstamp:52968405082 tag:CSIMUX_FRAME channel:0x00 frame:12 vi_tstamp:52968404713 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.595551: rtcpu_vinotify_event: tstamp:52968621002 tag:CSIMUX_FRAME channel:0x00 frame:13 vi_tstamp:52968620604 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.620996: rtcpu_vinotify_event: tstamp:52968836891 tag:CSIMUX_FRAME channel:0x00 frame:14 vi_tstamp:52968836493 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.646344: rtcpu_vinotify_event: tstamp:52969052770 tag:CSIMUX_FRAME channel:0x00 frame:15 vi_tstamp:52969052383 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.671729: rtcpu_vinotify_event: tstamp:52969268651 tag:CSIMUX_FRAME channel:0x00 frame:16 vi_tstamp:52969268274 data:0x00400061
 kworker/3:1-8808  [003] ....  1690.697109: rtcpu_vinotify_event: tstamp:52969484543 tag:CSIMUX_FRAME channel:0x00 frame:17 vi_tstamp:52969484164 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.722512: rtcpu_vinotify_event: tstamp:52969700424 tag:CSIMUX_FRAME channel:0x00 frame:18 vi_tstamp:52969700054 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.747919: rtcpu_vinotify_event: tstamp:52969916443 tag:CSIMUX_FRAME channel:0x00 frame:19 vi_tstamp:52969915944 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.773307: rtcpu_vinotify_event: tstamp:52970132302 tag:CSIMUX_FRAME channel:0x00 frame:20 vi_tstamp:52970131834 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.798662: rtcpu_vinotify_event: tstamp:52970348139 tag:CSIMUX_FRAME channel:0x00 frame:21 vi_tstamp:52970347723 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.824043: rtcpu_vinotify_event: tstamp:52970564081 tag:CSIMUX_FRAME channel:0x00 frame:22 vi_tstamp:52970563614 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.849419: rtcpu_vinotify_event: tstamp:52970780009 tag:CSIMUX_FRAME channel:0x00 frame:23 vi_tstamp:52970779504 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.874787: rtcpu_vinotify_event: tstamp:52970995861 tag:CSIMUX_FRAME channel:0x00 frame:24 vi_tstamp:52970995394 data:0x00400061
     kworker/3:1-8808  [003] ....  1690.900222: rtcpu_vinotify_event: tstamp:52971211752 tag:CSIMUX_FRAME channel:0x00 frame:25 vi_tstamp:52971211284 data:0x00400061
 vi-output, ov92-8831  [004] ....  1690.942493: tegra_channel_capture_setup: vnc_id 0 W 1280 H 800 fmt 10
 vi-output, ov92-8831  [004] ....  1690.942535: tegra_channel_capture_frame: sof:-549619126124.-267687059712
     kworker/3:1-8808  [003] ....  1690.980272: rtcpu_vinotify_event: tstamp:52971427591 tag:CSIMUX_FRAME channel:0x00 frame:26 vi_tstamp:52971427174 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.005592: rtcpu_vinotify_event: tstamp:52971643481 tag:CSIMUX_FRAME channel:0x00 frame:27 vi_tstamp:52971643065 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.031008: rtcpu_vinotify_event: tstamp:52971859357 tag:CSIMUX_FRAME channel:0x00 frame:28 vi_tstamp:52971858954 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.056450: rtcpu_vinotify_event: tstamp:52972075226 tag:CSIMUX_FRAME channel:0x00 frame:29 vi_tstamp:52972074845 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.081845: rtcpu_vinotify_event: tstamp:52972291115 tag:CSIMUX_FRAME channel:0x00 frame:30 vi_tstamp:52972290735 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.176704: rtos_queue_send_failed: tstamp:52972484567 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1691.291430: rtos_queue_send_failed: tstamp:52990279824 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1691.370494: rtos_queue_send_failed: tstamp:52991588325 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1691.449596: rtos_queue_send_failed: tstamp:52991595326 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1691.475008: rtcpu_vinotify_event: tstamp:52991937136 tag:CSIMUX_FRAME channel:0x00 frame:121 vi_tstamp:52991936732 data:0x00400061
 vi-output, ov92-8831  [004] ....  1691.517124: tegra_channel_capture_setup: vnc_id 0 W 1280 H 800 fmt 10
 vi-output, ov92-8831  [004] ....  1691.517164: tegra_channel_capture_frame: sof:-549619126124.-267687059712
     kworker/3:1-8808  [003] ....  1691.556284: rtcpu_vinotify_event: tstamp:52992153024 tag:CSIMUX_FRAME channel:0x00 frame:122 vi_tstamp:52992152621 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.581618: rtcpu_vinotify_event: tstamp:52992368911 tag:CSIMUX_FRAME channel:0x00 frame:123 vi_tstamp:52992368511 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.606933: rtcpu_vinotify_event: tstamp:52992584802 tag:CSIMUX_FRAME channel:0x00 frame:124 vi_tstamp:52992584401 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.641124: rtcpu_vinotify_event: tstamp:52992800689 tag:CSIMUX_FRAME channel:0x00 frame:125 vi_tstamp:52992800292 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.666659: rtcpu_vinotify_event: tstamp:52993016579 tag:CSIMUX_FRAME channel:0x00 frame:126 vi_tstamp:52993016181 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.692139: rtcpu_vinotify_event: tstamp:52993232451 tag:CSIMUX_FRAME channel:0x00 frame:127 vi_tstamp:52993232071 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.717544: rtcpu_vinotify_event: tstamp:52993448340 tag:CSIMUX_FRAME channel:0x00 frame:128 vi_tstamp:52993447962 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.758903: rtcpu_vinotify_event: tstamp:52993664250 tag:CSIMUX_FRAME channel:0x00 frame:129 vi_tstamp:52993663852 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.784304: rtcpu_vinotify_event: tstamp:52993880142 tag:CSIMUX_FRAME channel:0x00 frame:130 vi_tstamp:52993879742 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.809825: rtcpu_vinotify_event: tstamp:52994096028 tag:CSIMUX_FRAME channel:0x00 frame:131 vi_tstamp:52994095632 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.835158: rtcpu_vinotify_event: tstamp:52994311951 tag:CSIMUX_FRAME channel:0x00 frame:132 vi_tstamp:52994311522 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.860552: rtcpu_vinotify_event: tstamp:52994527810 tag:CSIMUX_FRAME channel:0x00 frame:133 vi_tstamp:52994527412 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.885937: rtcpu_vinotify_event: tstamp:52994743701 tag:CSIMUX_FRAME channel:0x00 frame:134 vi_tstamp:52994743303 data:0x00400061
kworker/3:1-8808  [003] ....  1691.911322: rtcpu_vinotify_event: tstamp:52994959591 tag:CSIMUX_FRAME channel:0x00 frame:135 vi_tstamp:52994959193 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.936725: rtcpu_vinotify_event: tstamp:52995175480 tag:CSIMUX_FRAME channel:0x00 frame:136 vi_tstamp:52995175082 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.962109: rtcpu_vinotify_event: tstamp:52995391370 tag:CSIMUX_FRAME channel:0x00 frame:137 vi_tstamp:52995390972 data:0x00400061
     kworker/3:1-8808  [003] ....  1691.987513: rtcpu_vinotify_event: tstamp:52995607261 tag:CSIMUX_FRAME channel:0x00 frame:138 vi_tstamp:52995606863 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.012908: rtcpu_vinotify_event: tstamp:52995823150 tag:CSIMUX_FRAME channel:0x00 frame:139 vi_tstamp:52995822753 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.038309: rtcpu_vinotify_event: tstamp:52996039041 tag:CSIMUX_FRAME channel:0x00 frame:140 vi_tstamp:52996038642 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.063677: rtcpu_vinotify_event: tstamp:52996254931 tag:CSIMUX_FRAME channel:0x00 frame:141 vi_tstamp:52996254532 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.089064: rtcpu_vinotify_event: tstamp:52996470818 tag:CSIMUX_FRAME channel:0x00 frame:142 vi_tstamp:52996470423 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.114406: rtcpu_vinotify_event: tstamp:52996686709 tag:CSIMUX_FRAME channel:0x00 frame:143 vi_tstamp:52996686313 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.139735: rtcpu_vinotify_event: tstamp:52996902600 tag:CSIMUX_FRAME channel:0x00 frame:144 vi_tstamp:52996902202 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.164960: rtcpu_vinotify_event: tstamp:52997118489 tag:CSIMUX_FRAME channel:0x00 frame:145 vi_tstamp:52997118093 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.190457: rtcpu_vinotify_event: tstamp:52997334381 tag:CSIMUX_FRAME channel:0x00 frame:146 vi_tstamp:52997333983 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.215873: rtcpu_vinotify_event: tstamp:52997550271 tag:CSIMUX_FRAME channel:0x00 frame:147 vi_tstamp:52997549873 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.249796: rtcpu_vinotify_event: tstamp:52997766132 tag:CSIMUX_FRAME channel:0x00 frame:148 vi_tstamp:52997765763 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.275232: rtcpu_vinotify_event: tstamp:52997982051 tag:CSIMUX_FRAME channel:0x00 frame:149 vi_tstamp:52997981654 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.354105: rtos_queue_send_failed: tstamp:52997985802 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1692.450834: rtos_queue_send_failed: tstamp:53008245628 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1692.530301: rtos_queue_send_failed: tstamp:53009548121 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1692.609419: rtos_queue_send_failed: tstamp:53009553386 queue:0x0b4a7698
     kworker/3:1-8808  [003] ....  1692.634779: rtcpu_vinotify_event: tstamp:53009877372 tag:CSIMUX_FRAME channel:0x00 frame:204 vi_tstamp:53009876949 data:0x000000a1
 vi-output, ov92-8831  [004] ....  1692.676651: tegra_channel_capture_setup: vnc_id 0 W 1280 H 800 fmt 10
 vi-output, ov92-8831  [004] ....  1692.676688: tegra_channel_capture_frame: sof:-549619126124.-267687059712
     kworker/3:1-8808  [003] ....  1692.712303: rtcpu_vinotify_event: tstamp:53010071900 tag:CSIMUX_FRAME channel:0x00 frame:205 vi_tstamp:53010071498 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.737599: rtcpu_vinotify_event: tstamp:53010287788 tag:CSIMUX_FRAME channel:0x00 frame:206 vi_tstamp:53010287388 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.763016: rtcpu_vinotify_event: tstamp:53010503678 tag:CSIMUX_FRAME channel:0x00 frame:207 vi_tstamp:53010503278 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.788445: rtcpu_vinotify_event: tstamp:53010719566 tag:CSIMUX_FRAME channel:0x00 frame:208 vi_tstamp:53010719169 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.813836: rtcpu_vinotify_event: tstamp:53010935456 tag:CSIMUX_FRAME channel:0x00 frame:209 vi_tstamp:53010935058 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.839192: rtcpu_vinotify_event: tstamp:53011151346 tag:CSIMUX_FRAME channel:0x00 frame:210 vi_tstamp:53011150948 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.864762: rtcpu_vinotify_event: tstamp:53011388576 tag:CSIMUX_FRAME channel:0x00 frame:211 vi_tstamp:53011388179 data:0x000000a1
     kworker/3:1-8808  [003] ....  1692.906460: rtcpu_vinotify_event: tstamp:53011583116 tag:CSIMUX_FRAME channel:0x00 frame:212 vi_tstamp:53011582729 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.931860: rtcpu_vinotify_event: tstamp:53011798999 tag:CSIMUX_FRAME channel:0x00 frame:213 vi_tstamp:53011798617 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.957276: rtcpu_vinotify_event: tstamp:53012014878 tag:CSIMUX_FRAME channel:0x00 frame:214 vi_tstamp:53012014508 data:0x00400061
     kworker/3:1-8808  [003] ....  1692.982618: rtcpu_vinotify_event: tstamp:53012230768 tag:CSIMUX_FRAME channel:0x00 frame:215 vi_tstamp:53012230399 data:0x00400061
     kworker/3:1-8808  [003] ....  1693.007932: rtcpu_vinotify_event: tstamp:53012446687 tag:CSIMUX_FRAME channel:0x00 frame:216 vi_tstamp:53012446288 data:0x00400061
     kworker/3:1-8808  [003] ....  1693.042109: rtcpu_vinotify_event: tstamp:53012662579 tag:CSIMUX_FRAME channel:0x00 frame:217 vi_tstamp:53012662178 data:0x00400061
     kworker/3:1-8808  [003] ....  1693.067499: rtcpu_vinotify_event: tstamp:53012878467 tag:CSIMUX_FRAME channel:0x00 frame:218 vi_tstamp:53012878069 data:0x0040006

ShaneCCC · September 2, 2022, 11:20am

The CSIMUX_FRAME data:0x00400061 tell the CRC error on payload.

Thanks

Henry.Lou · September 3, 2022, 8:57am

Hi @ShaneCCC
according to the following message, bit 22 means CRC error.

CSIMUX_FRAME data bit field
    bit 0:2 STREAM_ID
    bit 3 VPR
    bit 4 FS_flag
    bit 5 FE_flag
    bit 6 FE_CSI_FAULT
    bit 7 FS_FAULT
    bit 8 FORCE_FE_FAULT
    bit 9 FE_FRAME_ID_FAULT
    bit 10 PXL_ENABLE_FAULT
    bit 20:25 CSI_FAULT_CODE
CSI_FAULT_CODE data bit field
    bit 20 PP FSM timeout
    bit 21 PH single bit error repaired
    bit 22 CRC error on payload
    bit 23 Line short error

but, the other sensor which is registed on i2c 2-0060 works well.
so, we think HW is fun.
what`s next step to debug, could you give some suggestions?

ShaneCCC · September 5, 2022, 5:05am

Does it the same sensor module connect to i2c-2?

Henry.Lou · September 5, 2022, 6:00am

Hi @ShaneCCC

Henry.Lou:

[    6.574527] tegra-vi4 15700000.vi: subdev 150c0000.nvcsi--2 bound
[    6.574539] tegra-vi4 15700000.vi: subdev ov9281 2-0060 bound
[    6.575142] tegra-vi4 15700000.vi: subdev 150c0000.nvcsi--1 bound
[    6.575147] tegra-vi4 15700000.vi: subdev ov9281 2-0010 bound

yes, the two cameras are the same.
if run “v4l2-ctl --stream-mmap -d /dev/video0”, the first camera on 2-0060 works well.
but, if run “v4l2-ctl --stream-mmap -d /dev/video1” the second one fail.

ShaneCCC · September 5, 2022, 6:30am

Could you try connect to another lanes to verify?

Henry.Lou · September 5, 2022, 7:58am

Hi @ShaneCCC
do you mean change csi channel?
now, on our custom board, the first camera connect on csi channel a, and the second one is on csi channel b. It’s hard to change it.

update
attachment is the whole trache log, maybe there are some messgages we missed.
FYI
henry_trace10.log (721.0 KB)

Henry.Lou · September 5, 2022, 8:46am

Hi @ShaneCCC
We do a test: disconnet the first camera from our custom board, only connect the second one. After the board bring up, “media-ctl” shows that 2-0010 camera bound to video0. But, in the DT file, it’s devnode has been specified as “video1”. Could this be a trace point?

root@t-desktop:/home/t# media-ctl -p -d /dev/media0
Media controller API version 0.1.0

Media device information
------------------------
driver          tegra-vi4
model           NVIDIA Tegra Video Input Device
serial          
bus info        
hw revision     0x3
driver version  0.0.0

Device topology
- entity 1: 150c0000.nvcsi--2 (2 pads, 0 link)
            type V4L2 subdev subtype Unknown flags 0
            device node name /dev/v4l-subdev0
	pad0: Sink
	pad1: Source

- entity 4: 150c0000.nvcsi--1 (2 pads, 2 links)
            type V4L2 subdev subtype Unknown flags 0
            device node name /dev/v4l-subdev1
	pad0: Sink
		<- "ov9281 2-0010":0 [ENABLED]
	pad1: Source
		-> "vi-output, ov9281 2-0010":0 [ENABLED]

- entity 7: ov9281 2-0010 (1 pad, 1 link)
            type V4L2 subdev subtype Sensor flags 0
            device node name /dev/v4l-subdev2
	pad0: Source
		[fmt:Y8_1X8/1280x800 field:none colorspace:unknown]
		-> "150c0000.nvcsi--1":0 [ENABLED]

- entity 9: vi-output, ov9281 2-0010 (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video0
	pad0: Sink
		<- "150c0000.nvcsi--1":1 [ENABLED]

ShaneCCC · September 5, 2022, 10:31am

The video# in device tree didn’t use for current driver framework.

ShaneCCC · September 5, 2022, 10:33am

Didn’t see any FS/FE tags that’s weird.

Henry.Lou · September 6, 2022, 6:19am

Hi @ShaneCCC
we change the “embedded_metadata_height” from 1 to 0.
but same response.
attachment is the dmesg log, maybe helpful.
henry2.log (80.8 KB)

ShaneCCC · September 6, 2022, 6:46am

Did you ever boost clocks to try?
There are FIFO error could be NVCSI/VI clocks bandwidth too low cause the problem.

sudo jetson_clocks
sudo su
echo 1 > /sys/kernel/debug/bpmp/debug/clk/vi/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/isp/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/nvcsi/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/emc/mrq_rate_locked
cat /sys/kernel/debug/bpmp/debug/clk/vi/max_rate |tee /sys/kernel/debug/bpmp/debug/clk/vi/rate
cat /sys/kernel/debug/bpmp/debug/clk/isp/max_rate | tee  /sys/kernel/debug/bpmp/debug/clk/isp/rate
cat /sys/kernel/debug/bpmp/debug/clk/nvcsi/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/nvcsi/rate
cat /sys/kernel/debug/bpmp/debug/clk/emc/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/emc/rate

echo userspace > /sys/devices/13e10000.host1x/15340000.vic/devfreq/15340000.vic/governor

echo 1 > /sys/kernel/debug/bpmp/debug/clk/vic/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/vic/state
cat /sys/kernel/debug/bpmp/debug/clk/vic/max_rate > /sys/kernel/debug/bpmp/debug/clk/vic/rate

Henry.Lou · September 6, 2022, 7:00am

Hi @ShaneCCC
We tried these commands just now.
But, got same response.
attachments are logs. wish they may help.
henry_trace1.log (144.9 KB)
henry3.log (123.3 KB)

ShaneCCC · September 6, 2022, 11:38am

The error still the same CSIMUX_FRAME data:0x00400061
Maybe probe the MIPI signal to compare with I2C-2’s sensor.

Henry.Lou · September 17, 2022, 7:49am

Hi @ShaneCCC
We contact with the sensor FAE, we trigger the clock lane and data lane signal by oscilloscope. The FAE confirms that waveforms are fun. But, v4l2-ctl still does not work.

root@t-desktop:/home/t# v4l2-ctl --stream-mmap --verbose -d /dev/video1
VIDIOC_QUERYCAP: ok
VIDIOC_REQBUFS: ok
VIDIOC_QUERYBUF: ok
VIDIOC_QBUF: ok
VIDIOC_QUERYBUF: ok
VIDIOC_QBUF: ok
VIDIOC_QUERYBUF: ok
VIDIOC_QBUF: ok
VIDIOC_QUERYBUF: ok
VIDIOC_QBUF: ok
VIDIOC_STREAMON: ok

it blocks here, and gets no frame.
the dmesg shows that:

[   93.808093] ov9281 2-0010: ov9281_power_on: power on
[   93.818739] ov9281 2-0010: Using default I2C address 0x10 
[   93.845016] ov9281 2-0010: ov9281_s_stream: write mode table 0
[   93.871079] ov9281 2-0010: ov9281_s_stream: write fsync table 2
[   93.945481] ov9281 2-0010: ov9281_s_stream: write fsync slave mode table 0
[   93.952830] ov9281 2-0010: ov9281_s_stream: stream on
[   94.170086] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   94.176741] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   94.187562] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x00000104
[   94.195758] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x00000104
[   94.406390] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   94.412945] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   94.422820] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   94.430861] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   94.642656] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   94.649256] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   94.659833] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   94.668049] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   94.878867] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   94.885477] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   94.896044] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   94.904325] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   95.115256] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   95.121824] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   95.132654] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   95.140850] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   95.351594] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   95.358144] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   95.368900] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   95.377122] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   95.587590] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   95.594344] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   95.605310] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   95.613488] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   95.823863] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   95.830579] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   95.840773] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   95.848974] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   96.060053] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   96.066567] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   96.077154] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000114
[   96.085343] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000114
[   96.296403] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   96.303054] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   96.313958] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000194
[   96.322247] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000194
[   96.532628] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[   96.539207] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[   96.550153] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_INTR_STATUS 0x04000194
[   96.558382] nvcsi 150c0000.nvcsi: csi4_cil_check_status (1) CILA_ERR_INTR_STATUS 0x04000194

noting that ERROR_STATUS2VI_VC0 has gone.
but, the trace log shows no tags, such as PXL_SOF PXL_EOF etc.
we refer to the TRM, 28.6.138 chapter.
bit 8 means err_intr_cil_data_lane_rxfifo_full_err1_a.
bit 6 means err_intr_cil_data_lane_sot_mb_err1_a.
bit 2 means err_intr_cil_data_lane_sot_mb_err0_a.
Could you give us some introductions about these error data?
BTW

root@t-desktop:/home/t# v4l2-ctl --list-formats-ext
ioctl: VIDIOC_ENUM_FMT
	Index       : 0
	Type        : Video Capture
	Pixel Format: 'GREY'
	Name        : 8-bit Greyscale
		Size: Discrete 640x400
			Interval: Discrete 0.008s (120.000 fps)

the above logs show only index0, but video1 can not be detected.
We refer to this post, and find that all cameras, such as video0 video1 should be seen.
Could this be a trace point?

ShaneCCC · September 19, 2022, 2:54pm

You can boost the clocks for the FIFO error.

sudo nvpmodel -m 0
sudo jetson_clocks
sudo su
echo 1 > /sys/kernel/debug/bpmp/debug/clk/vi/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/isp/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/nvcsi/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/emc/mrq_rate_locked
cat /sys/kernel/debug/bpmp/debug/clk/vi/max_rate |tee /sys/kernel/debug/bpmp/debug/clk/vi/rate
cat /sys/kernel/debug/bpmp/debug/clk/isp/max_rate | tee  /sys/kernel/debug/bpmp/debug/clk/isp/rate
cat /sys/kernel/debug/bpmp/debug/clk/nvcsi/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/nvcsi/rate
cat /sys/kernel/debug/bpmp/debug/clk/emc/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/emc/rate