How to obtain more information from PXL_SOF syncpt timeout! err = -11 error

I’m currently connecting a camera with an FPGA to the TX2. Actually, the FPGA is generating an image of 1920x1080 at 50Hz in RAW10 format and sending it through the CSI bus (in a 4 lane configuration) to the TX2. Anyway, when I try to display that image in the TX2, I get the following error:

[  +0,202473] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  +0,006448] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel

I’ve searched in other posts, but I don’t see the way to get more information to know why it may be failing. The parameters in the device tree are set as follows:

mclk_khz = "1200000";
num_lanes = "4";
tegra_sinterface = "serial_a";
phy_mode = "DPHY";
discontinuous_clk = "no";
dpcm_enable = "false";
cil_settletime = "0";

csi_pixel_bit_depth = "10";
mode_type = "bayer";
pixel_phase = "rggb";
active_w = "1920";
active_h = "1080";
readout_orientation = "0";
line_length = "1920";
inherent_gain = "1";
pix_clk_hz = "480000000";

embedded_metadata_height = "0";

The clock is actually at 600MHz, so as far as I know, the mclk_khz parameter must be set to 1.2GHz considering it is DDR.

Regarding the line_length, as the image is generated and sent direcly, there are no dummy pixels so I guess it must have the same value as active_w.

The pipeline I use to get the image is the following, to get RAW data bypassing the ISP:

v4l2-ctl -d /dev/video0 --set-fmt-video=width=1920,height=1080,pixelformat=RG10 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=100

As I’m bypassing the ISP, are the parameters csi_pixel_bit_depth, mode_type, pixel_phase… relevant?

Moreover, I’d like to know if I have misunderstood any parameter and it should be set to another value, and also if there is some way, as I said before, to get more information of why the image is not being received. I’ve thought in changing the kernel error log level, but I don’t think this will make a difference.

Thanks in advance!

UPDATE [2020/01/28 16:10 CET]

I’ve achieved to get another error. Watching with the oscilloscope, all the signals were looking OK but one, which was not good due tho a physical defect. We fixed that, and now the error is giving more information:

[  +0,203248] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  +0,006516] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[  +0,012051] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x0000000e
[  +0,008840] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC1 = 0x0000000a
[  +0,008840] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC2 = 0x0000000a
[  +0,008850] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00010aae
[  +0,008570] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00010aae

The signals look like this:

Data signals:

Clock signal:

I will keep updating if I get any new.

UPDATE [2020/01/28 16:40 CET]

I’m adding trace messages for further information

# tracer: nop
#
# entries-in-buffer/entries-written: 241/241   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/5:2-10405 [005] ....  4178.490457: rtos_queue_peek_from_isr_failed: tstamp:130948812449 queue:0x0b4b4500
     kworker/5:2-10405 [005] ....  4178.490462: rtcpu_start: tstamp:130948813409
     kworker/5:2-10405 [005] ....  4178.490464: rtos_queue_send_from_isr_failed: tstamp:130948822219 queue:0x0b4a7258
     kworker/5:2-10405 [005] ....  4178.490465: rtos_queue_send_from_isr_failed: tstamp:130948822327 queue:0x0b4aad68
     kworker/5:2-10405 [005] ....  4178.490466: rtos_queue_send_from_isr_failed: tstamp:130948822433 queue:0x0b4ac998
     kworker/5:2-10405 [005] ....  4178.490467: rtos_queue_send_from_isr_failed: tstamp:130948822539 queue:0x0b4ae518
     kworker/5:2-10405 [005] ....  4178.490467: rtos_queue_send_from_isr_failed: tstamp:130948822644 queue:0x0b4af2d8
     kworker/5:2-10405 [005] ....  4178.490468: rtos_queue_send_from_isr_failed: tstamp:130948822749 queue:0x0b4b0098
     kworker/5:2-10405 [005] ....  4178.490469: rtos_queue_send_from_isr_failed: tstamp:130948822854 queue:0x0b4b0e58
     kworker/5:2-10405 [005] ....  4178.490469: rtos_queue_send_from_isr_failed: tstamp:130948822959 queue:0x0b4b1c18
     kworker/5:2-10405 [005] ....  4178.490471: rtos_queue_send_failed: tstamp:130948823430 queue:0x0b4a7258
     kworker/5:2-10405 [005] ....  4178.490471: rtos_queue_send_from_isr_failed: tstamp:130948825943 queue:0x0b4a7258
     kworker/5:2-10405 [005] ....  4178.490472: rtos_queue_send_from_isr_failed: tstamp:130948826058 queue:0x0b4aad68
     kworker/5:2-10405 [005] ....  4178.490473: rtos_queue_send_from_isr_failed: tstamp:130948826165 queue:0x0b4ac998
     kworker/5:2-10405 [005] ....  4178.490473: rtos_queue_send_from_isr_failed: tstamp:130948826271 queue:0x0b4ae518
     kworker/5:2-10405 [005] ....  4178.490474: rtos_queue_send_from_isr_failed: tstamp:130948826375 queue:0x0b4af2d8
     kworker/5:2-10405 [005] ....  4178.490475: rtos_queue_send_from_isr_failed: tstamp:130948826480 queue:0x0b4b0098
     kworker/5:2-10405 [005] ....  4178.490476: rtos_queue_send_from_isr_failed: tstamp:130948826585 queue:0x0b4b0e58
     kworker/5:2-10405 [005] ....  4178.490476: rtos_queue_send_from_isr_failed: tstamp:130948826690 queue:0x0b4b1c18
     kworker/5:2-10405 [005] ....  4178.490477: rtos_queue_send_failed: tstamp:130948827626 queue:0x0b4a7258
     kworker/5:2-10405 [005] ....  4178.490479: rtcpu_vinotify_event: tstamp:130949135367 tag:CSIMUX_STREAM channel:0xff frame:1 vi_tstamp:130949134788 data:0x00000001
     kworker/5:2-10405 [005] ....  4178.490479: rtcpu_vinotify_event: tstamp:130949135583 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:130949134887 data:0x00000001
     kworker/5:2-10405 [005] ....  4178.490480: rtcpu_vinotify_event: tstamp:130949138576 tag:CSIMUX_STREAM channel:0xff frame:2 vi_tstamp:130949138205 data:0x00000001
     kworker/5:2-10405 [005] ....  4178.490481: rtcpu_vinotify_event: tstamp:130949144131 tag:CHANSEL_PXL_SOF channel:0x00 frame:1822 vi_tstamp:130949143430 data:0x00000001
     kworker/5:2-10405 [005] ....  4178.490481: rtcpu_vinotify_event: tstamp:130949144297 tag:ATOMP_FS channel:0x00 frame:1822 vi_tstamp:130949143433 data:0x00000000
     kworker/5:2-10405 [005] ....  4178.490482: rtcpu_vinotify_event: tstamp:130949144415 tag:CHANSEL_FAULT channel:0x00 frame:1822 vi_tstamp:130949143536 data:0x00000200
     kworker/5:2-10405 [005] ....  4178.490482: rtcpu_vinotify_event: tstamp:130949144869 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1822 vi_tstamp:130949144551 data:0x08000000
     kworker/5:2-10405 [005] ....  4178.490483: rtcpu_vinotify_event: tstamp:130949145708 tag:CHANSEL_FAULT_FE channel:0x01 frame:1822 vi_tstamp:130949145138 data:0x00000001
     kworker/5:2-10405 [005] ....  4178.490483: rtcpu_vinotify_event: tstamp:130949145845 tag:ATOMP_FE channel:0x00 frame:1822 vi_tstamp:130949145141 data:0x00000000
    ......
     kworker/5:2-10405 [005] ....  4179.050530: rtos_queue_send_from_isr_failed: tstamp:130965589929 queue:0x0b4b0e58
     kworker/5:2-10405 [005] ....  4179.050532: rtos_queue_send_from_isr_failed: tstamp:130965590034 queue:0x0b4b1c18
     kworker/5:2-10405 [005] ....  4179.050533: rtos_queue_send_failed: tstamp:130965591179 queue:0x0b4a7258
     kworker/5:2-10405 [005] ....  4179.050537: rtcpu_vinotify_event: tstamp:130965592129 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:130965590834 data:0x00000001
     kworker/5:2-10405 [005] ....  4179.050538: rtcpu_vinotify_event: tstamp:130965592813 tag:CSIMUX_STREAM channel:0xff frame:1 vi_tstamp:130965592445 data:0x00000001
     kworker/5:2-10405 [005] ....  4179.050540: rtcpu_vinotify_event: tstamp:130965596227 tag:CSIMUX_STREAM channel:0xff frame:2 vi_tstamp:130965595861 data:0x00000001
     kworker/5:2-10405 [005] ....  4179.050541: rtcpu_vinotify_event: tstamp:130965610200 tag:CSIMUX_FRAME channel:0x8c frame:1897 vi_tstamp:130965609836 data:0x00000400
     kworker/5:2-10405 [005] ....  4179.050542: rtcpu_vinotify_event: tstamp:130965614175 tag:CHANSEL_PXL_SOF channel:0x00 frame:1897 vi_tstamp:130965613471 data:0x00000001
     kworker/5:2-10405 [005] ....  4179.050543: rtcpu_vinotify_event: tstamp:130965614339 tag:ATOMP_FS channel:0x00 frame:1897 vi_tstamp:130965613474 data:0x00000000
     kworker/5:2-10405 [005] ....  4179.050544: rtcpu_vinotify_event: tstamp:130965614456 tag:CHANSEL_FAULT channel:0x00 frame:1897 vi_tstamp:130965613577 data:0x00000200
     kworker/5:2-10405 [005] ....  4179.050546: rtcpu_vinotify_event: tstamp:130965614907 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1897 vi_tstamp:130965614590 data:0x08000000
     kworker/5:2-10405 [005] ....  4179.050547: rtcpu_vinotify_event: tstamp:130965616486 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1897 vi_tstamp:130965616118 data:0x08000000
     kworker/5:2-10405 [005] ....  4179.050548: rtcpu_vinotify_event: tstamp:130965621646 tag:CSIMUX_FRAME channel:0x00 frame:1897 vi_tstamp:130965620943 data:0x000004a0
     kworker/5:2-10405 [005] ....  4179.050549: rtcpu_vinotify_event: tstamp:130965621779 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:1897 vi_tstamp:130965620943 data:0x00000001
     kworker/5:2-10405 [005] ....  4179.050550: rtcpu_vinotify_event: tstamp:130965621918 tag:ATOMP_FE channel:0x00 frame:1897 vi_tstamp:130965620946 data:0x00000000

Seems this post is showing this error too, although it is not solved.

UPDATE [2020/01/28 17:55 CET]

I realized that the FPGA was generating images in RAW8 format, instead of RAW10, so as suggested in this post, I’ve modified it, and now many errors are not shown anymore, remaining the following ones.
Kernel message errors:

[  +0,213324] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[  +0,006413] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[  +0,010752] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00010000
[  +0,007944] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00010000

Trace messages:

kworker/5:0-11810 [005] ....  7985.152819: rtos_queue_peek_from_isr_failed: tstamp:249905660856 queue:0x0b4b4500
kworker/5:0-11810 [005] ....  7985.152825: rtcpu_start: tstamp:249905662189
kworker/5:0-11810 [005] ....  7985.152827: rtos_queue_send_from_isr_failed: tstamp:249905670889 queue:0x0b4a7258
kworker/5:0-11810 [005] ....  7985.152828: rtos_queue_send_from_isr_failed: tstamp:249905670999 queue:0x0b4aad68
kworker/5:0-11810 [005] ....  7985.152829: rtos_queue_send_from_isr_failed: tstamp:249905671109 queue:0x0b4ac998
kworker/5:0-11810 [005] ....  7985.152830: rtos_queue_send_from_isr_failed: tstamp:249905671215 queue:0x0b4ae518
kworker/5:0-11810 [005] ....  7985.152831: rtos_queue_send_from_isr_failed: tstamp:249905671320 queue:0x0b4af2d8
kworker/5:0-11810 [005] ....  7985.152832: rtos_queue_send_from_isr_failed: tstamp:249905671425 queue:0x0b4b0098
kworker/5:0-11810 [005] ....  7985.152833: rtos_queue_send_from_isr_failed: tstamp:249905671533 queue:0x0b4b0e58
kworker/5:0-11810 [005] ....  7985.152833: rtos_queue_send_from_isr_failed: tstamp:249905671638 queue:0x0b4b1c18
kworker/5:0-11810 [005] ....  7985.152835: rtos_queue_send_failed: tstamp:249905672096 queue:0x0b4a7258

UPDATE [2020/01/29 15:30 CET]

Since I’ve progressed with this error, and actually the problem I’m getting is different, I’m moving the problem to a new post.
Summing up, initially I was getting PXL_SOF syncpt timeout! err = -11 error only because there was actually no data being sent, as one of the data lanes was not working correctly. After fixing the hardware part, more informative errors appeared, which some of them can be seen in this post.

The trace show the short line and short frame. Please adjust the resolution in the device tree to try.

kworker/5:2-10405 [005] ....  4179.050544: rtcpu_vinotify_event: tstamp:130965614456 tag:CHANSEL_FAULT channel:0x00 frame:1897 vi_tstamp:130965613577 data:0x00000200
     kworker/5:2-10405 [005] ....  4179.050546: rtcpu_vinotify_event: tstamp:130965614907 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1897 vi_tstamp:130965614590 data:0x08000000
     kworker/5:2-10405 [005] ....  4179.050547: rtcpu_vinotify_event: tstamp:130965616486 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:1897 vi_tstamp:130965616118 data:0x08000000
     kworker/5:2-10405 [005] ....  4179.050548: rtcpu_vinotify_event: tstamp:130965621646 tag:CSIMUX_FRAME channel:0x00 frame:1897 vi_tstamp:130965620943 data:0x000004a0
     kworker/5:2-10405 [005] ....  4179.050549: rtcpu_vinotify_event: tstamp:130965621779 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:1897 vi_tstamp:130965620943 data:0x00000001