VIFALC_TDSTATE with IMX297 sensor and CTI Boson carrier

Robotics & Edge Computing Jetson & Embedded Systems Jetson Xavier NX
1

I am not able to start a stream on a Xavier NX board running JP 5.1.2/L4T35.4.1. The camera sensor is an IMX297 from The Imaging Source and the carrier board is a ConnectTech Boson. The following trace is produced:

root@nvidia-desktop:/home/nvidia# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 77/77   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/0:9-146     [000] ....    62.686864: rtcpu_string: tstamp:2643395416 id:0x04010000 str:"NVCSILP clock rate = 204000000 Hz.
"
     kworker/0:9-146     [000] ....    62.686923: rtcpu_dbg_set_loglevel: tstamp:2643422261 old:0 new:2
     kworker/0:9-146     [000] ....    68.854874: rtcpu_string: tstamp:2836501330 id:0x04010000 str:"VM0 deactivating."
        v4l2-ctl-2370    [001] ....    82.990569: tegra_channel_open: vi-output, tis_imx29x_mono 30-0
        v4l2-ctl-2370    [001] ....    82.995597: tegra_channel_set_power: tis_imx29x_mono 30-001a : 0x1
        v4l2-ctl-2370    [001] ....    82.995608: camera_common_s_power: status : 0x1
        v4l2-ctl-2370    [001] ....    82.995645: tegra_channel_set_power: 13e10000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2370    [001] ....    82.995647: csi_s_power: enable : 0x1
        v4l2-ctl-2370    [001] ....    82.996376: tegra_channel_capture_setup: vnc_id 0 W 728 H 544 fmt c4
        v4l2-ctl-2370    [000] ....    83.004046: tegra_channel_set_stream: enable : 0x1
        v4l2-ctl-2370    [000] ....    83.007156: tegra_channel_set_stream: 13e10000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2370    [000] ....    83.007160: csi_s_stream: enable : 0x1
        v4l2-ctl-2370    [000] ....    83.007928: tegra_channel_set_stream: tis_imx29x_mono 30-001a : 0x1
     kworker/0:9-146     [000] ....    83.046786: rtcpu_string: tstamp:3279905356 id:0x04010000 str:"VM0 activating."
     kworker/0:9-146     [000] ....    83.046789: rtcpu_string: tstamp:3279980193 id:0x04010000 str:"NVCSILP clock rate = 204000000 Hz.
"
     kworker/0:9-146     [000] ....    83.046804: rtcpu_string: tstamp:3280138204 id:0x04010000 str:"tegra_nvcsi_stream_set_config(vm0, stream=0, csi"
     kworker/0:9-146     [000] ....    83.046808: rtcpu_string: tstamp:3280138335 id:0x04010000 str:"=0)
"
     kworker/0:9-146     [000] ....    83.046815: rtcpu_string: tstamp:3280138890 id:0x04010000 str:"MIPI clock = 1485000 kHz, tHS-SETTLE = 0, tCLK-S"
     kworker/0:9-146     [000] ....    83.046816: rtcpu_string: tstamp:3280139006 id:0x04010000 str:"ETTLE = 0
"
     kworker/0:9-146     [000] ....    83.046823: rtcpu_string: tstamp:3280139297 id:0x04010000 str:"===== NVCSI Stream Configuration =====
"
     kworker/0:9-146     [000] ....    83.046830: rtcpu_string: tstamp:3280139630 id:0x04010000 str:"stream_id: PP 0, csi_port: PORT A
"
     kworker/0:9-146     [000] ....    83.046836: rtcpu_string: tstamp:3280139970 id:0x04010000 str:"Brick: PHY 0, Mode: D-PHY
"
     kworker/0:9-146     [000] ....    83.046842: rtcpu_string: tstamp:3280140369 id:0x04010000 str:"Partition: CIL A, LP bypass: Enabled, Lanes: 1
"
     kworker/0:9-146     [000] ....    83.046848: rtcpu_string: tstamp:3280140596 id:0x04010000 str:"Clock information:
"
     kworker/0:9-146     [000] ....    83.046854: rtcpu_string: tstamp:3280141037 id:0x04010000 str:"MIPI clock rate: 1485.00 MHz
"
     kworker/0:9-146     [000] ....    83.046859: rtcpu_string: tstamp:3280141368 id:0x04010000 str:"T_HS settle: 0, T_CLK settle: 0
"
     kworker/0:9-146     [000] ....    83.046865: rtcpu_string: tstamp:3280141671 id:0x04010000 str:"======================================
"
     kworker/0:9-146     [000] ....    83.046871: rtcpu_string: tstamp:3280145561 id:0x04010000 str:"tegra_nvcsi_stream_open(vm0, stream=0, csi=0)
"
     kworker/0:9-146     [000] ....    83.046877: rtcpu_string: tstamp:3280146425 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_A_"
     kworker/0:9-146     [000] ....    83.046878: rtcpu_string: tstamp:3280146539 id:0x04010000 str:"SW_RESET_0 = 00000001
"
     kworker/0:9-146     [000] ....    83.046884: rtcpu_string: tstamp:3280147047 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_B_"
     kworker/0:9-146     [000] ....    83.046886: rtcpu_string: tstamp:3280147161 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:9-146     [000] ....    83.046892: rtcpu_string: tstamp:3280147819 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_0_LM_SW_RESET"
     kworker/0:9-146     [000] ....    83.046893: rtcpu_string: tstamp:3280147930 id:0x04010000 str:"_0 = 00000001
"
     kworker/0:9-146     [000] ....    83.046899: rtcpu_string: tstamp:3280154178 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_0_LM_SW_RESET"
     kworker/0:9-146     [000] ....    83.046900: rtcpu_string: tstamp:3280154292 id:0x04010000 str:"_0 = 00000000
"
     kworker/0:9-146     [000] ....    83.046907: rtcpu_string: tstamp:3280154809 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 18
"
     kworker/0:9-146     [000] ....    83.046938: rtcpu_string: tstamp:3280155177 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 18
"
     kworker/0:9-146     [000] ....    83.046946: rtcpu_string: tstamp:3280155534 id:0x04010000 str:"nvcsi_calc_tclk_settle tclk_settle 33
"
     kworker/0:9-146     [000] ....    83.046952: rtcpu_string: tstamp:3280156134 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_A_"
     kworker/0:9-146     [000] ....    83.046954: rtcpu_string: tstamp:3280156248 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:9-146     [000] ....    83.046960: rtcpu_string: tstamp:3280156753 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_0_NVCSI_CIL_B_"
     kworker/0:9-146     [000] ....    83.046961: rtcpu_string: tstamp:3280156864 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:9-146     [000] ....    83.046967: rtcpu_string: tstamp:3280157492 id:0x04010000 str:"Deskew setup message sent for port 0 num_lane 1
"
     kworker/0:9-146     [000] ....    83.046974: rtcpu_vinotify_event: tstamp:3280562513 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:104961269312 data:0xcd9ce50010000000
     kworker/0:9-146     [000] ....    83.046975: rtcpu_vinotify_event: tstamp:3280562689 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:104961281120 data:0x0000000031000001
     kworker/0:9-146     [000] ....    83.046976: rtcpu_vinotify_event: tstamp:3280562863 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:104961336224 data:0xcd9ce20010000000
     kworker/0:9-146     [000] ....    83.046977: rtcpu_vinotify_event: tstamp:3280563016 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:104961348160 data:0x0000000031000002
     kworker/0:9-146     [000] ....    83.158859: rtcpu_string: tstamp:3284040770 id:0x04010000 str:"ISR PHY 0 CIL_A 0x1
"
     kworker/0:9-146     [000] ....    83.158884: rtcpu_nvcsi_intr: tstamp:3284040456 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001
 vi-output, tis_-2372    [001] ....    85.734003: tegra_channel_capture_setup: vnc_id 0 W 728 H 544 fmt c4
     kworker/0:9-146     [000] ....    85.790873: rtcpu_vinotify_event: tstamp:3365741255 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:107691935040 data:0xcd9ce50010000000
     kworker/0:9-146     [000] ....    85.790877: rtcpu_vinotify_event: tstamp:3365741426 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:107691977792 data:0x0000000031000001
     kworker/0:9-146     [000] ....    85.790878: rtcpu_vinotify_event: tstamp:3365741601 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:107692671584 data:0xcd9ce20010000000
     kworker/0:9-146     [000] ....    85.790879: rtcpu_vinotify_event: tstamp:3365741752 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:107692715008 data:0x0000000031000002
 vi-output, tis_-2372    [003] ....    88.293985: tegra_channel_capture_setup: vnc_id 0 W 728 H 544 fmt c4
     kworker/0:9-146     [000] ....    88.310871: rtcpu_vinotify_event: tstamp:3445494727 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:110251976320 data:0xcd9ce50010000000
     kworker/0:9-146     [000] ....    88.310875: rtcpu_vinotify_event: tstamp:3445494886 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:110252034080 data:0x0000000031000001
     kworker/0:9-146     [000] ....    88.310877: rtcpu_vinotify_event: tstamp:3445495063 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:110252052608 data:0xcd9ce20010000000
     kworker/0:9-146     [000] ....    88.310878: rtcpu_vinotify_event: tstamp:3445495211 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:110252113056 data:0x0000000031000002
        v4l2-ctl-2370    [003] ....    88.748574: tegra_channel_close: vi-output, tis_imx29x_mono 30-0
 vi-output, tis_-2372    [003] ....    90.853950: tegra_channel_capture_setup: vnc_id 0 W 728 H 544 fmt c4
        v4l2-ctl-2370    [003] ....    90.854629: tegra_channel_set_stream: enable : 0x0
        v4l2-ctl-2370    [003] ....    90.854632: tegra_channel_set_stream: tis_imx29x_mono 30-001a : 0x0
        v4l2-ctl-2370    [000] ....    90.855966: tegra_channel_set_stream: 13e10000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2370    [000] ....    90.855971: csi_s_stream: enable : 0x0
        v4l2-ctl-2370    [000] ....    90.861672: tegra_channel_set_power: tis_imx29x_mono 30-001a : 0x0
        v4l2-ctl-2370    [000] ....    90.861684: camera_common_s_power: status : 0x0
        v4l2-ctl-2370    [000] ....    90.861713: tegra_channel_set_power: 13e10000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2370    [000] ....    90.861716: csi_s_power: enable : 0x0
     kworker/0:9-146     [000] ....    90.886923: rtcpu_string: tstamp:3525571114 id:0x04010000 str:"ISR PHY 0 CIL_A 0x1
"
     kworker/0:9-146     [000] ....    90.886944: rtcpu_nvcsi_intr: tstamp:3525570814 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001
     kworker/0:9-146     [000] ....    90.886946: rtcpu_string: tstamp:3525571615 id:0x04010000 str:"ISR1 PHY 0 CIL_A status 21
"
     kworker/0:9-146     [000] ....    90.886954: rtcpu_nvcsi_intr: tstamp:3525570814 class:GLOBAL type:PHY_INTR1 phy:0 cil:0 st:0 vc:0 status:0x00000021
     kworker/0:9-146     [000] ....    90.886955: rtcpu_string: tstamp:3525590059 id:0x04010000 str:"ISR PHY 0 CIL_A 0x80000
"
     kworker/0:9-146     [000] ....    90.886963: rtcpu_nvcsi_intr: tstamp:3525589764 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00080000
     kworker/0:4-141     [000] ....    96.886914: rtcpu_string: tstamp:3713877112 id:0x04010000 str:"VM0 deactivating."

How should I decode this output?

3

Please consult with vendor for the supported.

Thanks

4

Yeah, I understand that. I have already contacted the two other vendors for support. In the meantime, I need support from Nvidia as well. Is there any information available about the Falcon?

I haven’t found any code in the kernel source that gives me any indication what the trace log entries mean. How do I decode these trace log messages?

For example, what does the data field in this log mean? What is TDSTATE in Falcon?

kworker/0:9-146     [000] ....    88.310878: rtcpu_vinotify_event: tstamp:3445495211 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:110252113056 data:0x0000000031000002
5

This is internal falcon message that tell the capture request already submitted.
Maybe you need to check the output signal by scope.
Below message tell the lane control error.

     kworker/0:9-146     [000] ....    90.886944: rtcpu_nvcsi_intr: tstamp:3525570814 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001
6

The camera is producing what appears to be a valid mipi output. Regarding the trace messages, is there some documentation that indicates what it means? The trace log contains various logs, and I would like to be able to understand all of them.

For example, the log you highlighted from the nvcsi interrupt. I have looked through the kernel source but I do not see where that is invoked so that I can understand what the status field of that log message means. Is that a status I can find in the source of the Nvidia kernel code or is that something coming from another processing domain?

7

Sorry to tell current don’t have document for it.

Thanks