CHANSEL_NOMATCH with FPDLink-III serdes, incorrectly splitting one camera into two channels?

jimrmooney · December 20, 2022, 12:39am

I am bringing up a specialized camera sensor and I am seeing an error CHANSEL_NOMATCH that I need to diagnose and find the best way forward to a solution.

Symptom:

The kernel trace below (with debug rce firmware) seems to indicate:

All the short packets (FS, FE etc) are being directed correctly to VC-ID 0x00
The long packets with correct DTYPE RAW12 pixels and VC-ID 0x00 are being redirected to an incorrect VC-ID. According to kernel traces, if I set the deserializer to output on VC-ID 0x00 the pixels appear to be sent to channel 0x01, if I set 0x01 the pixels are sent to 0x41 (too high to be a VC-ID), if I set VC-ID 0x02 the pixels are sent to channel 0x81. It seems that in the trace the VC-ID for long packets is 0x01+VC<<6. (In the CSI-2 v1 header the VC-ID is carried in bits 6:7, with DTYPE in bits 0:5.)
I see every frame with a CHANSEL_NOMATCH error and never receive any pixels. If the VC-ID from NVCSI HFP is already wrong before CHANSEL this would be the right output for bad data.

There may or may not be an embedded data long packet getting through successfully, not sure how to confirm.

To debug from the CHANSEL_NOMATCH symptom back through NVCSI HFP (Header Footer Parser) to my device config etc I need support with host1x insight, maybe firmware with additional debug.

I have seen other questions with a similar symptom, VC-ID turning from 0x01 to 0x41 for the pixel data from a GMSL deserialiser:

In that case the solution was setting the VC-ID in a gmsl-link node in the device tree, but I am using FPDLink-III not GMSL.

I think I have set vc-id=<0> and vc_id=“0” in my device tree where it should be (details below), but they do not seem to affect the “channel:” in the CHANSEL_NOMATCH trace entries.

I can see the long packet has the correct dtype (0x2c, 44) and length (0xc00, 3072 bytes for 2048 12-bit pixels).
I can not see the data from the packet that does not match because the unmatched data never goes through VI to go into system memory.

Logs and device details below.

What should I try next?
What more debug / logging would help?

In a GMSL camera serdes node “gmsl-link” can remap the vc-id of packets. Is there an FPDLink-III equivalent node that I need to add?
Is there a way to log/save/dump data all from a NVCSI channel? Maybe in debug firmware? I have not yet found a way to confirm the incoming data.
Is there a way to log/save/dump all data from a CHANSEL_NOMATCH packet (in my case this is almost all data)? Perhaps to set up a default sequential channel (not a structured VI channel) for unmatched data packets to be dumped to? Then it could be possible to work around this by recovering the data from there. As long as the data is misdirected by NVCSI and dumped by CHANSEL, I don’t see how I can see it.
Could these symptoms be caused by the serdes_pix_clk_hz being set incorrectly? I currently have it set to 250MHz based on 12bpp on 2 lanes of 1.5Gbps and that seems to be (almost) working.
Could these symptoms be caused by a timing error in the CSI-2 v1 signals? I could adjust many of those in the deserializer.

I have tried several tests that have not helped:

The deserializer defaults to VC-ID 0 and DTYPE RAW12 (0x2c, 44), meaning the CSI v1 long packet header first byte DATAID is 0x2c. I can set VC-ID to any 0-3 and any DTYPE, but I have not found a combination that works around the CHANSEL_NOMATCH.
The Orin TRM says CHANSEL is capable of matching multiple incoming virtual channels into a single output. Even though this should not be needed, I tried to test matching both VC-ID 0 OR VC-ID 1 by changing vi5_fops.c vi5_setup_surface() to set desc->ch_cfg.match.vc to 3 instead of (1u << chan->virtual_channel) (1 for VC-ID 0 plus 2 for VC-ID 1).

I have not (yet) tried some ideas that I think are unlikely and/or difficult to test:

The deserializer has control over 10 timing periods in the CSI-2 v1 signal, these are set automatically for 800Mbps and 1.6Gbps but could be adjusted manually if this might be a timing issue.
I expect the symptoms will be the same when I move this module back onto its devkit carrier board.

More background info:

The command I am using to test:
v4l2-ctl -d /dev/video0 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=1
This does not complete, I usually interrupt it after a few seconds of failures traced.

Hardware:

The sensor outputs 12-bit RAW parallel lines plus HSYNC, VSYNC and PCLK to a FPDLink-III serializer (TI DS90UB913)
The FPDLink-III is deserialized (TI DS90UB954) to CSI-2 v1 protocol generated by the deserializer based on the VSYNC and HSYNC coming in the FPDLink-III signal.
We plan to use the Direct V4L2 Interface because we don’t want any Camera Core Library image processing, except optionally unpacking RAW12 into 16-bit words.
In each 25Hz cycle the sensor emits 3 frames, one 2048x256(+3), one 2048x8(+3) and one 2048x64(+3), a total of 75 frames per second. We plan to mask the VI warnings about the short frames. Total data volume about 1MB per 25Hz, 25MB/s (33MB/s if unpacked from RAW12 to 16-bit).
By default the CSI-2 deserializer operates at 800Mbps per channel with de-skew disabled, I currently have it configured to 1.5Gbps per lane with de-skew enabled.
I have set the deserialiser to number frames 1-75, wrapping after 1 second.
I am using 2 lanes of 1.5Gbps, though I could also select 2 lanes of 800Mbps (or 4 lanes with our next PCB). The original parallel sensor output is only about 500Mb/s so any of these CSI-2 configurations should not overrun.
Currently I am testing on a ConnectTech Forge engineering sample AGX201-ENG, that affects the addresses in the DTB but should not affect this symptom vs an Orin AGX DevKit carrier board.

Output of media-ctl -p -d /dev/media0

Media controller API version 5.10.104

Media device information
------------------------
driver          tegra-camrtc-ca
model           NVIDIA Tegra Video Input Device
serial          
bus info        
hw revision     0x3
driver version  5.10.104

Device topology
- entity 1: 13e40000.host1x:nvcsi@15a00000- (2 pads, 2 links)
            type V4L2 subdev subtype Unknown flags 0
            device node name /dev/v4l-subdev0
	pad0: Sink
		<- "hfl118 7-0030":0 [ENABLED]
	pad1: Source
		-> "vi-output, hfl118 7-0030":0 [ENABLED]

- entity 4: hfl118 7-0030 (1 pad, 1 link)
            type V4L2 subdev subtype Sensor flags 0
            device node name /dev/v4l-subdev1
	pad0: Source
		[fmt:SRGGB12_1X12/2048x256 field:none colorspace:srgb]
		-> "13e40000.host1x:nvcsi@15a00000-":0 [ENABLED]

- entity 6: vi-output, hfl118 7-0030 (1 pad, 1 link)
            type Node subtype V4L flags 0
            device node name /dev/video0
	pad0: Sink
		<- "13e40000.host1x:nvcsi@15a00000-":1 [ENABLED]

Output of v4l2-compliance -d /dev/video0

v4l2-compliance SHA: not available, 64 bits

Compliance test for tegra-video device /dev/video0:

Driver Info:
	Driver name      : tegra-video
	Card type        : vi-output, hfl118 7-0030
	Bus info         : platform:tegra-capture-vi:0
	Driver version   : 5.10.104
	Capabilities     : 0x84200001
		Video Capture
		Streaming
		Extended Pix Format
		Device Capabilities
	Device Caps      : 0x04200001
		Video Capture
		Streaming
		Extended Pix Format
Media Driver Info:
	Driver name      : tegra-camrtc-ca
	Model            : NVIDIA Tegra Video Input Device
	Serial           : 
	Bus info         : 
	Media version    : 5.10.104
	Hardware revision: 0x00000003 (3)
	Driver version   : 5.10.104
Interface Info:
	ID               : 0x03000008
	Type             : V4L Video
Entity Info:
	ID               : 0x00000006 (6)
	Name             : vi-output, hfl118 7-0030
	Function         : V4L2 I/O
	Pad 0x01000007   : 0: Sink
	  Link 0x0200000c: from remote pad 0x1000003 of entity '13e40000.host1x:nvcsi@15a00000-': Data, Enabled

Required ioctls:
	test MC information (see 'Media Driver Info' above): OK
	test VIDIOC_QUERYCAP: OK

Allow for multiple opens:
	test second /dev/video0 open: OK
	test VIDIOC_QUERYCAP: OK
	test VIDIOC_G/S_PRIORITY: OK
	test for unlimited opens: OK

Debug ioctls:
	test VIDIOC_DBG_G/S_REGISTER: OK (Not Supported)
	test VIDIOC_LOG_STATUS: OK

Input ioctls:
	test VIDIOC_G/S_TUNER/ENUM_FREQ_BANDS: OK (Not Supported)
	test VIDIOC_G/S_FREQUENCY: OK (Not Supported)
	test VIDIOC_S_HW_FREQ_SEEK: OK (Not Supported)
	test VIDIOC_ENUMAUDIO: OK (Not Supported)
	test VIDIOC_G/S/ENUMINPUT: OK
	test VIDIOC_G/S_AUDIO: OK (Not Supported)
	Inputs: 1 Audio Inputs: 0 Tuners: 0

Output ioctls:
	test VIDIOC_G/S_MODULATOR: OK (Not Supported)
	test VIDIOC_G/S_FREQUENCY: OK (Not Supported)
	test VIDIOC_ENUMAUDOUT: OK (Not Supported)
	test VIDIOC_G/S/ENUMOUTPUT: OK (Not Supported)
	test VIDIOC_G/S_AUDOUT: OK (Not Supported)
	Outputs: 0 Audio Outputs: 0 Modulators: 0

Input/Output configuration ioctls:
	test VIDIOC_ENUM/G/S/QUERY_STD: OK (Not Supported)
	test VIDIOC_ENUM/G/S/QUERY_DV_TIMINGS: OK (Not Supported)
	test VIDIOC_DV_TIMINGS_CAP: OK (Not Supported)
	test VIDIOC_G/S_EDID: OK (Not Supported)

Control ioctls (Input 0):
	test VIDIOC_QUERY_EXT_CTRL/QUERYMENU: OK
	test VIDIOC_QUERYCTRL: OK
	test VIDIOC_G/S_CTRL: OK
	test VIDIOC_G/S/TRY_EXT_CTRLS: OK
	test VIDIOC_(UN)SUBSCRIBE_EVENT/DQEVENT: OK
	test VIDIOC_G/S_JPEGCOMP: OK (Not Supported)
	Standard Controls: 1 Private Controls: 18

Format ioctls (Input 0):
	test VIDIOC_ENUM_FMT/FRAMESIZES/FRAMEINTERVALS: OK
	test VIDIOC_G/S_PARM: OK
	test VIDIOC_G_FBUF: OK (Not Supported)
	test VIDIOC_G_FMT: OK
	test VIDIOC_TRY_FMT: OK
	test VIDIOC_S_FMT: OK
	test VIDIOC_G_SLICED_VBI_CAP: OK (Not Supported)
	test Cropping: OK (Not Supported)
	test Composing: OK (Not Supported)
	test Scaling: OK (Not Supported)

Codec ioctls (Input 0):
	test VIDIOC_(TRY_)ENCODER_CMD: OK (Not Supported)
	test VIDIOC_G_ENC_INDEX: OK (Not Supported)
	test VIDIOC_(TRY_)DECODER_CMD: OK (Not Supported)

Buffer ioctls (Input 0):
		fail: v4l2-test-buffers.cpp(715): q.create_bufs(node, 1, &fmt) != EINVAL
	test VIDIOC_REQBUFS/CREATE_BUFS/QUERYBUF: FAIL
	test VIDIOC_EXPBUF: OK
	test Requests: OK (Not Supported)

Total for tegra-video device /dev/video0: 45, Succeeded: 44, Failed: 1, Warnings: 0

dmesg:

[   90.124184] [RCE] NVCSILP clock rate = 408000000 Hz.
[  107.813059] bwmgr API not supported
[  107.815806] [RCE] VM0 deactivating.VM0 activating.NVCSILP clock rate = 408000000 Hz.
[  107.850751] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 46, flags: 0, err_data 64
[  107.853272] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 47, flags: 0, err_data 131072
[  107.868817] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 48, flags: 0, err_data 131072
[  107.875793] [RCE] tegra_nvcsi_stream_set_config(vm0, stream=0, csi=0)
[  107.875796] [RCE] MIPI clock = 750000 kHz, tHS-SETTLE = 0, tCLK-SETTLE = 0
[  107.875797] [RCE] ===== NVCSI Stream Configuration =====
[  107.875799] [RCE] stream_id: PP 0, csi_port: PORT A
[  107.875800] [RCE] Brick: PHY 0, Mode: D-PHY
[  107.875802] [RCE] Partition: CIL A, LP bypass: Enabled, Lanes: 2
[  107.875803] [RCE] Clock information:
[  107.875804] [RCE] MIPI clock rate: 750.00 MHz
[  107.875806] [RCE] T_HS settle: 0, T_CLK settle: 0
[  107.875808] [RCE] ======================================
[  107.875809] [RCE] tegra_nvcsi_stream_open(vm0, stream=0, csi=0)
[  107.875811] [RCE] nvcsi_calc_ths_settle ths_settle 53
[  107.875812] [RCE] nvcsi_calc_ths_settle ths_settle 53
[  107.875813] [RCE] nvcsi_calc_tclk_settle tclk_settle 75
[  107.890575] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 49, flags: 0, err_data 64
[  115.396785] bwmgr API not supported
[  115.439759] [RCE] tegra_nvcsi_stream_close(vm0, stream=0, csi=0)

Device Tree source:

/*
 * Jetson Device-tree overlay for Camera HFL118 on Forge Orin AGX
 *
 * Copyright (c) 2022, BrashTech.  All rights reserved.
 *
 */

#define HFL118_RST_L TEGRA234_AON_GPIO(BB, 0)

/{

	tegra-capture-vi {
		num-channels = <1>;
		status = "okay";
		ports {
			#address-cells = <1>;
			#size-cells = <0>;
			port@0 {
				reg = <0>;
				status = "okay";
				lihfl118_vi_in0: endpoint {
					status = "okay";
					port-index = <0>;
					bus-width = <2>;
					vc-id = <0>;
					remote-endpoint = <&lihfl118_csi_out0>;
				};
			};
		};
	};

	host1x@13e00000 {
		status = "okay";
		nvcsi@15a00000 {
			#address-cells = <1>;
			#size-cells = <0>;
			status = "okay";
			num-channels = <1>;
			channel@0 {
				reg = <0>;
				status = "okay";
				ports {
					status = "okay";
					#address-cells = <1>;
					#size-cells = <0>;
					port@0 {
						#address-cells = <1>;
						#size-cells = <0>;
						reg = <0>;
						status = "okay";
						lihfl118_csi_in0: endpoint@0 {
							#address-cells = <1>;
							#size-cells = <0>;
							reg = <0>;
							status = "okay";
							port-index = <0>;
							bus-width = <2>;
							vc-id = <0>;
							remote-endpoint = <&lihfl118_cam_out0>;
						};
					};
					port@1 {
						#address-cells = <1>;
						#size-cells = <0>;
						reg = <1>;
						status = "okay";
						lihfl118_csi_out0: endpoint@1 {
							#address-cells = <1>;
							#size-cells = <0>;
							reg = <1>;
							status = "okay";
							vc-id = <0>;
							remote-endpoint = <&lihfl118_vi_in0>;
						};
					};
				};
			};
		};
	};

	i2c@c250000 {
		hfl118_a@30 {
			compatible = "continental,hfl118";
			reg = <0x30>;
			status = "okay";
			devnode = "video0";
			physical_w = "11.5";
			physical_h = "2.8";
			sensor_model ="hfl118";
			post_crop_frame_drop = "0";
			use_decibel_gain = "true";
			delayed_gain = "false";
			use_sensor_mode_id = "true";
			limit_analog_gain = "true";
			mclk = "extperiph1";
			reset-gpios = <&tegra_aon_gpio HFL118_RST_L GPIO_ACTIVE_HIGH>;

			mode0 {
				mclk_khz = "250000"; /* Match serdes? */ 
				num_lanes = "2";
				vc_id = "0";
				tegra_sinterface = "serial_a";
				phy_mode = "DPHY";
				discontinuous_clk = "yes";
				dpcm_enable = "false";
				cil_settletime = "0";
				dynamic_pixel_bit_depth = "12";
				csi_pixel_bit_depth = "12";
				mode_type = "bayer";
				pixel_phase = "rggb";
				active_w = "2048";
				active_h = "258";
				readout_orientation = "0";
				line_length = "2200";
				inherent_gain = "1";
				pix_clk_hz = "250000000"; /* Match serdes */
				serdes_pix_clk_hz = "250000000"; /* 1.5Gbps * 2 / 12 = 250MHz */
				gain_factor = "10";
				min_gain_val = "0";
				max_gain_val = "0";
				step_gain_val = "1";
				default_gain = "0";
				min_hdr_ratio = "1";
				max_hdr_ratio = "1";
				framerate_factor = "1000000";
				min_framerate = "25000000"; /* 25 */
				max_framerate = "75000000"; /* 75 */
				step_framerate = "1";
				default_framerate= "25000000";
				exposure_factor = "1000000";
				min_exp_time = "1"; /* us */
				max_exp_time = "2"; /* us */
				step_exp_time = "1";
				default_exp_time = "2";/* us */
				embedded_metadata_height = "0";
			};
			ports {
				#address-cells = <1>;
				#size-cells = <0>;
				port@0 {
					reg = <0>;
					lihfl118_cam_out0: endpoint {
						port-index = <0>;
						bus-width = <2>;
						vc-id = <0>;
						remote-endpoint = <&lihfl118_csi_in0>;
					};
				};
			};
		};
	};

	tegra-camera-platform {
		compatible = "nvidia, tegra-camera-platform";
		num_csi_lanes = <2>;
		max_lane_speed = <1600000>;
		min_bits_per_pixel = <12>;
		vi_peak_byte_per_pixel = <2>;
		vi_bw_margin_pct = <25>;
		isp_peak_byte_per_pixel = <5>;
		isp_bw_margin_pct = <25>;
		modules {
			module0 {
				status = "okay";
				badge = "hfl118_bottom_lihfl118";
				position = "bottom";
				orientation = "0";
				drivernode0 {
					status = "okay";
					pcl_id = "v4l2_sensor";
					devname = "hfl118 30-0030";
					proc-device-tree = "/proc/device-tree/i2c@c250000/hfl118_a@30";
				};
			};
		};
	};
};

Kernel trace:

# tracer: nop
#
# entries-in-buffer/entries-written: 2340/2340   #P:8
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/1:6-154     [001] ....    96.068038: rtcpu_string: tstamp:3784168668 id:0x04010000 str:"VM0 deactivating."
        v4l2-ctl-2406    [007] ....   107.796289: tegra_channel_open: vi-output, hfl118 7-0030
        v4l2-ctl-2406    [007] ....   107.798432: tegra_channel_set_power: hfl118 7-0030 : 0x1
        v4l2-ctl-2406    [007] ....   107.798438: camera_common_s_power: status : 0x1
        v4l2-ctl-2406    [007] ....   107.798450: tegra_channel_set_power: 13e40000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2406    [007] ....   107.798452: csi_s_power: enable : 0x1
        v4l2-ctl-2406    [000] ....   107.800079: tegra_channel_capture_setup: vnc_id 0 W 2048 H 256 fmt c4
        v4l2-ctl-2406    [002] ....   107.808875: tegra_channel_set_stream: enable : 0x1
     kworker/1:4-152     [001] ....   107.815800: rtcpu_string: tstamp:4150886360 id:0x04010000 str:"VM0 activating."
     kworker/1:4-152     [001] ....   107.815802: rtcpu_string: tstamp:4150990743 id:0x04010000 str:"NVCSILP clock rate = 408000000 Hz.
"
        v4l2-ctl-2406    [002] ....   107.823809: tegra_channel_set_stream: 13e40000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2406    [002] ....   107.823812: csi_s_stream: enable : 0x1
        v4l2-ctl-2406    [002] ....   107.824298: tegra_channel_set_stream: hfl118 7-0030 : 0x1
     kworker/1:4-152     [001] ....   107.875791: rtcpu_string: tstamp:4151538065 id:0x04010000 str:"tegra_nvcsi_stream_set_config(vm0, stream=0, csi"
     kworker/1:4-152     [001] ....   107.875792: rtcpu_string: tstamp:4151538169 id:0x04010000 str:"=0)
"
     kworker/1:4-152     [001] ....   107.875795: rtcpu_string: tstamp:4151538540 id:0x04010000 str:"MIPI clock = 750000 kHz, tHS-SETTLE = 0, tCLK-SE"
     kworker/1:4-152     [001] ....   107.875795: rtcpu_string: tstamp:4151538642 id:0x04010000 str:"TTLE = 0
"
     kworker/1:4-152     [001] ....   107.875797: rtcpu_string: tstamp:4151538852 id:0x04010000 str:"===== NVCSI Stream Configuration =====
"
     kworker/1:4-152     [001] ....   107.875798: rtcpu_string: tstamp:4151539096 id:0x04010000 str:"stream_id: PP 0, csi_port: PORT A
"
     kworker/1:4-152     [001] ....   107.875800: rtcpu_string: tstamp:4151539353 id:0x04010000 str:"Brick: PHY 0, Mode: D-PHY
"
     kworker/1:4-152     [001] ....   107.875801: rtcpu_string: tstamp:4151539638 id:0x04010000 str:"Partition: CIL A, LP bypass: Enabled, Lanes: 2
"
     kworker/1:4-152     [001] ....   107.875803: rtcpu_string: tstamp:4151539820 id:0x04010000 str:"Clock information:
"
     kworker/1:4-152     [001] ....   107.875804: rtcpu_string: tstamp:4151540119 id:0x04010000 str:"MIPI clock rate: 750.00 MHz
"
     kworker/1:4-152     [001] ....   107.875806: rtcpu_string: tstamp:4151540364 id:0x04010000 str:"T_HS settle: 0, T_CLK settle: 0
"
     kworker/1:4-152     [001] ....   107.875807: rtcpu_string: tstamp:4151540590 id:0x04010000 str:"======================================
"
     kworker/1:4-152     [001] ....   107.875809: rtcpu_string: tstamp:4151542208 id:0x04010000 str:"tegra_nvcsi_stream_open(vm0, stream=0, csi=0)
"
     kworker/1:4-152     [001] ....   107.875810: rtcpu_string: tstamp:4151550847 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 53
"
     kworker/1:4-152     [001] ....   107.875812: rtcpu_string: tstamp:4151551112 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 53
"
     kworker/1:4-152     [001] ....   107.875813: rtcpu_string: tstamp:4151551373 id:0x04010000 str:"nvcsi_calc_tclk_settle tclk_settle 75
"
     kworker/1:4-152     [001] ....   107.875816: rtcpu_vinotify_event: tstamp:4151552750 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132833978400 data:0x379d580010000000
     kworker/1:4-152     [001] ....   107.875816: rtcpu_vinotify_event: tstamp:4151552889 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132833984896 data:0x0000000031000001
     kworker/1:4-152     [001] ....   107.875816: rtcpu_vinotify_event: tstamp:4151553043 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132834041024 data:0x379d550010000000
     kworker/1:4-152     [001] ....   107.875816: rtcpu_vinotify_event: tstamp:4151553177 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132834052256 data:0x0000000031000002
     kworker/1:4-152     [001] ....   107.875818: rtcpu_vinotify_error: tstamp:4151686312 cch:-1 vi:0 tag:CSIMUX_STREAM channel:0x00 frame:0 vi_tstamp:132853849728 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.875818: rtcpu_vinotify_event: tstamp:4152087514 cch:-1 vi:0 tag:CSIMUX_STREAM channel:0x00 frame:0 vi_tstamp:132853849728 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.875818: rtcpu_vinotify_event: tstamp:4152087649 cch:0 vi:0 tag:FS channel:0x00 frame:46 vi_tstamp:132862336384 data:0x0000002e00000010
     kworker/1:4-152     [001] ....   107.875818: rtcpu_vinotify_event: tstamp:4152087807 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:46 vi_tstamp:132862336480 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.875818: rtcpu_vinotify_event: tstamp:4152087937 cch:0 vi:0 tag:CHANSEL_PXL_SOF channel:0x23 frame:46 vi_tstamp:132862436608 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152088089 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:46 vi_tstamp:132862447488 data:0x0000000008020001
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152376348 cch:0 vi:0 tag:CHANSEL_PXL_EOF channel:0x23 frame:46 vi_tstamp:132875713120 data:0x0000000000ff0002
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152376504 cch:0 vi:0 tag:ATOMP_FRAME_DONE channel:0x23 frame:46 vi_tstamp:132875714112 data:0x0000000000000000
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152376636 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:46 vi_tstamp:132875734368 data:0x0000000002020001
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152376788 cch:0 vi:0 tag:CHANSEL_FAULT channel:0x23 frame:46 vi_tstamp:132875749824 data:0x0000000001000040
     kworker/1:4-152     [001] ....   107.875819: rtcpu_vinotify_event: tstamp:4152376919 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:46 vi_tstamp:132875795328 data:0x0000000001020001
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152377068 cch:0 vi:0 tag:FE channel:0x00 frame:46 vi_tstamp:132875819136 data:0x0000002e00000020
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152377202 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:46 vi_tstamp:132875819232 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152520310 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132876122496 data:0x379d580010000000
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152520442 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132876165824 data:0x0000000031000003
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152520595 cch:0 vi:0 tag:FS channel:0x00 frame:47 vi_tstamp:132877806688 data:0x0000002f00000010
     kworker/1:4-152     [001] ....   107.875820: rtcpu_vinotify_event: tstamp:4152520727 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:47 vi_tstamp:132877806784 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152520880 cch:0 vi:0 tag:CHANSEL_PXL_SOF channel:0x23 frame:47 vi_tstamp:132877906880 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152521014 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:47 vi_tstamp:132877917728 data:0x0000000008020002
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152521166 cch:0 vi:0 tag:FE channel:0x00 frame:47 vi_tstamp:132878393152 data:0x0000002f00000020
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152521299 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:47 vi_tstamp:132878393184 data:0x000a200001000000
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152521452 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:47 vi_tstamp:132878459904 data:0x0000000001020002
     kworker/1:4-152     [001] ....   107.875821: rtcpu_vinotify_event: tstamp:4152521586 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:47 vi_tstamp:132878393248 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152521739 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132878719680 data:0x379d550010000000
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152521871 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:132878763040 data:0x0000000031000004
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152522021 cch:0 vi:0 tag:FS channel:0x00 frame:48 vi_tstamp:132880380736 data:0x0000003000000010
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152522155 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:48 vi_tstamp:132880380800 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152522308 cch:0 vi:0 tag:CHANSEL_PXL_SOF channel:0x23 frame:48 vi_tstamp:132880480896 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.875822: rtcpu_vinotify_event: tstamp:4152522440 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:48 vi_tstamp:132880491776 data:0x0000000008020003
     kworker/1:4-152     [001] ....   107.875823: rtcpu_vinotify_event: tstamp:4153009498 cch:0 vi:0 tag:FE channel:0x00 frame:48 vi_tstamp:132893845760 data:0x0000003000000020
     kworker/1:4-152     [001] ....   107.875823: rtcpu_vinotify_event: tstamp:4153009634 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:48 vi_tstamp:132893845792 data:0x0042200001000000
     kworker/1:4-152     [001] ....   107.875823: rtcpu_vinotify_event: tstamp:4153009791 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:48 vi_tstamp:132893912544 data:0x0000000001020003
     kworker/1:4-152     [001] ....   107.875823: rtcpu_vinotify_event: tstamp:4153009926 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:48 vi_tstamp:132893845888 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.931794: rtcpu_vinotify_event: tstamp:4153551984 cch:0 vi:0 tag:FS channel:0x00 frame:49 vi_tstamp:132902328320 data:0x0000003100000010
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153552121 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:49 vi_tstamp:132902328416 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153552278 cch:0 vi:0 tag:CHANSEL_PXL_SOF channel:0x23 frame:49 vi_tstamp:132902428576 data:0x0000000000000001
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153552409 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:49 vi_tstamp:132902439424 data:0x0000000008020004
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153684147 cch:0 vi:0 tag:CHANSEL_PXL_EOF channel:0x23 frame:49 vi_tstamp:132915704800 data:0x0000000000ff0002
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153684280 cch:0 vi:0 tag:ATOMP_FRAME_DONE channel:0x23 frame:49 vi_tstamp:132915705792 data:0x0000000000000000
     kworker/1:4-152     [001] ....   107.931795: rtcpu_vinotify_event: tstamp:4153684435 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:49 vi_tstamp:132915726080 data:0x0000000002020004
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_event: tstamp:4153684567 cch:0 vi:0 tag:CHANSEL_FAULT channel:0x23 frame:49 vi_tstamp:132915741536 data:0x0000000001000040
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_event: tstamp:4153684717 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:49 vi_tstamp:132915787008 data:0x0000000001020004
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_event: tstamp:4153684847 cch:0 vi:0 tag:FE channel:0x00 frame:49 vi_tstamp:132915811072 data:0x0000003100000020
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_event: tstamp:4153684999 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:49 vi_tstamp:132915811200 data:0x0000000800000000
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_event: tstamp:4153685128 cch:0 vi:0 tag:FS channel:0x00 frame:50 vi_tstamp:132917798400 data:0x0000003200000010
     kworker/1:4-152     [001] ....   107.931796: rtcpu_vinotify_error: tstamp:4153688275 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:50 vi_tstamp:132917898624 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.931797: rtcpu_vinotify_error: tstamp:4153768876 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:51 vi_tstamp:132920472672 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.931798: rtcpu_vinotify_event: tstamp:4154202991 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:50 vi_tstamp:132917898624 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.931798: rtcpu_vinotify_event: tstamp:4154203126 cch:0 vi:0 tag:FE channel:0x00 frame:50 vi_tstamp:132918385152 data:0x0000003200000020
     kworker/1:4-152     [001] ....   107.931798: rtcpu_vinotify_event: tstamp:4154203279 cch:0 vi:0 tag:FS channel:0x00 frame:51 vi_tstamp:132920372416 data:0x0000003300000010
     kworker/1:4-152     [001] ....   107.931798: rtcpu_vinotify_event: tstamp:4154203411 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:51 vi_tstamp:132920472672 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.931798: rtcpu_vinotify_event: tstamp:4154203563 cch:0 vi:0 tag:FE channel:0x00 frame:51 vi_tstamp:132933837728 data:0x0000003300000020
     kworker/1:4-152     [001] ....   107.931799: rtcpu_vinotify_error: tstamp:4154455153 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:52 vi_tstamp:132942438752 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.931799: rtcpu_vinotify_event: tstamp:4154745290 cch:0 vi:0 tag:FS channel:0x00 frame:52 vi_tstamp:132942338496 data:0x0000003400000010
     kworker/1:4-152     [001] ....   107.931799: rtcpu_vinotify_event: tstamp:4154745446 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:52 vi_tstamp:132942438752 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987906: rtcpu_vinotify_error: tstamp:4154938597 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:53 vi_tstamp:132957908832 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987907: rtcpu_vinotify_error: tstamp:4155019057 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:54 vi_tstamp:132960482848 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987908: rtcpu_vinotify_event: tstamp:4155287884 cch:0 vi:0 tag:FE channel:0x00 frame:52 vi_tstamp:132955821280 data:0x0000003400000020
     kworker/1:4-152     [001] ....   107.987909: rtcpu_vinotify_event: tstamp:4155288034 cch:0 vi:0 tag:FS channel:0x00 frame:53 vi_tstamp:132957808576 data:0x0000003500000010
     kworker/1:4-152     [001] ....   107.987909: rtcpu_vinotify_event: tstamp:4155288165 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:53 vi_tstamp:132957908832 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987909: rtcpu_vinotify_event: tstamp:4155288314 cch:0 vi:0 tag:FE channel:0x00 frame:53 vi_tstamp:132958395264 data:0x0000003500000020
     kworker/1:4-152     [001] ....   107.987910: rtcpu_vinotify_event: tstamp:4155288444 cch:0 vi:0 tag:FS channel:0x00 frame:54 vi_tstamp:132960382624 data:0x0000003600000010
     kworker/1:4-152     [001] ....   107.987910: rtcpu_vinotify_event: tstamp:4155288594 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:54 vi_tstamp:132960482848 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987910: rtcpu_vinotify_error: tstamp:4155705276 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:55 vi_tstamp:132982432256 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987911: rtcpu_vinotify_event: tstamp:4155705834 cch:0 vi:0 tag:FE channel:0x00 frame:54 vi_tstamp:132973865376 data:0x0000003600000020
     kworker/1:4-152     [001] ....   107.987911: rtcpu_vinotify_event: tstamp:4155705984 cch:0 vi:0 tag:FS channel:0x00 frame:55 vi_tstamp:132982332064 data:0x0000003700000010
     kworker/1:4-152     [001] ....   107.987911: rtcpu_vinotify_event: tstamp:4155706111 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:55 vi_tstamp:132982432256 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987912: rtcpu_vinotify_error: tstamp:4156188396 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:56 vi_tstamp:132997902560 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987912: rtcpu_vinotify_event: tstamp:4156210486 cch:0 vi:0 tag:FE channel:0x00 frame:55 vi_tstamp:132995814848 data:0x0000003700000020
     kworker/1:4-152     [001] ....   107.987912: rtcpu_vinotify_event: tstamp:4156210615 cch:0 vi:0 tag:FS channel:0x00 frame:56 vi_tstamp:132997802336 data:0x0000003800000010
     kworker/1:4-152     [001] ....   107.987913: rtcpu_vinotify_event: tstamp:4156210765 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:56 vi_tstamp:132997902560 data:0x0000000000000589
     kworker/1:4-152     [001] ....   107.987913: rtcpu_vinotify_event: tstamp:4156210892 cch:0 vi:0 tag:FE channel:0x00 frame:56 vi_tstamp:132998388832 data:0x0000003800000020
     kworker/1:4-152     [001] ....   107.987913: rtcpu_vinotify_error: tstamp:4156268833 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:57 vi_tstamp:133000476608 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043799: rtcpu_vinotify_event: tstamp:4156753063 cch:0 vi:0 tag:FS channel:0x00 frame:57 vi_tstamp:133000376352 data:0x0000003900000010
     kworker/1:4-152     [001] ....   108.043800: rtcpu_vinotify_event: tstamp:4156753192 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:57 vi_tstamp:133000476608 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043800: rtcpu_vinotify_event: tstamp:4156753343 cch:0 vi:0 tag:FE channel:0x00 frame:57 vi_tstamp:133013841664 data:0x0000003900000020
     kworker/1:4-152     [001] ....   108.043802: rtcpu_vinotify_error: tstamp:4156955319 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:58 vi_tstamp:133022444096 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043802: rtcpu_vinotify_event: tstamp:4157295357 cch:0 vi:0 tag:FS channel:0x00 frame:58 vi_tstamp:133022343808 data:0x0000003a00000010
     kworker/1:4-152     [001] ....   108.043802: rtcpu_vinotify_event: tstamp:4157295511 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:58 vi_tstamp:133022444096 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043803: rtcpu_vinotify_error: tstamp:4157438764 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:59 vi_tstamp:133037914336 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043803: rtcpu_vinotify_error: tstamp:4157519235 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:60 vi_tstamp:133040488352 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043803: rtcpu_vinotify_event: tstamp:4157837977 cch:0 vi:0 tag:FE channel:0x00 frame:58 vi_tstamp:133035826592 data:0x0000003a00000020
     kworker/1:4-152     [001] ....   108.043804: rtcpu_vinotify_event: tstamp:4157838129 cch:0 vi:0 tag:FS channel:0x00 frame:59 vi_tstamp:133037814080 data:0x0000003b00000010
     kworker/1:4-152     [001] ....   108.043804: rtcpu_vinotify_event: tstamp:4157838258 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:59 vi_tstamp:133037914336 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043805: rtcpu_vinotify_event: tstamp:4157838409 cch:0 vi:0 tag:FE channel:0x00 frame:59 vi_tstamp:133038400608 data:0x0000003b00000020
     kworker/1:4-152     [001] ....   108.043805: rtcpu_vinotify_event: tstamp:4157838537 cch:0 vi:0 tag:FS channel:0x00 frame:60 vi_tstamp:133040388128 data:0x0000003c00000010
     kworker/1:4-152     [001] ....   108.043805: rtcpu_vinotify_event: tstamp:4157838688 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:60 vi_tstamp:133040488352 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.043806: rtcpu_vinotify_event: tstamp:4157935831 cch:0 vi:0 tag:FE channel:0x00 frame:60 vi_tstamp:133053853216 data:0x0000003c00000020
     kworker/1:4-152     [001] ....   108.043806: rtcpu_vinotify_error: tstamp:4158205296 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:61 vi_tstamp:133062442976 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099908: rtcpu_vinotify_event: tstamp:4158435236 cch:0 vi:0 tag:FS channel:0x00 frame:61 vi_tstamp:133062342752 data:0x0000003d00000010
     kworker/1:4-152     [001] ....   108.099909: rtcpu_vinotify_event: tstamp:4158435367 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:61 vi_tstamp:133062442976 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099910: rtcpu_vinotify_error: tstamp:4158688727 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:62 vi_tstamp:133077913056 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099910: rtcpu_vinotify_error: tstamp:4158769186 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:63 vi_tstamp:133080487072 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099910: rtcpu_vinotify_event: tstamp:4158977862 cch:0 vi:0 tag:FE channel:0x00 frame:61 vi_tstamp:133075825568 data:0x0000003d00000020
     kworker/1:4-152     [001] ....   108.099911: rtcpu_vinotify_event: tstamp:4158977994 cch:0 vi:0 tag:FS channel:0x00 frame:62 vi_tstamp:133077812800 data:0x0000003e00000010
     kworker/1:4-152     [001] ....   108.099911: rtcpu_vinotify_event: tstamp:4158978143 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:62 vi_tstamp:133077913056 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099911: rtcpu_vinotify_event: tstamp:4158978281 cch:0 vi:0 tag:FE channel:0x00 frame:62 vi_tstamp:133078399616 data:0x0000003e00000020
     kworker/1:4-152     [001] ....   108.099912: rtcpu_vinotify_event: tstamp:4158978428 cch:0 vi:0 tag:FS channel:0x00 frame:63 vi_tstamp:133080386848 data:0x0000003f00000010
     kworker/1:4-152     [001] ....   108.099912: rtcpu_vinotify_event: tstamp:4158978559 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:63 vi_tstamp:133080487072 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099913: rtcpu_vinotify_error: tstamp:4159455127 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:64 vi_tstamp:133102437888 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099913: rtcpu_vinotify_event: tstamp:4159520411 cch:0 vi:0 tag:FE channel:0x00 frame:63 vi_tstamp:133093852128 data:0x0000003f00000020
     kworker/1:4-152     [001] ....   108.099913: rtcpu_vinotify_event: tstamp:4159520541 cch:0 vi:0 tag:FS channel:0x00 frame:64 vi_tstamp:133102337664 data:0x0000004000000010
     kworker/1:4-152     [001] ....   108.099914: rtcpu_vinotify_event: tstamp:4159520691 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:64 vi_tstamp:133102437888 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099914: rtcpu_vinotify_error: tstamp:4159938576 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:65 vi_tstamp:133117908192 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099915: rtcpu_vinotify_event: tstamp:4160014830 cch:0 vi:0 tag:FE channel:0x00 frame:64 vi_tstamp:133115820448 data:0x0000004000000020
     kworker/1:4-152     [001] ....   108.099915: rtcpu_vinotify_event: tstamp:4160014979 cch:0 vi:0 tag:FS channel:0x00 frame:65 vi_tstamp:133117807936 data:0x0000004100000010
     kworker/1:4-152     [001] ....   108.099915: rtcpu_vinotify_event: tstamp:4160015109 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:65 vi_tstamp:133117908192 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.099916: rtcpu_vinotify_event: tstamp:4160015255 cch:0 vi:0 tag:FE channel:0x00 frame:65 vi_tstamp:133118394464 data:0x0000004100000020
     kworker/1:4-152     [001] ....   108.099916: rtcpu_vinotify_event: tstamp:4160015384 cch:0 vi:0 tag:FS channel:0x00 frame:66 vi_tstamp:133120381984 data:0x0000004200000010
     kworker/1:4-152     [001] ....   108.099917: rtcpu_vinotify_error: tstamp:4160019044 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:66 vi_tstamp:133120482208 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155910: rtcpu_vinotify_event: tstamp:4160551492 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:66 vi_tstamp:133120482208 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155910: rtcpu_vinotify_event: tstamp:4160551623 cch:0 vi:0 tag:FE channel:0x00 frame:66 vi_tstamp:133133864736 data:0x0000004200000020
     kworker/1:4-152     [001] ....   108.155912: rtcpu_vinotify_error: tstamp:4160704853 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:67 vi_tstamp:133142429184 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155912: rtcpu_vinotify_event: tstamp:4161093762 cch:0 vi:0 tag:FS channel:0x00 frame:67 vi_tstamp:133142328928 data:0x0000004300000010
     kworker/1:4-152     [001] ....   108.155912: rtcpu_vinotify_event: tstamp:4161093895 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:67 vi_tstamp:133142429184 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155913: rtcpu_vinotify_error: tstamp:4161188301 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:68 vi_tstamp:133157899456 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155913: rtcpu_vinotify_error: tstamp:4161268736 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:69 vi_tstamp:133160473504 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155914: rtcpu_vinotify_event: tstamp:4161636347 cch:0 vi:0 tag:FE channel:0x00 frame:67 vi_tstamp:133155811744 data:0x0000004300000020
     kworker/1:4-152     [001] ....   108.155914: rtcpu_vinotify_event: tstamp:4161636476 cch:0 vi:0 tag:FS channel:0x00 frame:68 vi_tstamp:133157799232 data:0x0000004400000010
     kworker/1:4-152     [001] ....   108.155914: rtcpu_vinotify_event: tstamp:4161636627 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:68 vi_tstamp:133157899456 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.155915: rtcpu_vinotify_event: tstamp:4161636754 cch:0 vi:0 tag:FE channel:0x00 frame:68 vi_tstamp:133158385760 data:0x0000004400000020
     kworker/1:4-152     [001] ....   108.155915: rtcpu_vinotify_event: tstamp:4161636900 cch:0 vi:0 tag:FS channel:0x00 frame:69 vi_tstamp:133160373248 data:0x0000004500000010
     kworker/1:4-152     [001] ....   108.155915: rtcpu_vinotify_event: tstamp:4161637033 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:69 vi_tstamp:133160473504 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211916: rtcpu_vinotify_error: tstamp:4161955095 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:70 vi_tstamp:133182436896 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211919: rtcpu_vinotify_event: tstamp:4162178921 cch:0 vi:0 tag:FE channel:0x00 frame:69 vi_tstamp:133173838528 data:0x0000004500000020
     kworker/1:4-152     [001] ....   108.211919: rtcpu_vinotify_event: tstamp:4162179051 cch:0 vi:0 tag:FS channel:0x00 frame:70 vi_tstamp:133182336672 data:0x0000004600000010
     kworker/1:4-152     [001] ....   108.211920: rtcpu_vinotify_event: tstamp:4162179201 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:70 vi_tstamp:133182436896 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211920: rtcpu_vinotify_error: tstamp:4162438865 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:71 vi_tstamp:133197907136 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211921: rtcpu_vinotify_event: tstamp:4162439422 cch:0 vi:0 tag:FE channel:0x00 frame:70 vi_tstamp:133195819392 data:0x0000004600000020
     kworker/1:4-152     [001] ....   108.211921: rtcpu_vinotify_event: tstamp:4162439575 cch:0 vi:0 tag:FS channel:0x00 frame:71 vi_tstamp:133197806944 data:0x0000004700000010
     kworker/1:4-152     [001] ....   108.211921: rtcpu_vinotify_event: tstamp:4162439706 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:71 vi_tstamp:133197907136 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211922: rtcpu_vinotify_error: tstamp:4162519011 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:72 vi_tstamp:133200481152 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211922: rtcpu_vinotify_event: tstamp:4162938537 cch:0 vi:0 tag:FE channel:0x00 frame:71 vi_tstamp:133198393440 data:0x0000004700000020
     kworker/1:4-152     [001] ....   108.211922: rtcpu_vinotify_event: tstamp:4162938667 cch:0 vi:0 tag:FS channel:0x00 frame:72 vi_tstamp:133200380992 data:0x0000004800000010
     kworker/1:4-152     [001] ....   108.211923: rtcpu_vinotify_event: tstamp:4162938817 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:72 vi_tstamp:133200481152 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211923: rtcpu_vinotify_event: tstamp:4162938947 cch:0 vi:0 tag:FE channel:0x00 frame:72 vi_tstamp:133213846048 data:0x0000004800000020
     kworker/1:4-152     [001] ....   108.211923: rtcpu_vinotify_error: tstamp:4163204738 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:73 vi_tstamp:133222425472 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.211924: rtcpu_vinotify_event: tstamp:4163480831 cch:0 vi:0 tag:FS channel:0x00 frame:73 vi_tstamp:133222325216 data:0x0000004900000010
     kworker/1:4-152     [001] ....   108.211924: rtcpu_vinotify_event: tstamp:4163480962 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:73 vi_tstamp:133222425472 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267907: rtcpu_vinotify_error: tstamp:4163688187 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:74 vi_tstamp:133237895744 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267908: rtcpu_vinotify_error: tstamp:4163768620 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:75 vi_tstamp:133240469760 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267910: rtcpu_vinotify_event: tstamp:4164023428 cch:0 vi:0 tag:FE channel:0x00 frame:73 vi_tstamp:133235808000 data:0x0000004900000020
     kworker/1:4-152     [001] ....   108.267910: rtcpu_vinotify_event: tstamp:4164023559 cch:0 vi:0 tag:FS channel:0x00 frame:74 vi_tstamp:133237795552 data:0x0000004a00000010
     kworker/1:4-152     [001] ....   108.267910: rtcpu_vinotify_event: tstamp:4164023714 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:74 vi_tstamp:133237895744 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267911: rtcpu_vinotify_event: tstamp:4164023843 cch:0 vi:0 tag:FE channel:0x00 frame:74 vi_tstamp:133238382016 data:0x0000004a00000020
     kworker/1:4-152     [001] ....   108.267911: rtcpu_vinotify_event: tstamp:4164023991 cch:0 vi:0 tag:FS channel:0x00 frame:75 vi_tstamp:133240369600 data:0x0000004b00000010
     kworker/1:4-152     [001] ....   108.267912: rtcpu_vinotify_event: tstamp:4164024119 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:75 vi_tstamp:133240469760 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267912: rtcpu_vinotify_error: tstamp:4164454926 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:1 vi_tstamp:133262427328 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267912: rtcpu_vinotify_event: tstamp:4164566000 cch:0 vi:0 tag:FE channel:0x00 frame:75 vi_tstamp:133253834880 data:0x0000004b00000020
     kworker/1:4-152     [001] ....   108.267913: rtcpu_vinotify_event: tstamp:4164566129 cch:0 vi:0 tag:FS channel:0x00 frame:1 vi_tstamp:133262327072 data:0x0000000100000010
     kworker/1:4-152     [001] ....   108.267913: rtcpu_vinotify_event: tstamp:4164566281 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:1 vi_tstamp:133262427328 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267914: rtcpu_vinotify_event: tstamp:4164871937 cch:0 vi:0 tag:FE channel:0x00 frame:1 vi_tstamp:133275809824 data:0x0000000100000020
     kworker/1:4-152     [001] ....   108.267914: rtcpu_vinotify_error: tstamp:4164938243 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:2 vi_tstamp:133277897664 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267915: rtcpu_vinotify_error: tstamp:4165018694 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:3 vi_tstamp:133280471648 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267915: rtcpu_vinotify_event: tstamp:4165379483 cch:0 vi:0 tag:FS channel:0x00 frame:2 vi_tstamp:133277797408 data:0x0000000200000010
     kworker/1:4-152     [001] ....   108.267915: rtcpu_vinotify_event: tstamp:4165379612 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:2 vi_tstamp:133277897664 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.267916: rtcpu_vinotify_event: tstamp:4165379761 cch:0 vi:0 tag:FE channel:0x00 frame:2 vi_tstamp:133278383936 data:0x0000000200000020
     kworker/1:4-152     [001] ....   108.267916: rtcpu_vinotify_event: tstamp:4165379888 cch:0 vi:0 tag:FS channel:0x00 frame:3 vi_tstamp:133280371424 data:0x0000000300000010
     kworker/1:4-152     [001] ....   108.267916: rtcpu_vinotify_event: tstamp:4165380040 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:3 vi_tstamp:133280471648 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.323907: rtcpu_vinotify_error: tstamp:4165704931 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:4 vi_tstamp:133302431712 data:0x0000000000000589
     kworker/1:4-152     [001] ....   108.323909: rtcpu_vinotify_event: tstamp:4165922068 cch:0 vi:0 tag:FE channel:0x00 frame:3 vi_tstamp:133293854176 data:0x0000000300000020
     kworker/1:4-152     [001] ....   108.323909: rtcpu_vinotify_event: tstamp:4165922221 cch:0 vi:0 tag:FS channel:0x00 frame:4 vi_tstamp:133302331456 data:0x0000000400000010
     kworker/1:4-152     [001] ....   108.323909: rtcpu_vinotify_event: tstamp:4165922355 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:4 vi_tstamp:133302431712 data:0x0000000000000589

... repeating the same 4 lines per frame, 75 frames per second, no other messages

     kworker/1:4-152     [001] ....   115.215856: rtcpu_vinotify_event: tstamp:4381636603 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:72 vi_tstamp:140200557440 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.215856: rtcpu_vinotify_error: tstamp:4381957836 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:73 vi_tstamp:140222523776 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.215856: rtcpu_vinotify_event: tstamp:4382178484 cch:0 vi:0 tag:FE channel:0x00 frame:72 vi_tstamp:140213922496 data:0x0000004800000020
     kworker/1:4-152     [001] ....   115.215857: rtcpu_vinotify_event: tstamp:4382178614 cch:0 vi:0 tag:FS channel:0x00 frame:73 vi_tstamp:140222423520 data:0x0000004900000010
     kworker/1:4-152     [001] ....   115.215857: rtcpu_vinotify_event: tstamp:4382178767 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:73 vi_tstamp:140222523776 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.215857: rtcpu_vinotify_error: tstamp:4382441583 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:74 vi_tstamp:140237994016 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.215858: rtcpu_vinotify_event: tstamp:4382442138 cch:0 vi:0 tag:FE channel:0x00 frame:73 vi_tstamp:140235906272 data:0x0000004900000020
     kworker/1:4-152     [001] ....   115.215858: rtcpu_vinotify_event: tstamp:4382442292 cch:0 vi:0 tag:FS channel:0x00 frame:74 vi_tstamp:140237893856 data:0x0000004a00000010
     kworker/1:4-152     [001] ....   115.215858: rtcpu_vinotify_event: tstamp:4382442425 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:74 vi_tstamp:140237994016 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.215859: rtcpu_vinotify_error: tstamp:4382521700 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:75 vi_tstamp:140240568128 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271848: rtcpu_vinotify_event: tstamp:4382937986 cch:0 vi:0 tag:FE channel:0x00 frame:74 vi_tstamp:140238480320 data:0x0000004a00000020
     kworker/1:4-152     [001] ....   115.271849: rtcpu_vinotify_event: tstamp:4382938118 cch:0 vi:0 tag:FS channel:0x00 frame:75 vi_tstamp:140240467872 data:0x0000004b00000010
     kworker/1:4-152     [001] ....   115.271849: rtcpu_vinotify_event: tstamp:4382938271 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:75 vi_tstamp:140240568128 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271850: rtcpu_vinotify_error: tstamp:4383207775 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:1 vi_tstamp:140262517280 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271851: rtcpu_vinotify_event: tstamp:4383480312 cch:0 vi:0 tag:FE channel:0x00 frame:75 vi_tstamp:140253932896 data:0x0000004b00000020
     kworker/1:4-152     [001] ....   115.271851: rtcpu_vinotify_event: tstamp:4383480464 cch:0 vi:0 tag:FS channel:0x00 frame:1 vi_tstamp:140262417088 data:0x0000000100000010
     kworker/1:4-152     [001] ....   115.271851: rtcpu_vinotify_event: tstamp:4383480595 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:1 vi_tstamp:140262517280 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271852: rtcpu_vinotify_error: tstamp:4383691048 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:2 vi_tstamp:140277987328 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271852: rtcpu_vinotify_error: tstamp:4383771486 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:3 vi_tstamp:140280561376 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271853: rtcpu_vinotify_event: tstamp:4384022903 cch:0 vi:0 tag:FE channel:0x00 frame:1 vi_tstamp:140275899776 data:0x0000000100000020
     kworker/1:4-152     [001] ....   115.271853: rtcpu_vinotify_event: tstamp:4384023035 cch:0 vi:0 tag:FS channel:0x00 frame:2 vi_tstamp:140277887104 data:0x0000000200000010
     kworker/1:4-152     [001] ....   115.271853: rtcpu_vinotify_event: tstamp:4384023187 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:2 vi_tstamp:140277987328 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.271854: rtcpu_vinotify_event: tstamp:4384023318 cch:0 vi:0 tag:FE channel:0x00 frame:2 vi_tstamp:140278473856 data:0x0000000200000020
     kworker/1:4-152     [001] ....   115.271854: rtcpu_vinotify_event: tstamp:4384023467 cch:0 vi:0 tag:FS channel:0x00 frame:3 vi_tstamp:140280461152 data:0x0000000300000010
     kworker/1:4-152     [001] ....   115.271854: rtcpu_vinotify_event: tstamp:4384023597 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:3 vi_tstamp:140280561376 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327847: rtcpu_vinotify_error: tstamp:4384457999 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:4 vi_tstamp:140302528384 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327850: rtcpu_vinotify_event: tstamp:4384565472 cch:0 vi:0 tag:FE channel:0x00 frame:3 vi_tstamp:140293926496 data:0x0000000300000020
     kworker/1:4-152     [001] ....   115.327850: rtcpu_vinotify_event: tstamp:4384565602 cch:0 vi:0 tag:FS channel:0x00 frame:4 vi_tstamp:140302428192 data:0x0000000400000010
     kworker/1:4-152     [001] ....   115.327850: rtcpu_vinotify_event: tstamp:4384565752 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:4 vi_tstamp:140302528384 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327851: rtcpu_vinotify_event: tstamp:4384875101 cch:0 vi:0 tag:FE channel:0x00 frame:4 vi_tstamp:140315910944 data:0x0000000400000020
     kworker/1:4-152     [001] ....   115.327851: rtcpu_vinotify_error: tstamp:4384941402 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:5 vi_tstamp:140317998656 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327851: rtcpu_vinotify_error: tstamp:4385021839 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:6 vi_tstamp:140320572704 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327852: rtcpu_vinotify_event: tstamp:4385380066 cch:0 vi:0 tag:FS channel:0x00 frame:5 vi_tstamp:140317898432 data:0x0000000500000010
     kworker/1:4-152     [001] ....   115.327852: rtcpu_vinotify_event: tstamp:4385380197 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:5 vi_tstamp:140317998656 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327853: rtcpu_vinotify_event: tstamp:4385380349 cch:0 vi:0 tag:FE channel:0x00 frame:5 vi_tstamp:140318484960 data:0x0000000500000020
     kworker/1:4-152     [001] ....   115.327853: rtcpu_vinotify_event: tstamp:4385380477 cch:0 vi:0 tag:FS channel:0x00 frame:6 vi_tstamp:140320472480 data:0x0000000600000010
     kworker/1:4-152     [001] ....   115.327853: rtcpu_vinotify_event: tstamp:4385380628 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:6 vi_tstamp:140320572704 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327854: rtcpu_vinotify_error: tstamp:4385707906 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:7 vi_tstamp:140342525952 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.327854: rtcpu_vinotify_event: tstamp:4385922637 cch:0 vi:0 tag:FE channel:0x00 frame:6 vi_tstamp:140333955200 data:0x0000000600000020
     kworker/1:4-152     [001] ....   115.327854: rtcpu_vinotify_event: tstamp:4385922790 cch:0 vi:0 tag:FS channel:0x00 frame:7 vi_tstamp:140342425760 data:0x0000000700000010
     kworker/1:4-152     [001] ....   115.327854: rtcpu_vinotify_event: tstamp:4385922921 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:7 vi_tstamp:140342525952 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383849: rtcpu_vinotify_error: tstamp:4386191448 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:8 vi_tstamp:140357996000 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383850: rtcpu_vinotify_error: tstamp:4386271830 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:9 vi_tstamp:140360570048 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383852: rtcpu_vinotify_event: tstamp:4386465223 cch:0 vi:0 tag:FE channel:0x00 frame:7 vi_tstamp:140355908544 data:0x0000000700000020
     kworker/1:4-152     [001] ....   115.383852: rtcpu_vinotify_event: tstamp:4386465354 cch:0 vi:0 tag:FS channel:0x00 frame:8 vi_tstamp:140357895776 data:0x0000000800000010
     kworker/1:4-152     [001] ....   115.383852: rtcpu_vinotify_event: tstamp:4386465508 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:8 vi_tstamp:140357996000 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383853: rtcpu_vinotify_event: tstamp:4386465637 cch:0 vi:0 tag:FE channel:0x00 frame:8 vi_tstamp:140358482560 data:0x0000000800000020
     kworker/1:4-152     [001] ....   115.383853: rtcpu_vinotify_event: tstamp:4386465786 cch:0 vi:0 tag:FS channel:0x00 frame:9 vi_tstamp:140360469824 data:0x0000000900000010
     kworker/1:4-152     [001] ....   115.383854: rtcpu_vinotify_event: tstamp:4386465917 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:9 vi_tstamp:140360570048 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383854: rtcpu_vinotify_event: tstamp:4386953472 cch:0 vi:0 tag:FE channel:0x00 frame:9 vi_tstamp:140373935168 data:0x0000000900000020
     kworker/1:4-152     [001] ....   115.383854: rtcpu_vinotify_event: tstamp:4386953602 cch:0 vi:0 tag:FS channel:0x00 frame:10 vi_tstamp:140382418880 data:0x0000000a00000010
     kworker/1:4-152     [001] ....   115.383855: rtcpu_vinotify_error: tstamp:4386957698 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:10 vi_tstamp:140382519040 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383855: rtcpu_vinotify_error: tstamp:4387441102 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:11 vi_tstamp:140397989120 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383855: rtcpu_vinotify_event: tstamp:4387495218 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:10 vi_tstamp:140382519040 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383856: rtcpu_vinotify_event: tstamp:4387495351 cch:0 vi:0 tag:FE channel:0x00 frame:10 vi_tstamp:140395901600 data:0x0000000a00000020
     kworker/1:4-152     [001] ....   115.383856: rtcpu_vinotify_event: tstamp:4387495506 cch:0 vi:0 tag:FS channel:0x00 frame:11 vi_tstamp:140397888864 data:0x0000000b00000010
     kworker/1:4-152     [001] ....   115.383857: rtcpu_vinotify_event: tstamp:4387495637 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:11 vi_tstamp:140397989120 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.383857: rtcpu_vinotify_event: tstamp:4387495788 cch:0 vi:0 tag:FE channel:0x00 frame:11 vi_tstamp:140398475552 data:0x0000000b00000020
     kworker/1:4-152     [001] ....   115.383857: rtcpu_vinotify_error: tstamp:4387521614 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:12 vi_tstamp:140400563136 data:0x0000000000000589
        v4l2-ctl-2406    [002] ....   115.391128: tegra_channel_close: vi-output, hfl118 7-0030
        v4l2-ctl-2406    [002] ....   115.391160: tegra_channel_set_stream: enable : 0x0
        v4l2-ctl-2406    [002] ....   115.391162: tegra_channel_set_stream: hfl118 7-0030 : 0x0
        v4l2-ctl-2406    [002] ....   115.393688: tegra_channel_set_stream: 13e40000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2406    [002] ....   115.393691: csi_s_stream: enable : 0x0
        v4l2-ctl-2406    [002] ....   115.406406: tegra_channel_set_power: hfl118 7-0030 : 0x0
        v4l2-ctl-2406    [002] ....   115.406415: camera_common_s_power: status : 0x0
        v4l2-ctl-2406    [002] ....   115.406425: tegra_channel_set_power: 13e40000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2406    [002] ....   115.406429: csi_s_power: enable : 0x0
     kworker/1:4-152     [001] ....   115.439747: rtcpu_vinotify_event: tstamp:4388037788 cch:0 vi:0 tag:FS channel:0x00 frame:12 vi_tstamp:140400462912 data:0x0000000c00000010
     kworker/1:4-152     [001] ....   115.439748: rtcpu_vinotify_event: tstamp:4388037943 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:12 vi_tstamp:140400563136 data:0x0000000000000589
     kworker/1:4-152     [001] ....   115.439749: rtcpu_vinotify_event: tstamp:4388038077 cch:0 vi:0 tag:FE channel:0x00 frame:12 vi_tstamp:140413928256 data:0x0000000c00000020
     kworker/1:4-152     [001] ....   115.439752: rtcpu_string: tstamp:4388097063 id:0x04010000 str:"tegra_nvcsi_stream_close(vm0, stream=0, csi=0)
"
     kworker/1:4-152     [001] ....   121.263940: rtcpu_string: tstamp:4569916714 id:0x04010000 str:"VM0 deactivating."

ShaneCCC · December 20, 2022, 8:24am

Do you check without virtual channel?
For the virtual channel each VC-ID should have a video# node to control it.

jimrmooney · December 20, 2022, 9:13am

Thanks for the quick reply Shane.

Do you check without virtual channel?

Do you mean remove all the vc-id and vc_id from the device tree? I previously tried a version without those which was not working, but I can retest that in case there was some other reason that earlier version was failing.

I can not make the CSI-2 stream have “no” VC-ID, the two bits in the first byte of every CSI-2 v1 header can only be VC-ID 0-3, not unset.

For the virtual channel each VC-ID should have a video# node to control it.

That sounds promising, can you link me to documentation or example code for the video# node you refer to?

I do have devnode=“video0”:

	i2c@c250000 {
		hfl118_a@30 {
			devnode = "video0";

… but you are suggesting a node video0 somewhere in the device tree too, like this?

	video0 {

I have not seen that in the examples and documentation I have looked at.

When I dump my entire live /proc/device-tree to a file.dts the only mention of “video” is the devnode = "video0";

jimrmooney · December 20, 2022, 9:33am

Do you check without virtual channel?

My retest confirmed that removing the vc-id and vc_id lines from the device tree seemed to make no difference to the split Virtual Channels 0x00 and 0x01 in the trace:

     kworker/0:1-15      [000] ....   132.380125: rtcpu_vinotify_error: tstamp:4917589906 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:34 vi_tstamp:157362750784 data:0x0000000000000589
     kworker/0:1-15      [000] ....   132.380126: rtcpu_vinotify_event: tstamp:4917738874 cch:0 vi:0 tag:FE channel:0x00 frame:33 vi_tstamp:157354150944 data:0x0000002100000020
     kworker/0:1-15      [000] ....   132.380126: rtcpu_vinotify_event: tstamp:4917739006 cch:0 vi:0 tag:FS channel:0x00 frame:34 vi_tstamp:157362650592 data:0x0000002200000010
     kworker/0:1-15      [000] ....   132.380126: rtcpu_vinotify_event: tstamp:4917739189 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:34 vi_tstamp:157362750784 data:0x0000000000000589
     kworker/0:1-15      [000] ....   132.380126: rtcpu_vinotify_event: tstamp:4918007143 cch:0 vi:0 tag:FE channel:0x00 frame:34 vi_tstamp:157376133312 data:0x0000002200000020

ShaneCCC · December 20, 2022, 9:38am

Does this chip output embedded data?
Please add embedded_metadata_height in device tree for correct value.

jimrmooney · December 20, 2022, 11:40am

Does this chip output embedded data?

I think it has 1 non-pixel line but I would like to prove what it is outputting without relying on assumptions; if NVCSI has a debug way to dump out the incoming CSI packets before they are unpacked that would let me confirm the packets.

This sensor uses a parallel serializer (DS90UB913) and is normally deserialised to parallel (DS90UB914 des). We are using CSI-2 (DS90UB954 des) so the 954 chip is generating some of the CSI-2 v1 protocol itself, most of the data but not all is from the sensor chip.

On my logic analyzer (fast enough to record frames and lines but not fast enough to record pixels) I confirmed 3 VSync periods in each 25Hz cycle, the number of HSync pulses per frame is 256+3, 8+3 and 64+3 in sequence. We expect to see CHANSEL_SHORT_FRAME events for the second and 3rd frames, they report either 0x0a (8+2) lines or 0x42 (64+2) lines, no matter whether embedded_metadata_height="0"; or 1 or 2 or 3. That suggests there are 256+2 pixel lines in the first frame and one non-pixel line in each of the three frames, possibly embedded data. There may be 2 blank pixel lines, I can’t see or receive the CHANSEL_NOMATCH CSI-2 packet contents to confirm.

When embedded_metadata_height is non-0 then there are two additional CSIMUX_STREAM lines with cch:-1 (before and after the 4 VIFALC_TDSTATE channel 0x23 messages that are always early in every trace):

     kworker/3:5-237     [003] ....   160.248305: rtcpu_vinotify_error: tstamp:5788499852 cch:-1 vi:0 tag:CSIMUX_STREAM channel:0x00 frame:0 vi_tstamp:185231884160 data:0x0000000000000001
     kworker/3:5-237     [003] ....   160.248306: rtcpu_vinotify_event: tstamp:5788500550 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:185216093536 data:0x379d580010000000
     kworker/3:5-237     [003] ....   160.248307: rtcpu_vinotify_event: tstamp:5788500684 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:185216100032 data:0x0000000031000001
     kworker/3:5-237     [003] ....   160.248307: rtcpu_vinotify_event: tstamp:5788500837 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:185216155520 data:0x379d550010000000
     kworker/3:5-237     [003] ....   160.248307: rtcpu_vinotify_event: tstamp:5788500968 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:185216162080 data:0x0000000031000002
     kworker/3:5-237     [003] ....   160.248307: rtcpu_vinotify_event: tstamp:5788945958 cch:-1 vi:0 tag:CSIMUX_STREAM channel:0x00 frame:0 vi_tstamp:185231884160 data:0x0000000000000001

I have tested with 0, 1, 2 and 3 lines and the trace seems unchanged except for the many expected minor differences with timestamps and frame numbers. I substituted them out before getting pretty clean diffs; the remaining differences seem mainly just slight sequence changes in the same series of events.

jimrmooney · December 26, 2022, 3:28pm

I found a comment in kernel/nvidia/include/soc/tegra/camrtc-capture.h that suggests this CHANSEL_NOMATCH error message may actually be caused by NVCSI abandoning scheduling new capture requests:

/**
* Incoming frame not matched by any VI channel.
* This error is usually caused by not having a pending
* capture request ready to catch the incoming frame.
* The frame will be dropped.
*/
#define CAPTURE_STATUS_NOTIFY_BIT_CHANSEL_NO_MATCH MK_BIT64(46)

Is NVCSI+VI giving up on scheduling capture requests because 4 frames are discarded in a row? There are no rtcpu_vinotify_error traces until after those first 4 frames. Can I make it persist longer scheduling capture requests? Unlimited?

I probably made a wrong assumption earlier about the VC 0x01 being the cause of the CHANSEL_NOMATCH, it sounds likely the problem is actually that no capture request was made (and the event VC being different from the VC_ID on the CSI packets seems common on error events).

[  208.076470] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 4, flags: 0, err_data 512
[  208.091949] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 5, flags: 0, err_data 512
[  208.094560] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 6, flags: 0, err_data 512
[  208.116479] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 7, flags: 0, err_data 512

The UB954 deserializer by default deletes the first line if it is short, so in my earlier testing the first line was not being transmitted over the CSI channel. After I reconfigured that I now see the expected number of lines and a new short line event notification 0x200 in the trace which appears to be the err_data 512 reported in dmesg.

In every frame line 0 triggers a Short Line event (even if embedded_metadata_height="1" because the DType of the first line is 0x2c RAW12):
rtcpu_vinotify_event: ... CHANSEL_FAULT channel:0x23 frame:... data:0x0000000000000200

In every frame with 256+3 lines (every 3rd frame), the last line 258 (0x102) also sets the short line bit and frame end bit 0x202, right before ATOMP_FRAME_DONE with data 0x0 then FE with data 0x20 set:

...: rtcpu_vinotify_event: tstamp:4202808341 cch:0 vi:0 tag:CHANSEL_FAULT channel:0x23 frame:3 vi_tstamp:134489552928 data:0x0000000001020202
...: rtcpu_vinotify_event: tstamp:4202808473 cch:0 vi:0 tag:ATOMP_FRAME_DONE channel:0x23 frame:3 vi_tstamp:134489553888 data:0x0000000000000000
...: rtcpu_vinotify_event: tstamp:4202808623 cch:0 vi:0 tag:FE channel:0x00 frame:3 vi_tstamp:134489555008 data:0x0000000300000020

Are the short line and short frame events causing the frames to be discarded?
If yes, how can I mask those two faults to stop them discarding the frame?
I see register VI_CSIMUX_CSI_STREAM_0 is a FAULT_MASK with bit 3 masking a “Line short error”.
I don’t see a fault mask bit for a short frame.
How do I set the “Line short error” mask bit through NVCSI?
Is that a message request CAPTURE_HSM_CHANSEL_ERROR_MASK_REQ (not currently used in csi5_fops)?
Could I implement that in csi5_fops.c with something like this:

	memset(&msg, 0, sizeof(msg));
	msg.header.msg_id = CAPTURE_HSM_CHANSEL_ERROR_MASK_REQ;
	msg.hsm_chansel_mask_req.hsm_chansel_error_config.chansel_correctable_mask = 0x08; // Suppress short line error
	msg.hsm_chansel_mask_req.hsm_chansel_error_config.chansel_uncorrectable_mask = 0x08; // Suppress short line error
	err = csi5_send_control_message(tegra_chan->tegra_vi_channel[0], &msg,
			&msg.hsm_chansel_mask_resp.result);

The UB954 deserializer when receiving raw data can not put different data types on different lines, I can choose any DType value, but all the CSI lines must be sent with the same DType. The default is 0x2c RAW12, but I tested with the DType to 0x12 to make the entire frame embedded data, and I set embedded_metadata_height="259" to cover the entire frame. Result: I no longer got the CHANSEL_FAULT short line events err_data 0x200, instead I got CHANSEL_SHORT_FRAME events and err_data 0x20000 or 0x40000:

[  102.309488] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 0, flags: 0, err_data 131072
[  102.312060] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 0, flags: 0, err_data 262144
[  102.327549] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 0, flags: 0, err_data 262144
[  102.349484] tegra-camrtc-capture-vi tegra-capture-vi: corr_err: discarding frame 0, flags: 0, err_data 131072

I do get a ATOMP_EMB_DATA_DONE event on the 259 line frames, so I may be able to receive each entire frame as embedded data from chan->emb_buf in vi5_fops.c even if every frame has no pixel lines to process:

     kworker/0:7-190     [000] ....   102.353392: rtcpu_vinotify_event: tstamp:3979142367 cch:0 vi:0 tag:FS channel:0x00 frame:19 vi_tstamp:127318564096 data:0x0000001300000010
     kworker/0:7-190     [000] ....   102.353393: rtcpu_vinotify_event: tstamp:3979142509 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:19 vi_tstamp:127318564192 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353393: rtcpu_vinotify_event: tstamp:3979142664 cch:0 vi:0 tag:CHANSEL_EMBED_SOF channel:0x23 frame:19 vi_tstamp:127318610976 data:0x0000000000000004
     kworker/0:7-190     [000] ....   102.353393: rtcpu_vinotify_event: tstamp:3979142797 cch:0 vi:0 tag:CHANSEL_EMBED_EOF channel:0x23 frame:19 vi_tstamp:127332044704 data:0x0000000001020008
     kworker/0:7-190     [000] ....   102.353393: rtcpu_vinotify_event: tstamp:3979142952 cch:0 vi:0 tag:ATOMP_EMB_DATA_DONE channel:0x23 frame:19 vi_tstamp:127332045696 data:0x0000000000000000
     kworker/0:7-190     [000] ....   102.353394: rtcpu_vinotify_event: tstamp:3979143084 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:19 vi_tstamp:127332070304 data:0x0000000003020001
     kworker/0:7-190     [000] ....   102.353394: rtcpu_vinotify_event: tstamp:3979143237 cch:0 vi:0 tag:FE channel:0x00 frame:19 vi_tstamp:127332046784 data:0x0000001300000020
     kworker/0:7-190     [000] ....   102.353394: rtcpu_vinotify_event: tstamp:3979143371 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:19 vi_tstamp:127332046816 data:0x0000200001000000
     kworker/0:7-190     [000] ....   102.353394: rtcpu_vinotify_event: tstamp:3979143524 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:19 vi_tstamp:127332144512 data:0x0000000001020001
     kworker/0:7-190     [000] ....   102.353394: rtcpu_vinotify_event: tstamp:3979143657 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:19 vi_tstamp:127332046912 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979143808 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:127332421856 data:0x379d580010000000
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979143939 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:127332465216 data:0x0000000031000003
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979634015 cch:0 vi:0 tag:FS channel:0x00 frame:20 vi_tstamp:127334034304 data:0x0000001400000010
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979634154 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:20 vi_tstamp:127334034400 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979634307 cch:0 vi:0 tag:CHANSEL_EMBED_SOF channel:0x23 frame:20 vi_tstamp:127334080960 data:0x0000000000000004
     kworker/0:7-190     [000] ....   102.353395: rtcpu_vinotify_event: tstamp:3979634438 cch:0 vi:0 tag:FE channel:0x00 frame:20 vi_tstamp:127334620832 data:0x0000001400000020
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979634589 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:20 vi_tstamp:127334620864 data:0x000b200000000000
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979634723 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:20 vi_tstamp:127334689888 data:0x0000000001020002
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979634874 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:20 vi_tstamp:127334620864 data:0x0000200001000000
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979635006 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:20 vi_tstamp:127334620928 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979635158 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:127335018880 data:0x379d550010000000
     kworker/0:7-190     [000] ....   102.353396: rtcpu_vinotify_event: tstamp:3979635289 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:127335062208 data:0x0000000031000004
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979635437 cch:0 vi:0 tag:FS channel:0x00 frame:21 vi_tstamp:127336608320 data:0x0000001500000010
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979635568 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:21 vi_tstamp:127336608448 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979635718 cch:0 vi:0 tag:CHANSEL_EMBED_SOF channel:0x23 frame:21 vi_tstamp:127336655008 data:0x0000000000000004
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979699835 cch:0 vi:0 tag:FE channel:0x00 frame:21 vi_tstamp:127350073568 data:0x0000001500000020
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979699985 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:21 vi_tstamp:127350073600 data:0x0043200000000000
     kworker/0:7-190     [000] ....   102.353397: rtcpu_vinotify_event: tstamp:3979700116 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:21 vi_tstamp:127350142624 data:0x0000000001020003
     kworker/0:7-190     [000] ....   102.353398: rtcpu_vinotify_event: tstamp:3980231316 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:21 vi_tstamp:127350073600 data:0x0000200001000000
     kworker/0:7-190     [000] ....   102.353398: rtcpu_vinotify_event: tstamp:3980231449 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:21 vi_tstamp:127350073664 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353398: rtcpu_vinotify_event: tstamp:3980231598 cch:0 vi:0 tag:FS channel:0x00 frame:22 vi_tstamp:127358572800 data:0x0000001600000010
     kworker/0:7-190     [000] ....   102.353398: rtcpu_vinotify_event: tstamp:3980231731 cch:0 vi:0 tag:ATOMP_FS channel:0x00 frame:22 vi_tstamp:127358572928 data:0x0000000800000000
     kworker/0:7-190     [000] ....   102.353398: rtcpu_vinotify_event: tstamp:3980231882 cch:0 vi:0 tag:CHANSEL_EMBED_SOF channel:0x23 frame:22 vi_tstamp:127358619488 data:0x0000000000000004
     kworker/0:7-190     [000] ....   102.353399: rtcpu_vinotify_error: tstamp:3980444250 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:23 vi_tstamp:127374089664 data:0x0000000000000249
     kworker/0:7-190     [000] ....   102.409191: rtcpu_vinotify_error: tstamp:3980525933 cch:0 vi:0 tag:CHANSEL_NOMATCH channel:0x01 frame:24 vi_tstamp:127376663712 data:0x0000000000000249
     kworker/0:7-190     [000] ....   102.409194: rtcpu_vinotify_event: tstamp:3980526260 cch:0 vi:0 tag:CHANSEL_EMBED_EOF channel:0x23 frame:22 vi_tstamp:127372053440 data:0x0000000001020008
     kworker/0:7-190     [000] ....   102.409195: rtcpu_vinotify_event: tstamp:3980526412 cch:0 vi:0 tag:ATOMP_EMB_DATA_DONE channel:0x23 frame:22 vi_tstamp:127372054432 data:0x0000000000000000
     kworker/0:7-190     [000] ....   102.409196: rtcpu_vinotify_event: tstamp:3980526545 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:22 vi_tstamp:127372079072 data:0x0000000003020004
     kworker/0:7-190     [000] ....   102.409196: rtcpu_vinotify_event: tstamp:3980526694 cch:0 vi:0 tag:FE channel:0x00 frame:22 vi_tstamp:127372055456 data:0x0000001600000020
     kworker/0:7-190     [000] ....   102.409196: rtcpu_vinotify_event: tstamp:3980526829 cch:0 vi:0 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:22 vi_tstamp:127372055456 data:0x0000200001000000
     kworker/0:7-190     [000] ....   102.409199: rtcpu_vinotify_event: tstamp:3980526980 cch:0 vi:0 tag:VIFALC_ACTIONLST channel:0x23 frame:22 vi_tstamp:127372153248 data:0x0000000001020004
     kworker/0:7-190     [000] ....   102.409200: rtcpu_vinotify_event: tstamp:3980527114 cch:0 vi:0 tag:ATOMP_FE channel:0x00 frame:22 vi_tstamp:127372055552 data:0x0000000800000000

kayccc · January 18, 2023, 1:50am

Sorry for the late response, have you managed to get issue resolved or still need the support? Thanks

jimrmooney · January 18, 2023, 3:05am

Thank you @kayccc, I would still like advice from someone with insight into the Falcon processor streaming functionality. Can someone please either:

Tell me how to officially mask this particular expected data “error” before capture, or
Confirm that my current post-capture workaround is safe: I am ignoring one specific kind of CAPTURE_STATUS_FALCON_ERROR and continuing streaming all the data successfully despite the error. I hope that this won’t cause an issue with the Falcon somehow.

After days of kernel debugging over the holidays I found a workaround patching vi5_ops.c in the kernel to ignore one particular error condition from the Falcon processing after it occurs:

diff -u kernel{-orig,}/nvidia/drivers/media/platform/tegra/camera/vi/vi5_fops.c
--- kernel-orig/nvidia/drivers/media/platform/tegra/camera/vi/vi5_fops.c	2022-08-11 11:15:42.000000000 +0800
+++ kernel/nvidia/drivers/media/platform/tegra/camera/vi/vi5_fops.c	2023-01-14 11:53:07.546719975 +0800
@@ -467,7 +467,11 @@
 				dev_err(vi->dev, "uncorr_err: request err %d\n", err);
 			}
 			goto uncorr_err;
-		} else if (descr->status.status != CAPTURE_STATUS_SUCCESS) {
+		} else if (descr->status.status != CAPTURE_STATUS_SUCCESS &&
+			// Tolerate short frames rejected by Falcon with no other error flags
+			!(descr->status.status == CAPTURE_STATUS_FALCON_ERROR &&
+			descr->status.flags == 0 &&
+			descr->status.err_data == 0x200)) { // Short line/frame flag only?
 			if ((descr->status.flags
 					& CAPTURE_STATUS_FLAG_CHANNEL_IN_ERROR) != 0) {
 				chan->queue_error = true;

All the data has already made it into the buffer, but without that kernel patch all buffers are rejected and no data is streamed.

The Falcon error I’m trying to mask is caused by one or both of these data “features”:

the embedded data first line on every frame is shorter than the other lines and has DType RAW12 pixel data, not DType embedded data.
the frames have 3 different heights in a cycle, triggering SHORT_FRAME on 2 out of every 3 frames.

Dead ends I tried:

I can not make the CSI source properly apply two different DTypes to the lines, embedded data for the first line and pixel data for the rest. This is a hardware limitation of the TI DS90UB954 deserialiser chip which can only apply one DType to all lines coming from a DS90UB913 serialiser (non-CSI, no DType).
If I make all lines DType embedded data (0 lines of pixel data) then the short line is not an error, though the varying frame height is still reported. But, because the L4T VI processing implementation only uses one shared buffer for embedded data (emb_buf, not a queue of buffers like the pixel data) the incoming frame starts getting overwritten by the following frame within 3ms, before it can be reliably processed, so that workaround was much worse.

jimrmooney · February 6, 2023, 7:37pm

Could the Falcon failure prevent the CPU cache sync/clean after a frame is written into a DMA memory buffer by NVCSI/VI?

I have noticed that the top parts of some frames (0-50 lines of pixel data) appear to be from an earlier frame that was in the same buffer. In my code I am using DMA_BUF_IOCTL_SYNC with DMA_BUF_SYNC_READ | DMA_BUF_SYNC_START before the file write and DMA_BUF_SYNC_READ | DMA_BUF_SYNC_END after the file write, but I’m still getting the glitch in the data written out.

This happens often even using dd or v4l2-ctl to capture raw data to a file. If I increase the number of buffers this problem does not seem to happen the first time a buffer is used, only when buffers are recycled. Example commands:

dd if=/dev/video0 of=testdd.raw bs=1060864 count=512
v4l2-ctl -d /dev/video0 --set-ctrl bypass_mode=0 --stream-mmap 16 --stream-count=512 --stream-to=testv4l2-ctl.raw

One possible cause of this symptom might be that the CPU cache (populated when the earlier frame was saved to the file) is not being invalidated when the new frame is written to the same buffer by NVCSI/VI.

I am ignoring a Falcon error in vi5_fops.c because I have not been able to mask the short first line & short frames from triggering the error that normally dumps the frame. If I was not ignoring this error then the frames would all be rejected, so maybe the logic might skip the CPU cache sync/clean.

ShaneCCC · June 1, 2023, 5:35pm

For the CHANSEL_SHORT_FRAME you can boost the clocks to try.
If didn’t help that tell the sensor output size less than expected. You need to modify sensor driver reported less height for it.

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

system · June 28, 2023, 2:21am

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.