Driver GMSL1 cameras using MAX9296, preview the cameras failed?

Hi NV_Team,

I’m using Xavier to driver GMSL1 cameras using MAX9296, but there is an error when preview the cameras. Can you help to check my csi log, and give me some advice about how to fix the problems? what about the CSIMUX_FRAME/CHANSEL_SHORT_FRAME/CHANSEL_FAULT means in the csi log and how to fix them by modifying the source code?

HW:
Xavier + MAX9296 + MAX96705/AR0147 (4Lanes, 1280x720@30fps)
SW:
JetPack4.5

DMESG Log
[   74.946063] ar0147yuv 30-001b: ar0147yuv_set_mode: mode index:0
[   74.946077] ar0147yuv 30-001b: ar0147yuv_start_streaming: start streaming
[   74.950552] [RCE] Configuring VI GoS.
[   74.950565] [RCE] VM GOS[#0] addr=0xc2100000
[   74.950590] [RCE] VM GOS[#1] addr=0xc2101000
[   74.950605] [RCE] VM GOS[#2] addr=0xc2102000
[   74.950612] [RCE] VM GOS[#3] addr=0xc2103000
[   74.950620] [RCE] VM GOS[#4] addr=0xc2104000
[   74.950627] [RCE] VM GOS[#5] addr=0xc2105000
[   74.950635] [RCE] vi5_hwinit: firmware CL2018101701 protocol version 2.2
[   74.950646] [RCE] VI GOS[#0] set to VM GOS[4] base 0xc2104000
[   74.977013] tegra194-vi5 15c10000.vi: corr_err: discarding frame 0, flags: 32, err_data 160
[   74.996468] tegra194-vi5 15c10000.vi: corr_err: discarding frame 0, flags: 0, err_data 64
[   77.658610] tegra194-vi5 15c10000.vi: no reply from camera processor
[   77.658752] tegra194-vi5 15c10000.vi: uncorr_err: request timed out after 2500 ms
[   77.658907] tegra194-vi5 15c10000.vi: err_rec: attempting to reset the capture channel
[   77.660708] tegra-capture-ivc ivc-bc00000.rtcpu:ivccontrol@3: No callback found for msg id: 0x39
[   77.660900] tegra-capture-ivc ivc-bc00000.rtcpu:ivccontrol@3: No callback found for msg id: 0x41
[   77.661037] tegra-capture-ivc ivc-bc00000.rtcpu:ivccontrol@3: No callback found for msg id: 0x37
[   77.661206] tegra194-vi5 15c10000.vi: err_rec: successfully reset the capture channel
[   77.698742] [RCE] Configuring VI GoS.
[   77.698759] [RCE] VM GOS[#0] addr=0xc2100000
[   77.698765] [RCE] VM GOS[#1] addr=0xc2101000
[   77.698771] [RCE] VM GOS[#2] addr=0xc2102000
[   77.698778] [RCE] VM GOS[#3] addr=0xc2103000
[   77.698784] [RCE] VM GOS[#4] addr=0xc2104000
[   77.698790] [RCE] VM GOS[#5] addr=0xc2105000


     kworker/0:2-1173  [000] ....    74.950641: rtcpu_string: tstamp:2913417487 id:0x04010000 str:"VI GOS[#0] set to VM GOS[4] base 0xc2104000
"
     kworker/0:2-1173  [000] ....    74.950649: rtcpu_vinotify_event: tstamp:2913794625 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3035086336 data:0x10000000
     kworker/0:2-1173  [000] ....    74.950650: rtcpu_vinotify_event: tstamp:2913794920 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3035090144 data:0x31000001
     kworker/0:2-1173  [000] ....    74.950651: rtcpu_vinotify_event: tstamp:2913795272 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3035091136 data:0x07020001
     kworker/0:2-1173  [000] ....    74.950651: rtcpu_vinotify_event: tstamp:2913795556 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3035146624 data:0x10000000
     kworker/0:2-1173  [000] ....    74.950652: rtcpu_vinotify_event: tstamp:2913795909 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3035150496 data:0x31000002
     kworker/0:2-1173  [000] ....    74.950652: rtos_queue_send_from_isr_failed: tstamp:2914212881 queue:0x0bcb41f8
     kworker/0:2-1173  [000] ....    74.950653: rtos_queue_send_from_isr_failed: tstamp:2914213020 queue:0x0bcb8a60
     kworker/0:2-1173  [000] ....    74.950669: rtos_queue_send_from_isr_failed: tstamp:2914213157 queue:0x0bcba5e0
     kworker/0:2-1173  [000] ....    74.950670: rtos_queue_send_from_isr_failed: tstamp:2914213294 queue:0x0bcbb3a0
     kworker/0:2-1173  [000] ....    74.950671: rtos_queue_send_from_isr_failed: tstamp:2914213427 queue:0x0bcbc160
     kworker/0:2-1173  [000] ....    75.010499: rtcpu_vinotify_error: tstamp:2915177225 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:2915171756 data:0x000000a0
     kworker/0:2-1173  [000] ....    75.010504: rtos_queue_send_from_isr_failed: tstamp:2915186801 queue:0x0bcb41f8
     kworker/0:2-1173  [000] ....    75.010506: rtos_queue_send_from_isr_failed: tstamp:2915186940 queue:0x0bcb8a60
     kworker/0:2-1173  [000] ....    75.010506: rtos_queue_send_from_isr_failed: tstamp:2915187080 queue:0x0bcba5e0
     kworker/0:2-1173  [000] ....    75.010507: rtos_queue_send_from_isr_failed: tstamp:2915187212 queue:0x0bcbb3a0
     kworker/0:2-1173  [000] ....    75.010508: rtos_queue_send_from_isr_failed: tstamp:2915187344 queue:0x0bcbc160
     kworker/0:2-1173  [000] ....    75.010509: rtcpu_vinotify_event: tstamp:2915259863 tag:FS channel:0x00 frame:0 vi_tstamp:2915171356 data:0x00000010
     kworker/0:2-1173  [000] ....    75.010510: rtcpu_vinotify_event: tstamp:2915260013 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:2915171358 data:0x00000000
     kworker/0:2-1173  [000] ....    75.010511: rtcpu_vinotify_event: tstamp:2915260140 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:2915171756 data:0x000000a0
     kworker/0:2-1173  [000] ....    75.010511: rtcpu_vinotify_event: tstamp:2915260281 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:0 vi_tstamp:2915171756 data:0x01000000
     kworker/0:2-1173  [000] ....    75.010512: rtcpu_vinotify_event: tstamp:2915260408 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3091204384 data:0x01020001
     kworker/0:2-1173  [000] ....    75.010513: rtcpu_vinotify_event: tstamp:2915260548 tag:FS channel:0x00 frame:0 vi_tstamp:2915171756 data:0x00000010
     kworker/0:2-1173  [000] ....    75.010513: rtcpu_vinotify_event: tstamp:2915260677 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:2915171759 data:0x00000000
     kworker/0:2-1173  [000] ....    75.010514: rtcpu_vinotify_event: tstamp:2915260818 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:2915171759 data:0x00000000
     kworker/0:2-1173  [000] ....    75.010514: rtcpu_vinotify_event: tstamp:2915260944 tag:CHANSEL_PXL_SOF channel:0x23 frame:0 vi_tstamp:2915172497 data:0x00000001
     kworker/0:2-1173  [000] ....    75.010515: rtcpu_vinotify_event: tstamp:2915261085 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3091247040 data:0x08020001
     kworker/0:2-1173  [000] ....    75.010516: rtcpu_vinotify_event: tstamp:2915784519 tag:CHANSEL_PXL_EOF channel:0x23 frame:0 vi_tstamp:2915779732 data:0x02cf0002
     kworker/0:2-1173  [000] ....    75.010516: rtos_queue_send_from_isr_failed: tstamp:2915795499 queue:0x0bcb41f8
     kworker/0:2-1173  [000] ....    75.010517: rtos_queue_send_from_isr_failed: tstamp:2915795638 queue:0x0bcb8a60
     kworker/0:2-1173  [000] ....    75.010517: rtos_queue_send_from_isr_failed: tstamp:2915795778 queue:0x0bcba5e0
     kworker/0:2-1173  [000] ....    75.010518: rtos_queue_send_from_isr_failed: tstamp:2915795910 queue:0x0bcbb3a0
     kworker/0:2-1173  [000] ....    75.010519: rtos_queue_send_from_isr_failed: tstamp:2915796044 queue:0x0bcbc160
     kworker/0:2-1173  [000] ....    75.010520: rtos_queue_peek_from_isr_failed: tstamp:2916095163 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    75.066520: rtcpu_vinotify_event: tstamp:2916236482 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3110649344 data:0x07020002
     kworker/0:2-1173  [000] ....    75.066524: rtcpu_vinotify_event: tstamp:2916236613 tag:ATOMP_FRAME_DONE channel:0x23 frame:0 vi_tstamp:2915779755 data:0x00000000
     kworker/0:2-1173  [000] ....    75.066524: rtcpu_vinotify_event: tstamp:2916236758 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3110655104 data:0x02020002
     kworker/0:2-1173  [000] ....    75.066525: rtcpu_vinotify_event: tstamp:2916236880 tag:CHANSEL_FAULT channel:0x23 frame:0 vi_tstamp:2915780187 data:0x02d00040
     kworker/0:2-1173  [000] ....    75.066526: rtcpu_vinotify_event: tstamp:2916237022 tag:RESERVED_19 channel:0x23 frame:0 vi_tstamp:3110671872 data:0x01020002
     kworker/0:2-1173  [000] ....    75.066526: rtcpu_vinotify_event: tstamp:2916237145 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3110828832 data:0x10000000
     kworker/0:2-1173  [000] ....    75.066527: rtcpu_vinotify_event: tstamp:2916237286 tag:RESERVED_18 channel:0x23 frame:0 vi_tstamp:3110871840 data:0x31000003
     kworker/0:2-1173  [000] ....    75.178547: rtos_queue_peek_from_isr_failed: tstamp:2921095161 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    75.346505: rtos_queue_peek_from_isr_failed: tstamp:2926095159 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    75.514552: rtos_queue_peek_from_isr_failed: tstamp:2931095159 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    75.682570: rtos_queue_peek_from_isr_failed: tstamp:2936095158 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    75.850531: rtos_queue_peek_from_isr_failed: tstamp:2941095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.018530: rtos_queue_peek_from_isr_failed: tstamp:2946095163 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.130544: rtos_queue_peek_from_isr_failed: tstamp:2951095161 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.298527: rtos_queue_peek_from_isr_failed: tstamp:2956095159 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.466586: rtos_queue_peek_from_isr_failed: tstamp:2961095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.634560: rtos_queue_peek_from_isr_failed: tstamp:2966095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.802585: rtos_queue_peek_from_isr_failed: tstamp:2971095159 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    76.970592: rtos_queue_peek_from_isr_failed: tstamp:2976095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    77.138597: rtos_queue_peek_from_isr_failed: tstamp:2981095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    77.250576: rtos_queue_peek_from_isr_failed: tstamp:2986095159 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    77.418591: rtos_queue_peek_from_isr_failed: tstamp:2991095162 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    77.586643: rtos_queue_peek_from_isr_failed: tstamp:2996095158 queue:0x0bcbcf78
     kworker/0:2-1173  [000] ....    77.698647: rtos_queue_send_from_isr_failed: tstamp:2998994184 queue:0x0bcb41f8
     kworker/0:2-1173  [000] ....    77.698650: rtos_queue_send_from_isr_failed: tstamp:2998994327 queue:0x0bcb8a60
     kworker/0:2-1173  [000] ....    77.698651: rtos_queue_send_from_isr_failed: tstamp:2998994467 queue:0x0bcba5e0
     kworker/0:2-1173  [000] ....    77.698652: rtos_queue_send_from_isr_failed: tstamp:2998994602 queue:0x0bcbb3a0
     kworker/0:2-1173  [000] ....    77.698653: rtos_queue_send_from_isr_failed: tstamp:2998994734 queue:0x0bcbc160
     kworker/0:2-1173  [000] ....    77.698653: rtos_queue_send_from_isr_failed: tstamp:2999034665 queue:0x0bcb41f8
     kworker/0:2-1173  [000] ....    77.698654: rtos_queue_send_from_isr_failed: tstamp:2999034804 queue:0x0bcb8a60
     kworker/0:2-1173  [000] ....    77.698654: rtos_queue_send_from_isr_failed: tstamp:2999034942 queue:0x0bcba5e0
     kworker/0:2-1173  [000] ....    77.698655: rtos_queue_send_from_isr_failed: tstamp:2999035075 queue:0x0bcbb3a0
     kworker/0:2-1173  [000] ....    77.698656: rtos_queue_send_from_isr_failed: tstamp:2999035209 queue:0x0bcbc160
     kworker/0:2-1173  [000] ....    77.698657: rtcpu_nvcsi_intr: tstamp:2999041791 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000110
     kworker/0:2-1173  [000] ....    77.698658: rtcpu_nvcsi_intr: tstamp:2999041791 class:CORRECTABLE_ERR type:PHY_INTR phy:0 cil:0 st:0 vc:0 status:0x00000110
     kworker/0:2-1173  [000] ....    77.698658: rtcpu_nvcsi_intr: tstamp:2999042583 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000110
     kworker/0:2-1173  [000] ....    77.698722: rtcpu_nvcsi_intr: tstamp:2999042583 class:CORRECTABLE_ERR type:PHY_INTR phy:0 cil:0 st:0 vc:0 status:0x00000110
     kworker/0:2-1173  [000] ....    77.698723: rtcpu_nvcsi_intr: tstamp:2999043095 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:0 vc:0 status:0x00000004
     kworker/0:2-1173  [000] ....    77.698724: rtcpu_nvcsi_intr: tstamp:2999043095 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000110
     kworker/0:2-1173  [000] ....    77.698724: rtcpu_nvcsi_intr: tstamp:2999043095 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:0 vc:0 status:0x00000004
     kworker/0:2-1173  [000] ....    77.698725: rtcpu_nvcsi_intr: tstamp:2999043095 class:CORRECTABLE_ERR type:PHY_INTR phy:0 cil:0 st:0 vc:0 status:0x00000110

log.csidump.ar0147.log (40.5 KB)

hello Luna2020,

tracing logs, SHORT_FRAME means the coming lines less than VI engine’s expectation.
could you please revise the active_h in the device tree property for testing?
BTW,
it also helps if you’re able to enable test-pattern-generator on the SerDes chip,
could you please configure that to narrow down the issue?
thanks

Hi JerryChang,

I have tried to modify active_h from 720 to 700, there is still "SHORT_FRAME " error, is there any register or csi log can check the actually pixel recieved by VI engines?

This SerDes driver MAX9295A/AR0231 is okay, so the hardware is fine.

hello Luna2020,

I think part of the signaling should be correct.
please also check below example,
it’s shown the signaling of start-of-frame and also end-of-frame, the timestamps values also looks correct.
bit-16:32 of CHANSEL_PXL_EOF also indicate the line-numbers received by VI engine.
0x02cf = 719d which shows 720-lines, (counts start from zero), so it equal to the active_h=720 in your DT configuration.

CHANSEL_PXL_SOF channel:0x23 frame:0 vi_tstamp:2915172497 data:0x00000001
CHANSEL_PXL_EOF channel:0x23 frame:0 vi_tstamp:2915779732 data:0x02cf0002

however,
there’s CHANSEL_FAULT error after 1st frame,
for example,

CHANSEL_FAULT channel:0x23 frame:0 vi_tstamp:2915780187 data:0x02d00040

this is a PIXEL_RUNAWAY failure, the line number here shows, 0x02d0 = 720d
we may dig into the signaling after frame-end. is there anything, such as embedded metadata coming after frame-end packet?
thanks

Hi JerryChang,

Thanks for your information. The ‘PIXEL_RUNAWAY’ means I need to add ‘active_h’ to verify it ?
I also see an error tracing log with ‘CSIMUX_FRAME’. Does it mean the FE packages lost?
“The bit 5 and 7 indicate lose the FE package cause the FS_FAULT — (A frame start occurred before previous frame end)”

tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:170626203395 data:0x000000a0

I defined embedded metadata in dtsi, but it is set to 0.

DTSI 
i2c@3180000 {
	tca9546@70 {
		i2c@0 {
			ar0147yuv_a@1b {
				compatible = "nvidia,ar0147yuv";

				reg = <0x1b>;
				reg_mux = <0>;
				/* Physical dimensions of sensor */
				physical_w = "15.0";
				physical_h = "12.5";

				sensor_model ="ar0147yuv";

				/* Defines number of frames to be dropped by driver internally after applying */
				/* sensor crop settings. Some sensors send corrupt frames after applying */
				/* crop co-ordinates */
				post_crop_frame_drop = "0";

				/* Convert Gain to unit of dB (decibel) befor passing to kernel driver */
				use_decibel_gain = "true";

				/* enable CID_SENSOR_MODE_ID for sensor modes selection */
				use_sensor_mode_id = "true";

				mode0 {/*mode ar0147yuv_MODE_1280X720_CROP_30FPS*/
					mclk_khz = "24000";
					num_lanes = "4";
					tegra_sinterface = "serial_a";
					vc_id = "0";
					
					discontinuous_clk = "no";
					dpcm_enable = "false";
					cil_settletime = "0";
					dynamic_pixel_bit_depth = "8";
					csi_pixel_bit_depth = "8";
					mode_type = "yuv";
					pixel_phase = "uyvy";

					active_w = "1280";
					active_h = "720";
					readout_orientation = "0";
					line_length = "2200";
					inherent_gain = "1";
					mclk_multiplier = "200";
					pix_clk_hz = "74250000";
					serdes_pix_clk_hz = "833333333";

					gain_factor = "10";
					min_gain_val = "0"; /* dB */
					max_gain_val = "300"; /* dB */
					step_gain_val = "3"; /* 0.3 */
					default_gain = "0";
					min_hdr_ratio = "1";
					max_hdr_ratio = "1";
					framerate_factor = "1000000";
					min_framerate = "30000000";
					max_framerate = "30000000";
					step_framerate = "1";
					default_framerate = "30000000";
					exposure_factor = "1000000";
					min_exp_time = "59"; /*us, 2 lines*/
					max_exp_time = "16657";
					step_exp_time = "1";
					default_exp_time = "16657";/* us */
					embedded_metadata_height = "0";
				};
				ports {
					#address-cells = <1>;
					#size-cells = <0>;
					port@0 {
						reg = <0>;
						ar0147yuv_ar0147yuv_out0: endpoint {
							vc-id = <0>;
							port-index = <0>;
							bus-width = <4>;
							remote-endpoint = <&ar0147yuv_csi_in0>;
							};
						};
					};
				gmsl-link {
					src-csi-port = "b";
					dst-csi-port = "a";
					serdes-csi-link = "a";
					csi-mode = "1x4";
					st-vc = <0>;
					vc-id = <0>;
					num-lanes = <4>;
					streams =  "yuv422";
					};
				};

			ar0147yuv_b@1c {
				compatible = "nvidia,ar0147yuv";

				reg = <0x1c>;
				reg_mux = <0>;
				/* Physical dimensions of sensor */
				physical_w = "15.0";
				physical_h = "12.5";

				sensor_model ="ar0147yuv";

				/* Defines number of frames to be dropped by driver internally after applying */
				/* sensor crop settings. Some sensors send corrupt frames after applying */
				/* crop co-ordinates */
				post_crop_frame_drop = "0";

				/* Convert Gain to unit of dB (decibel) befor passing to kernel driver */
				use_decibel_gain = "true";

				/* enable CID_SENSOR_MODE_ID for sensor modes selection */
				use_sensor_mode_id = "true";


				mode0 {/*mode ar0147yuv_MODE_1280X720_CROP_30FPS*/
					mclk_khz = "24000";
					num_lanes = "4";
					tegra_sinterface = "serial_a";
					vc_id = "1";
					
					discontinuous_clk = "no";
					dpcm_enable = "false";
					cil_settletime = "0";
					dynamic_pixel_bit_depth = "8";
					csi_pixel_bit_depth = "8";
					mode_type = "yuv";
					pixel_phase = "uyvy";

					active_w = "1280";
					active_h = "720";
					readout_orientation = "0";
					line_length = "2200";
					inherent_gain = "1";
					mclk_multiplier = "200";
					pix_clk_hz = "74250000";
					serdes_pix_clk_hz = "833333333";

					gain_factor = "10";
					min_gain_val = "0"; /* dB */
					max_gain_val = "300"; /* dB */
					step_gain_val = "3"; /* 0.3 */
					default_gain = "0";
					min_hdr_ratio = "1";
					max_hdr_ratio = "1";
					framerate_factor = "1000000";
					min_framerate = "30000000";
					max_framerate = "30000000";
					step_framerate = "1";
					default_framerate = "30000000";
					exposure_factor = "1000000";
					min_exp_time = "59"; /*us, 2 lines*/
					max_exp_time = "16657";
					step_exp_time = "1";
					default_exp_time = "16657";/* us */
					embedded_metadata_height = "0";
				};
				ports {
					#address-cells = <1>;
					#size-cells = <0>;
					port@0 {
						reg = <0>;
						ar0147yuv_ar0147yuv_out1: endpoint {
							vc-id = <1>;
							port-index = <0>;
							bus-width = <4>;
							remote-endpoint = <&ar0147yuv_csi_in1>;
							};
						};
					};
				gmsl-link {
					src-csi-port = "b";
					dst-csi-port = "a";
					serdes-csi-link = "b";
					csi-mode = "1x4";
					st-vc = <0>;
					vc-id = <1>;
					num-lanes = <4>;
					streams =  "yuv422";
					};
				};
		};
	};
};

hello Luna2020,

you may have a try, but I’m guessing there’s actually an issue behind frame-end.
it’s VI engine to expect a complete frame signaling within SOF/EOF; CSI MUX report an error if there’s additional lines received after end-of-frame.
so, the expected signaling comes as following, FS, SOF, Active Pixels, EOF, FE…

Hi JerryChang,

I modify the max9296 registers settings and solved this problem.

Thanks for your support.