Orin jetpack5.1.2 When the data rate of each channel is 1.8Gbps, Csi2 cannot receive frames

Robotics & Edge Computing Jetson & Embedded Systems Jetson AGX Orin
1

Jetson Team：
we have four 1920*1536(isx031) camera connect to max96717 ---- max96712 ----orin。
The mipi speed configured with a serializer is 1800Mbps.
orin side i have already config serdes_pix_clk_hz = “450000000”;
I am unable to obtain images

Complete camera trace log:

_-----=> irqs-off

/ _----=> need-resched

| / _—=> hardirq/softirq

|| / _–=> preempt-depth

||| / delay

TASK-PID CPU# |||| TIMESTAMP FUNCTION

| | | |||| | |

 kworker/4:6-202     [004] ....    76.305995: rtcpu_string: tstamp:2987210355 id:0x04010000 str:"VM0 deactivating."
 kworker/4:6-202     [004] ....    80.234011: rtcpu_string: tstamp:3109928189 id:0x04010000 str:"VM0 activating."
 kworker/4:6-202     [004] ....    80.234017: rtcpu_string: tstamp:3110011839 id:0x04010000 str:"calibration status1 251b51f2 status2 274aca72

"
kworker/4:6-202 [004] … 80.234038: rtcpu_string: tstamp:3110012546 id:0x04010000 str:"calibration status1 290b4ed0 status2 20fac273
"
kworker/4:6-202 [004] … 80.234040: rtcpu_string: tstamp:3110013250 id:0x04010000 str:"calibration status1 19383a93 status2 2af852d5
"
kworker/4:6-202 [004] … 80.234042: rtcpu_string: tstamp:3110013950 id:0x04010000 str:"calibration status1 20fa52b6 status2 213a4dd0
"
kworker/4:6-202 [004] … 80.234043: rtcpu_string: tstamp:3110026738 id:0x04010000 str:“NVCSILP clock rate = 408000000 Hz.
"
kworker/4:6-202 [004] … 80.465986: rtcpu_isp_falcon_task_start: tstamp:3116432206 ch:0 task:HANDLE_EVENT
kworker/4:6-202 [004] … 80.465992: rtcpu_isp_falcon_task_end: tstamp:3116432245 task:HANDLE_EVENT
kworker/4:6-202 [004] … 81.149974: rtcpu_vinotify_event: tstamp:3138919020 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:100429823904 data:0x359d580010000000
kworker/4:6-202 [004] … 81.149977: rtcpu_vinotify_event: tstamp:3138919156 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:100429830752 data:0x0000000031000001
kworker/4:6-202 [004] … 81.149977: rtcpu_vinotify_event: tstamp:3138919311 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:100429886400 data:0x359d550010000000
kworker/4:6-202 [004] … 81.149977: rtcpu_vinotify_event: tstamp:3138919440 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:100429892992 data:0x0000000031000002
kworker/4:6-202 [004] … 81.149978: rtcpu_string: tstamp:3138954212 id:0x04010000 str:“tegra_nvcsi_stream_set_config(vm0, stream=0, csi”
kworker/4:6-202 [004] … 81.149980: rtcpu_string: tstamp:3138954313 id:0x04010000 str:”=0)
"
kworker/4:6-202 [004] … 81.149986: rtcpu_string: tstamp:3138954682 id:0x04010000 str:“MIPI clock = 900000 kHz, tHS-SETTLE = 0, tCLK-SE”
kworker/4:6-202 [004] … 81.149987: rtcpu_string: tstamp:3138954784 id:0x04010000 str:“TTLE = 0
"
kworker/4:6-202 [004] … 81.149989: rtcpu_string: tstamp:3138954994 id:0x04010000 str:”===== NVCSI Stream Configuration =====
"
kworker/4:6-202 [004] … 81.149991: rtcpu_string: tstamp:3138955237 id:0x04010000 str:"stream_id: PP 0, csi_port: PORT A
"
kworker/4:6-202 [004] … 81.149992: rtcpu_string: tstamp:3138955489 id:0x04010000 str:"Brick: PHY 0, Mode: D-PHY
"
kworker/4:6-202 [004] … 81.149994: rtcpu_string: tstamp:3138955772 id:0x04010000 str:"Partition: CIL A, LP bypass: Enabled, Lanes: 4
"
kworker/4:6-202 [004] … 81.149996: rtcpu_string: tstamp:3138955950 id:0x04010000 str:"Clock information:
"
kworker/4:6-202 [004] … 81.149998: rtcpu_string: tstamp:3138956248 id:0x04010000 str:"MIPI clock rate: 900.00 MHz
"
kworker/4:6-202 [004] … 81.150000: rtcpu_string: tstamp:3138956489 id:0x04010000 str:“T_HS settle: 0, T_CLK settle: 0
"
kworker/4:6-202 [004] … 81.150002: rtcpu_string: tstamp:3138956715 id:0x04010000 str:”======================================
"
kworker/4:6-202 [004] … 81.150004: rtcpu_string: tstamp:3138958442 id:0x04010000 str:"tegra_nvcsi_stream_open(vm0, stream=0, csi=0)
"
kworker/4:6-202 [004] … 81.150005: rtcpu_string: tstamp:3138959038 id:0x04010000 str:“nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_A_”
kworker/4:6-202 [004] … 81.150006: rtcpu_string: tstamp:3138959141 id:0x04010000 str:"SW_RESET_0 = 00000003
"
kworker/4:6-202 [004] … 81.150008: rtcpu_string: tstamp:3138959500 id:0x04010000 str:“nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_B_”
kworker/4:6-202 [004] … 81.150008: rtcpu_string: tstamp:3138959601 id:0x04010000 str:"SW_RESET_0 = 00000003
"
kworker/4:6-202 [004] … 81.150010: rtcpu_string: tstamp:3138960276 id:0x04010000 str:“nvcsi_reset_lane_merger: NVCSI_PHY_0_LM_SW_RESET”
kworker/4:6-202 [004] … 81.150011: rtcpu_string: tstamp:3138960377 id:0x04010000 str:“0 = 00000001
"
kworker/4:6-202 [004] … 81.150013: rtcpu_string: tstamp:3138966374 id:0x04010000 str:“nvcsi_reset_lane_merger: NVCSI_PHY_0_LM_SW_RESET”
kworker/4:6-202 [004] … 81.150013: rtcpu_string: tstamp:3138966475 id:0x04010000 str:“0 = 00000000
"
kworker/4:6-202 [004] … 81.150015: rtcpu_string: tstamp:3138967049 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 51
"
kworker/4:6-202 [004] … 81.150017: rtcpu_string: tstamp:3138967311 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 51
"
kworker/4:6-202 [004] … 81.150019: rtcpu_string: tstamp:3138967569 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 51
"
kworker/4:6-202 [004] … 81.150020: rtcpu_string: tstamp:3138967826 id:0x04010000 str:"nvcsi_calc_tclk_settle tclk_settle 75
"
kworker/4:6-202 [004] … 81.150022: rtcpu_string: tstamp:3138968272 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_A”
kworker/4:6-202 [004] … 81.150023: rtcpu_string: tstamp:3138968373 id:0x04010000 str:"SW_RESET_0 = 00000000
"
kworker/4:6-202 [004] … 81.150025: rtcpu_string: tstamp:3138968727 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_B”
kworker/4:6-202 [004] … 81.150025: rtcpu_string: tstamp:3138968827 id:0x04010000 str:"SW_RESET_0 = 00000000
"
kworker/4:6-202 [004] … 81.150027: rtcpu_string: tstamp:3138969262 id:0x04010000 str:"Deskew setup message sent for port 0 num_lane 4
"

4

hello 305248199,

please refer to developer guide, SerDes Pixel Clock.
since you’ve data-rate larger than 1.5Gbps, please check you’ve deskew calibration, else the camera firmware will continue to wait for deskew signal from the sensor side.

it looks you’ve apply rce-fw update already, may I know where you’ve obtain the binary file?
anyways.
you should refer to Topic 268833, which given camera firmware to update deskew algorithm, and also stability fixes based-on JP-5.1.2/r35.4.1

5

I have seen it, and my parameters are calculated based on the documentation; Patches have also been applied,

6

hello 305248199,

please examine your sensor stream with v4l2 IOCTL to narrow down the issue.

7

No issues before using deskew; However, the problems that arise after increasing bandwidth; Here, use the formula:
Output data rate = (sensor or deserializer pixel clock in hertz) * (bits per pixel) / (number of CSI lanes)
Calculating doesn’t seem to be useful, is there anything else to pay attention to?

8

hello 305248199,

we did had some bugs with data-rate larger than 1.5Gbps, which addressed by rce-fw update.
so, may I double confirm which binary file you used? because it looks you’re using the one with debug flag enabled.

besides,
there’re some changes check-in to rel-35, is it possible for moving to the latest rel-35 (JP-5.1.3/r35.5.0) for verification?

9

RCE-FW is using Topic268833_JP-512_RCE-FW-Debug.7z

JP512 version is our mass-produced version

10

please apply this rce-fw Topic268833_JP-512_rce-fw.7z.

11

Okay, I’ll give it a try

12

apply this rce-fw Topic268833_JP-512_rce-fw.7z ，Same effect,

_-----=> irqs-off

/ _----=> need-resched

| / _—=> hardirq/softirq

|| / _–=> preempt-depth

||| / delay

TASK-PID CPU# |||| TIMESTAMP FUNCTION

| | | |||| | |

 kworker/6:2-139     [006] ....   141.377466: rtcpu_string: tstamp:5023745542 id:0x04010000 str:"VM0 activating."
 kworker/6:2-139     [006] ....   141.489467: rtcpu_isp_falcon_task_start: tstamp:732761722 ch:0 task:HANDLE_EVENT
 kworker/6:2-139     [006] ....   141.489474: rtcpu_isp_falcon_task_end: tstamp:732761763 task:HANDLE_EVENT
 kworker/6:2-139     [006] ....   142.169436: rtcpu_vinotify_event: tstamp:5048756175 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:161544492480 data:0x359d580010000000
 kworker/6:2-139     [006] ....   142.169438: rtcpu_vinotify_event: tstamp:5048756398 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:161544498976 data:0x0000000031000001
 kworker/6:2-139     [006] ....   142.169439: rtcpu_vinotify_event: tstamp:5048756657 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:161544559680 data:0x359d550010000000
 kworker/6:2-139     [006] ....   142.169439: rtcpu_vinotify_event: tstamp:5048756870 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:161544566272 data:0x0000000031000002
13

is it complete logs? could you please capture the logs into single text file.
anyways, there’s no frame packet related messages on CSI channel. please double check device outputting MIPI signaling correctly.

14

It is a complete camera trace log.

mipi D1N pin

c65de8b247d6a1962f7a858f262d2a2
c65de8b247d6a1962f7a858f262d2a21702×1276 307 KB

mipi clock n pin

aace2f35b4125d0113240dfec01951d
aace2f35b4125d0113240dfec01951d1702×1276 271 KB

15

hello 305248199,

is it able to issue a reset on SerDes chip to re-initial stream while you’re calling s_stream()?

besides,
you may also give it another try with below commands to boost all the VI/CSI/ISP clocks.
for instance,

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
16

Using these commands, the problem still persists~~

17

hello 305248199,

the hardware connections should be okay as you’ve verified before using deskew,
as mentioned, the main problem here is no frame packets has received by VI engine.
basically, we should at least receiving SOF/EOF on the CSI channel.

18

Can you view the raw SOF/EOF data received on the CSI channel?

19

hello 305248199,

it’ll reported to VI tracing logs. such as CHANSEL_PXL_SOF, CHANSEL_PXL_EOF, CHANSEL_LOAD_FRAMED…etc
for instance,

     kworker/0:1-1428  [000] ...1  1844.751319: rtcpu_vinotify_handle_msg: tstamp:57783599528 tag:CHANSEL_PXL_SOF channel:0x02 frame:6 vi_tstamp:1949023381 data:0x00000001
     kworker/0:1-1428  [000] ...1  1844.751321: rtcpu_vinotify_handle_msg: tstamp:57783599673 tag:CHANSEL_PXL_SOF channel:0x03 frame:6 vi_tstamp:1949023381 data:0x00000001
     kworker/0:1-1428  [000] ...1  1844.751322: rtcpu_vinotify_handle_msg: tstamp:57783599816 tag:CHANSEL_PXL_SOF channel:0x01 frame:6 vi_tstamp:1949023382 data:0x00000001
     kworker/0:1-1428  [000] ...1  1844.751322: rtcpu_vinotify_handle_msg: tstamp:57783599955 tag:CHANSEL_PXL_SOF channel:0x00 frame:6 vi_tstamp:1949023382 data:0x00000001
     kworker/0:1-1428  [000] ...1  1844.751323: rtcpu_vinotify_handle_msg: tstamp:57783600096 tag:ATOMP_FS channel:0x02 frame:6 vi_tstamp:1949023418 data:0x00000000
     kworker/0:1-1428  [000] ...1  1844.751324: rtcpu_vinotify_handle_msg: tstamp:57783600194 tag:ATOMP_FS channel:0x03 frame:6 vi_tstamp:1949023419 data:0x00000000
     kworker/0:1-1428  [000] ...1  1844.751325: rtcpu_vinotify_handle_msg: tstamp:57783600294 tag:ATOMP_FS channel:0x01 frame:6 vi_tstamp:1949023419 data:0x00000000
     kworker/0:1-1428  [000] ...1  1844.751325: rtcpu_vinotify_handle_msg: tstamp:57783600392 tag:ATOMP_FS channel:0x00 frame:6 vi_tstamp:1949023419 data:0x00000000
     kworker/0:1-1428  [000] ...1  1844.751326: rtcpu_vinotify_handle_msg: tstamp:57783606123 tag:CHANSEL_LOAD_FRAMED channel:0x20 frame:6 vi_tstamp:1949030403 data:0x08000000
     kworker/0:1-1428  [000] ...1  1844.751327: rtcpu_vinotify_handle_msg: tstamp:57783606220 tag:CHANSEL_LOAD_FRAMED channel:0x10 frame:6 vi_tstamp:1949030536 data:0x18000000
     kworker/0:1-1428  [000] ...1  1844.751328: rtcpu_vinotify_handle_msg: tstamp:57783606321 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:6 vi_tstamp:1949030661 data:0x28000000
     kworker/0:1-1428  [000] ...1  1844.751329: rtcpu_vinotify_handle_msg: tstamp:57783606413 tag:CHANSEL_LOAD_FRAMED channel:0x02 frame:6 vi_tstamp:1949030775 data:0x38000000
     kworker/0:1-1428  [000] ...1  1844.751329: rtcpu_vinotify_handle_msg: tstamp:57783889348 tag:CHANSEL_PXL_EOF channel:0x02 frame:6 vi_tstamp:1949312995 data:0x01df0002
     kworker/0:1-1428  [000] ...1  1844.751330: rtcpu_vinotify_handle_msg: tstamp:57783889450 tag:CHANSEL_PXL_EOF channel:0x03 frame:6 vi_tstamp:1949312995 data:0x01df0002
     kworker/0:1-1428  [000] ...1  1844.751331: rtcpu_vinotify_handle_msg: tstamp:57783889549 tag:CHANSEL_PXL_EOF channel:0x01 frame:6 vi_tstamp:1949312996 data:0x01df0002
     kworker/0:1-1428  [000] ...1  1844.751332: rtcpu_vinotify_handle_msg: tstamp:57783889648 tag:CHANSEL_PXL_EOF channel:0x00 frame:6 vi_tstamp:1949312996 data:0x01df0002
20

It doesn’t seem like this problem anymore. From the complete camera trace log, I didn’t find anything similar to what you mentioned above…

21

hello 305248199,

those shared logs (in comment #19) did not failures, but the expected messages when you received MIPI signaling on CSI channel correctly.

22

I don’t seem to have received the (in comment #19) log. I received it from the first floor