TX2 CSI MIPI debug messages

Hi,

I am trying to debug what’s going wrong while the TX2 is handling an incoming MIPI stream.

With the debugging info I find in https://elinux.org/Jetson_TX2_Camera_BringUp I am able to see the following during the reception:

          v4l_id-7828  [000] ....    68.667582: tegra_channel_open: vi-output, ov10640 9-0049
      v4l_id-7828  [000] ....    68.669966: tegra_channel_set_power: ov10640 9-0049 : 0x1
      v4l_id-7828  [000] ....    68.669977: camera_common_s_power: status : 0x1
      v4l_id-7828  [000] ....    68.670038: tegra_channel_set_power: 150c0000.nvcsi--6 : 0x1
      v4l_id-7828  [000] ....    68.670042: csi_s_power: enable : 0x1
      v4l_id-7828  [002] ....    68.675702: tegra_channel_close: vi-output, ov10640 9-0049
      v4l_id-7828  [002] ....    68.675714: tegra_channel_set_power: ov10640 9-0049 : 0x0
      v4l_id-7828  [002] ....    68.675725: camera_common_s_power: status : 0x0
      v4l_id-7828  [001] ....    68.675829: tegra_channel_set_power: 150c0000.nvcsi--6 : 0x0
      v4l_id-7828  [001] ....    68.675835: csi_s_power: enable : 0x0
    v4l2-ctl-7837  [002] ....    76.988819: tegra_channel_open: vi-output, ov10640 9-0049
    v4l2-ctl-7837  [002] ....    76.989983: tegra_channel_set_power: ov10640 9-0049 : 0x1
    v4l2-ctl-7837  [002] ....    76.989994: camera_common_s_power: status : 0x1
    v4l2-ctl-7837  [002] ....    76.990057: tegra_channel_set_power: 150c0000.nvcsi--6 : 0x1
    v4l2-ctl-7837  [002] ....    76.990060: csi_s_power: enable : 0x1
    v4l2-ctl-7837  [002] ....    76.999431: tegra_channel_capture_setup: vnc_id 0 W 1280 H 1080 fmt 20
 vi-output, ov10-7838  [000] ....    76.999701: tegra_channel_set_stream: enable : 0x1
 vi-output, ov10-7838  [001] ....    77.002156: tegra_channel_set_stream: 150c0000.nvcsi--6 : 0x1
 vi-output, ov10-7838  [001] ....    77.002162: csi_s_stream: enable : 0x1
 vi-output, ov10-7838  [001] ....    77.002201: tegra_channel_set_stream: ov10640 9-0049 : 0x1
     kworker/2:0-24    [002] ....    77.029002: rtos_queue_peek_from_isr_failed: tstamp:2774369496 queue:0x0b4b4500
     kworker/2:0-24    [002] ....    77.029006: rtcpu_start: tstamp:2774372588
...
 vi-output, ov10-7838  [001] ....    78.577076: tegra_channel_capture_setup: vnc_id 0 W 1280 H 1080 fmt 20
 vi-output, ov10-7838  [001] ....    78.577120: tegra_channel_capture_frame: sof:-549620696288.-266827611008

Note the tegra_channel_capture_frame: sof:-549620696288.-266827611008

The timestamp/argument after the SOF is weird.
In a working scenario, it looks like this:

    v4l2-ctl-7157  [002] ....   162.442877: tegra_channel_open: vi-output, ov10640 9-0049
    v4l2-ctl-7157  [002] ....   162.444041: tegra_channel_set_power: ov10640 9-0049 : 0x1
    v4l2-ctl-7157  [002] ....   162.444053: camera_common_s_power: status : 0x1
    v4l2-ctl-7157  [002] ....   162.444132: tegra_channel_set_power: 150c0000.nvcsi--6 : 0x1
    v4l2-ctl-7157  [002] ....   162.444135: csi_s_power: enable : 0x1
    v4l2-ctl-7157  [002] ....   162.453027: tegra_channel_capture_setup: vnc_id 0 W 1280 H 1080 fmt 20
 vi-output, ov10-7158  [000] ....   162.453221: tegra_channel_set_stream: enable : 0x1
 vi-output, ov10-7158  [001] ....   162.459202: tegra_channel_set_stream: 150c0000.nvcsi--6 : 0x1
 vi-output, ov10-7158  [001] ....   162.459208: csi_s_stream: enable : 0x1
 vi-output, ov10-7158  [001] ....   162.459247: tegra_channel_set_stream: ov10640 9-0049 : 0x1
     kworker/2:0-24    [002] ....   162.497559: rtos_queue_peek_from_isr_failed: tstamp:5446077303 queue:0x0b4b4500
     kworker/2:0-24    [002] ....   162.497565: rtcpu_start: tstamp:5446079353
..
 vi-output, ov10-7158  [001] ....   163.732700: tegra_channel_capture_frame: sof:163.366997691
 vi-output, ov10-7158  [001] ....   163.765097: tegra_channel_capture_frame: sof:163.399423195
     kworker/2:0-24    [002] ....   163.785658: rtos_queue_peek_from_isr_failed: tstamp:5486077687 queue:0x0b4b4500
     kworker/2:0-24    [002] ....   163.785675: rtcpu_vinotify_event: tstamp:5486086151 tag:CHANSEL_PXL_SOF channel:0x00 frame:1 vi_tstamp:5486085655 data:0x00000001
     kworker/2:0-24    [002] ....   163.785684: rtcpu_vinotify_event: tstamp:5486086316 tag:ATOMP_FS channel:0x00 frame:1 vi_tstamp:5486085659 data:0x00000000
     kworker/2:0-24    [002] ....   163.785691: rtcpu_vinotify_event: tstamp:5486093352 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1 vi_tstamp:5486092974 data:0x08000000
     kworker/2:0-24    [002] ....   163.785698: rtcpu_vinotify_event: tstamp:5486742676 tag:CHANSEL_PXL_EOF channel:0x00 frame:1 vi_tstamp:5486741999 data:0x04370002
     kworker/2:0-24    [002] ....   163.785705: rtcpu_vinotify_event: tstamp:5486742793 tag:ATOMP_FE channel:0x00 frame:1 vi_tstamp:5486742025 data:0x00000000
     kworker/2:0-24    [002] ....   163.785713: rtcpu_vinotify_event: tstamp:5487099467 tag:CHANSEL_PXL_SOF channel:0x00 frame:2 vi_tstamp:5487098952 data:0x00000001
     kworker/2:0-24    [002] ....   163.785720: rtcpu_vinotify_event: tstamp:5487099629 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:5487098956 data:0x00000000
     kworker/2:0-24    [002] ....   163.785727: rtcpu_vinotify_event: tstamp:5487105571 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:2 vi_tstamp:5487105205 data:0x08000000

Any idea what could be causing the system to detect the SOF, but discarding it? The traces are not telling much more useful.
Also, for some reason, in the non working case, it is always doing tegra_channel_capture_setup before tegra_channel_capture_frame, while in the working case it just says capture_frame twice.

Thanks for your reply!

Arnout

Figured it out.

This was being traced from tegra_channel_capture_frame_single_thread in nvidia/drivers/media/platform/tegra/camera/vi/vi2_fops.c presumably. At the end it said

	tegra_channel_ring_buffer(chan, vb, &ts, state);
trace_tegra_channel_capture_frame("sof", ts);
return 0;

Basically if the ringbuffer function failed, the timestamp was bogus.
There was no frame being detected on the mipi line, NO SOF detected. This was due to a bad VC id I was sending.
=> Fixed now