V4L2 Driver Timeout Issues with Xilinx FPGA and Orin Nano DevKit

Autonomous Machines Jetson & Embedded Systems Jetson Orin Nano
,
1

Hello Developers,

I am currently developing a V4L2 driver to output MIPI CSI-2 data from an FPGA as an image. The FPGA is based on Xilinx, and the image is being output at 1920x1200 in RGB888 format. The line rate is 800Mbps, and I have adjusted the hmax and vmax of the CMOS sensor to output at 15 fps.

The FPGA continuously outputs a specified image format to the AP without any control via I2C. The AP is an Orin Nano DevKit with Jetson Linux r36.3 installed.

I am currently facing an issue with streaming images via V4L2. The driver loads correctly, and the device path is detected, but when I start streaming, continuous timeouts occur, preventing successful streaming. The trace log output is as follows:

# tracer: nop
#
# entries-in-buffer/entries-written: 388/388   #P:4
#
#                                _-------=> irqs-off
#                               / _------=> need-resched
#                              | / _-----=> need-resched-lazy
#                              || / _----=> hardirq/softirq
#                              ||| / _---=> preempt-depth
#                              |||| / _--=> preempt-lazy-depth
#                              ||||| / _-=> migrate-disable
#                              |||||| /     delay
#           TASK-PID     CPU#  |||||||  TIMESTAMP  FUNCTION
#              | |         |   |||||||      |         |
     kworker/0:4-162     [000] .......   471.788020: rtcpu_string: tstamp:15466355043 id:0x04010000 str:"VM0 deactivating."
         QThread-5629    [002] .......   541.466149: tegra_channel_open: vi-output, fpga 9-001a
         QThread-5629    [000] .......   541.485676: tegra_channel_set_power: fpga 9-001a : 0x1
         QThread-5629    [000] .......   541.485689: camera_common_s_power: status : 0x1
         QThread-5629    [000] .......   541.787117: tegra_channel_set_power: 13e00000.host1x:nvcsi@15a00000- : 0x1
         QThread-5629    [000] .......   541.787122: csi_s_power: enable : 0x1
         QThread-5629    [000] .......   541.787708: tegra_channel_capture_setup: vnc_id 0 W 1920 H 1200 fmt 9
 vi-output, fpga-5630    [003] .......   541.796032: vi_task_submit: class_id:48 ch:0 syncpt_id:31 syncpt_thresh:174 pid:5630 tid:5630
 vi-output, fpga-5630    [003] .......   541.796039: vi_task_submit: class_id:48 ch:0 syncpt_id:31 syncpt_thresh:174 pid:5630 tid:5630
 vi-output, fpga-5630    [003] .......   541.796040: vi_task_submit: class_id:48 ch:0 syncpt_id:31 syncpt_thresh:174 pid:5630 tid:5630
 vi-output, fpga-5630    [003] .......   541.796042: vi_task_submit: class_id:48 ch:0 syncpt_id:31 syncpt_thresh:174 pid:5630 tid:5630
         QThread-5629    [000] .......   541.796090: tegra_channel_set_stream: enable : 0x1
         QThread-5629    [000] .......   541.796651: tegra_channel_set_stream: 13e00000.host1x:nvcsi@15a00000- : 0x1
         QThread-5629    [000] .......   541.796654: csi_s_stream: enable : 0x1
         QThread-5629    [000] .......   541.797189: tegra_channel_set_stream: fpga 9-001a : 0x1
     kworker/0:4-162     [000] .......   541.831556: rtcpu_string: tstamp:17654198711 id:0x04010000 str:"VM0 activating."
     kworker/0:4-162     [000] .......   541.831560: rtcpu_string: tstamp:17654290617 id:0x04010000 str:"calibration status1 23294a32 status2 25294611
"
     kworker/0:4-162     [000] .......   541.831574: rtcpu_string: tstamp:17654291063 id:0x04010000 str:"calibration status1 2108681 status2 210dc33
"
     kworker/0:4-162     [000] .......   541.831576: rtcpu_string: tstamp:17654291509 id:0x04010000 str:"calibration status1 2719d6f3 status2 2d4a4a74
"
     kworker/0:4-162     [000] .......   541.831577: rtcpu_string: tstamp:17654291950 id:0x04010000 str:"calibration status1 2f69ceb2 status2 2929ca93
"
     kworker/0:4-162     [000] .......   541.831579: rtcpu_string: tstamp:17654300389 id:0x04010000 str:"NVCSILP clock rate = 408000000 Hz.
"
     kworker/0:4-162     [000] .......   541.831581: rtcpu_string: tstamp:17654375325 id:0x04010000 str:"tegra_nvcsi_stream_set_config(vm0, stream=2, csi"
     kworker/0:4-162     [000] .......   541.831581: rtcpu_string: tstamp:17654375430 id:0x04010000 str:"=2)
"
     kworker/0:4-162     [000] .......   541.831583: rtcpu_string: tstamp:17654375803 id:0x04010000 str:"MIPI clock = 400000 kHz, tHS-SETTLE = 0, tCLK-SE"
     kworker/0:4-162     [000] .......   541.831583: rtcpu_string: tstamp:17654375906 id:0x04010000 str:"TTLE = 0
"
     kworker/0:4-162     [000] .......   541.831585: rtcpu_string: tstamp:17654376116 id:0x04010000 str:"===== NVCSI Stream Configuration =====
"
     kworker/0:4-162     [000] .......   541.831587: rtcpu_string: tstamp:17654376365 id:0x04010000 str:"stream_id: PP 2, csi_port: PORT C
"
     kworker/0:4-162     [000] .......   541.831588: rtcpu_string: tstamp:17654376609 id:0x04010000 str:"Brick: PHY 1, Mode: D-PHY
"
     kworker/0:4-162     [000] .......   541.831590: rtcpu_string: tstamp:17654376889 id:0x04010000 str:"Partition: CIL A, LP bypass: Enabled, Lanes: 2
"
     kworker/0:4-162     [000] .......   541.831591: rtcpu_string: tstamp:17654377069 id:0x04010000 str:"Clock information:
"
     kworker/0:4-162     [000] .......   541.831592: rtcpu_string: tstamp:17654377369 id:0x04010000 str:"MIPI clock rate: 400.00 MHz
"
     kworker/0:4-162     [000] .......   541.831594: rtcpu_string: tstamp:17654377610 id:0x04010000 str:"T_HS settle: 0, T_CLK settle: 0
"
     kworker/0:4-162     [000] .......   541.831595: rtcpu_string: tstamp:17654377834 id:0x04010000 str:"======================================
"
     kworker/0:4-162     [000] .......   541.831597: rtcpu_string: tstamp:17654379877 id:0x04010000 str:"tegra_nvcsi_stream_open(vm0, stream=2, csi=2)
"
     kworker/0:4-162     [000] .......   541.831598: rtcpu_string: tstamp:17654380482 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_"
     kworker/0:4-162     [000] .......   541.831599: rtcpu_string: tstamp:17654380586 id:0x04010000 str:"SW_RESET_0 = 00000003
"
     kworker/0:4-162     [000] .......   541.831600: rtcpu_string: tstamp:17654380948 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_"
     kworker/0:4-162     [000] .......   541.831600: rtcpu_string: tstamp:17654381063 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:4-162     [000] .......   541.831602: rtcpu_string: tstamp:17654381604 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET"
     kworker/0:4-162     [000] .......   541.831602: rtcpu_string: tstamp:17654381706 id:0x04010000 str:"_0 = 00000001
"
     kworker/0:4-162     [000] .......   541.831604: rtcpu_string: tstamp:17654387709 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET"
     kworker/0:4-162     [000] .......   541.831604: rtcpu_string: tstamp:17654387812 id:0x04010000 str:"_0 = 00000000
"
     kworker/0:4-162     [000] .......   541.831606: rtcpu_string: tstamp:17654388253 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 61
"
     kworker/0:4-162     [000] .......   541.831607: rtcpu_string: tstamp:17654388520 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 61
"
     kworker/0:4-162     [000] .......   541.831608: rtcpu_string: tstamp:17654388781 id:0x04010000 str:"nvcsi_calc_tclk_settle tclk_settle 75
"
     kworker/0:4-162     [000] .......   541.831609: rtcpu_string: tstamp:17654389227 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_"
     kworker/0:4-162     [000] .......   541.831610: rtcpu_string: tstamp:17654389328 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:4-162     [000] .......   541.831611: rtcpu_string: tstamp:17654389686 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_"
     kworker/0:4-162     [000] .......   541.831612: rtcpu_string: tstamp:17654389789 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:4-162     [000] .......   541.831615: rtcpu_vinotify_event: tstamp:17654683462 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:564939419776 data:0x799e300010000000
     kworker/0:4-162     [000] .......   541.831615: rtcpu_vinotify_event: tstamp:17654683600 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:564939426208 data:0x0000000031000001
     kworker/0:4-162     [000] .......   541.831615: rtcpu_vinotify_event: tstamp:17654683755 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:0 vi_tstamp:564939429184 data:0x0000000007020001
     kworker/0:4-162     [000] .......   541.831616: rtcpu_vinotify_event: tstamp:17654683887 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:564939476320 data:0x799e2d0010000000
     kworker/0:4-162     [000] .......   541.831616: rtcpu_vinotify_event: tstamp:17654684043 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:564939482848 data:0x0000000031000002
     kworker/0:4-162     [000] .......   541.887500: rtcpu_vinotify_error: tstamp:17656374048 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565003942688 data:0x0000000000000489
     kworker/0:4-162     [000] .......   541.887504: rtcpu_vinotify_event: tstamp:17656374437 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:565003923808 data:0x0000000000000012
     kworker/0:4-162     [000] .......   541.887504: rtcpu_vinotify_event: tstamp:17656711692 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565003942688 data:0x0000000000000489
     kworker/0:4-162     [000] .......   541.947502: rtcpu_vinotify_error: tstamp:17658457623 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565070617952 data:0x0000000000000489
     kworker/0:4-162     [000] .......   541.947505: rtcpu_vinotify_event: tstamp:17658739979 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:565070598432 data:0x0000000000000022
     kworker/0:4-162     [000] .......   541.947506: rtcpu_vinotify_event: tstamp:17658740132 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:565070599040 data:0x0000000000000012
     kworker/0:4-162     [000] .......   541.947506: rtcpu_vinotify_event: tstamp:17658740268 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565070617952 data:0x0000000000000489
     kworker/0:4-162     [000] .......   542.003514: rtcpu_vinotify_error: tstamp:17660541228 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565137293184 data:0x0000000000000489
     kworker/0:4-162     [000] .......   542.003517: rtcpu_vinotify_event: tstamp:17660768122 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:565137273664 data:0x0000000000000022
     kworker/0:4-162     [000] .......   542.003518: rtcpu_vinotify_event: tstamp:17660768261 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:565137274272 data:0x0000000000000012
     kworker/0:4-162     [000] .......   542.003518: rtcpu_vinotify_event: tstamp:17660768415 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565137293184 data:0x0000000000000489
     kworker/0:4-162     [000] .......   542.115620: rtcpu_vinotify_error: tstamp:17662624809 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565203968416 data:0x0000000000000489
     kworker/0:4-162     [000] .......   542.115623: rtcpu_vinotify_event: tstamp:17662625289 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:565203948928 data:0x0000000000000022
     kworker/0:4-162     [000] .......   542.115624: rtcpu_vinotify_event: tstamp:17662625440 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:565203949504 data:0x0000000000000012
     kworker/0:4-162     [000] .......   542.115624: rtcpu_vinotify_event: tstamp:17662625576 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565203968416 data:0x0000000000000489
     kworker/0:4-162     [000] .......   542.175498: rtcpu_vinotify_error: tstamp:17664708431 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:565270643648 data:0x0000000000000489

I have noticed two oddities in this situation.

First, the FPGA sends data in RGB888 format, but the V4L2 image format is RGBA8888. Reading previous forum threads, it seems that RGB888 is not supported.

Second, the timestamps for the FE and FS related logs in the trace log appear to have almost no interval between them.

Your advice on the problems and solutions for this situation would be greatly appreciated.

Thank you.

3

hello matthew147,

that’s correct,
VI did not support RGB888 memory formats due to it’ll add luminance format.
and, VIC output format only support RGB/BGR with alpha channel.

there’s code related to your streaming settings,
the code 0x489 it means the RGB888 format type, which means a correct setting here.

we usuaully checking timestamps from FS (frame-start) to FE (frame-end).
for instance,
tag:FS channel:0x03 frame:0 vi_tstamp:565137274272 data:0x0000000000000012
tag:FE channel:0x03 frame:0 vi_tstamp:565203948928 data:0x0000000000000022

time interval… 565203948928 (FE) - 565137274272 (FS) = 66,674,656 ~= 66ms
it is close to your 15-fps (i.e. 1/15sec) mode config.

however, there’s no valid frame packets received by channel select.
it should report a pair of CHANSEL_PXL_SOF and CHANSEL_PXL_EOF to indicate a good frame.


besides, it looks you’ve applied debug version RCE firmware, the binary version matters, may I double confirm where did you obtain the binary file.

4

Hello JerryChang,

First of all, I obtained the debug RCE firmware through this post: Request debug RTCPU image for JetPack 6.0

I have additional questions regarding the answer you provided.

Regarding the previous first question, what I initially expected was that if the FPGA sends data in RGB888, the VI would receive it and store it in memory as RGBA8888. However, my understanding now is that the FPGA needs to send it as RGBA8888 from the beginning. Is my understanding correct?

And if this is true, how should the mode settings be configured in the device tree? When I checked the kernel code related to pixel formats previously, I don’t recall seeing any settings for RGBA8888. The current device tree settings related to the pixel format are as follows:

...
				mode0 {
					mclk_khz = "24000";
					tegra_sinterface = CAM1_SINTERFACE;
					lane_polarity = CAM1_LANE_POLARITY;
					num_lanes = CAM1_NUM_LANES;
					phy_mode = "DPHY";
					discontinuous_clk = "no";
					dpcm_enable = "false";
					cil_settletime = "0";
					active_w = "1920";
					active_h = "1200";
					mode_type = "rgb";
					pixel_phase = "rgb888";
					csi_pixel_bit_depth = "24";
					readout_orientation = "0";
					line_length = "1974";
					inherent_gain = "1";
					// pix_clk_hz = "133333334"; /* 800.00 MHz */
					pix_clk_hz = "66666667";  /* 400.00 MHz */
					// pix_clk_hz = "33333334"; /* 200.00 MHz */
					gain_factor = "16";
					framerate_factor = "1000000";
					exposure_factor = "1000000";
					min_gain_val = "16"; /* 1.00x */
					max_gain_val = "356"; /* 22x */
					step_gain_val = "1";
					default_gain = "16"; /* 1.00x */
					min_hdr_ratio = "1";
					max_hdr_ratio = "1";
					min_framerate = "2000000"; /* 2.0 fps */
					max_framerate = "30000000"; /* 120.0 fps */
					step_framerate = "1";
					default_framerate = "15000000"; /* 30.0 fps */
					min_exp_time = "13"; /* us */
					max_exp_time = "683709"; /* us */
					step_exp_time = "1";
					default_exp_time = "2495"; /* us */
					embedded_metadata_height = "0";
				};
...

Lastly, regarding the frame packet question:

Is this issue related to RGB888, or is there another possible cause? Any advice on what might be suspected would be very helpful.

Thank you.

5

hello matthew147,

this is what you should expect.

FPGA sends data in RGB888, the VI would receive it and store it in memory as RGBA8888.

please use v4l commands, i.e. $ v4l2-ctl -d /dev/video0 --list-formats-ext to check the sensor capability
it should report AB24, 32-bit RGBA 8-8-8-8. as your camera format.
you should running with v4l2src to fetch the streaming as following.
$ gst-launch-1.0 v4l2src device=/dev/video0 ! video/x-raw,format=RGBA,width=1280,height=1024,framerate=60/1 ! nvvidconv ! fakesink

6

Hello JerryChang,

Here are the results of executing the commands you provided.

ssw@orin-nano:~$ v4l2-ctl -d /dev/video1 --list-formats-ext
ioctl: VIDIOC_ENUM_FMT
        Type: Video Capture

        [0]: 'AB24' (32-bit RGBA 8-8-8-8)
                Size: Discrete 1920x1200
                        Interval: Discrete 0.067s (15.000 fps)
ssw@orin-nano:~$ gst-launch-1.0 v4l2src device=/dev/video1 ! video/x-raw,format=RGBA,width=1920,height=1200,framerate=15/1 ! nvvidconv ! fakesink
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Redistribute latency...
^Chandling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:11.603584733
Setting pipeline to NULL ...
Freeing pipeline ...
ssw@orin-nano:~$

Here is a portion of the dmesg output:

[   16.924437] nvidia-modeset: Loading NVIDIA UNIX Open Kernel Mode Setting Driver for aarch64  540.3.0  Release Build  (matthew@matthew-desktop)  Fri Jun  7 07:27:36 PM KST 2024
[   17.206556] NVRM rpcRmApiControl_dce: NVRM_RPC_DCE: Failed RM ctrl call cmd:0x731341 result 0xffff:
[   19.438842] rfkill: input handler disabled
[  142.287918] fpga 9-001a: probing v4l2 sensor at addr 0x1a
[  142.288028] fpga 9-001a: fpga_parse_dt()
[  142.288050] fpga 9-001a: mclk name not present, assume sensor driven externally
[  142.288052] fpga 9-001a: avdd, iovdd and/or dvdd reglrs. not present, assume sensor powered independently
[  142.288055] fpga 9-001a: fpga_power_get()
[  142.288147] fpga 9-001a: tegracam sensor driver:fpga_v2.0.6
[  142.288208] tegra-camrtc-capture-vi tegra-capture-vi: subdev fpga 9-001a bound
[  142.298146] fpga 9-001a: fpga driver probed
[  191.431608] [RCE] calibration status1 23294a32 status2 25294611
[  191.431621] [RCE] calibration status1 26188421 status2 210dc31
[  191.431624] [RCE] calibration status1 2919d6f3 status2 2d4a4a54
[  191.431626] [RCE] calibration status1 2f69ceb2 status2 2929ca93
[  191.431628] [RCE] NVCSILP clock rate = 408000000 Hz.
[  279.382375] fpga 9-001a: fpga_power_on()
[  279.382385] fpga 9-001a: fpga_power_on: power on
[  279.692414] fpga 9-001a: fpga_set_mode()
[  279.692433] fpga 9-001a: fpga_start_streaming()
[  279.705602] [RCE] VM0 deactivating.VM0 activating.calibration status1 23294a32 status2 2d294611
[  279.705612] [RCE] calibration status1 29494261 status2 2af9de73
[  279.705615] [RCE] calibration status1 2719d6f4 status2 2d5a4a54
[  279.705617] [RCE] calibration status1 2f6a4eb2 status2 2b29ca93
[  279.705620] [RCE] NVCSILP clock rate = 408000000 Hz.
[  279.705623] [RCE] tegra_nvcsi_stream_set_config(vm0, stream=2, csi=2)
[  279.705625] [RCE] MIPI clock = 400000 kHz, tHS-SETTLE = 0, tCLK-SETTLE = 0
[  279.705627] [RCE] ===== NVCSI Stream Configuration =====
[  279.705629] [RCE] stream_id: PP 2, csi_port: PORT C
[  279.705630] [RCE] Brick: PHY 1, Mode: D-PHY
[  279.705632] [RCE] Partition: CIL A, LP bypass: Enabled, Lanes: 2
[  279.705633] [RCE] Clock information:
[  279.705635] [RCE] MIPI clock rate: 400.00 MHz
[  279.705636] [RCE] T_HS settle: 0, T_CLK settle: 0
[  279.705638] [RCE] ======================================
[  279.705639] [RCE] tegra_nvcsi_stream_open(vm0, stream=2, csi=2)
[  279.705642] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_SW_RESET_0 = 00000003
[  279.705644] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_SW_RESET_0 = 00000000
[  279.705646] [RCE] nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET_0 = 00000001
[  279.705648] [RCE] nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET_0 = 00000000
[  279.705650] [RCE] nvcsi_calc_ths_settle ths_settle 61
[  279.705652] [RCE] nvcsi_calc_ths_settle ths_settle 61
[  279.705653] [RCE] nvcsi_calc_tclk_settle tclk_settle 75
[  279.705655] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_SW_RESET_0 = 00000000
[  279.705657] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_SW_RESET_0 = 00000000
[  282.333479] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  282.333507] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  282.334002] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  285.149330] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  285.149357] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  285.149961] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  287.709206] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  287.709232] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  287.710155] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  290.269099] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  290.269129] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  290.270134] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  292.796975] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  292.796998] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  292.798112] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  292.798149] fpga 9-001a: fpga_stop_streaming()
[  292.800367] fpga 9-001a: fpga_power_off()
[  292.800376] fpga 9-001a: fpga_power_off: power off

And here is a portion of the trace output:

# tracer: nop
#
# entries-in-buffer/entries-written: 952/952   #P:4
#
#                                _-------=> irqs-off
#                               / _------=> need-resched
#                              | / _-----=> need-resched-lazy
#                              || / _----=> hardirq/softirq
#                              ||| / _---=> preempt-depth
#                              |||| / _--=> preempt-lazy-depth
#                              ||||| / _-=> migrate-disable
#                              |||||| /     delay
#           TASK-PID     CPU#  |||||||  TIMESTAMP  FUNCTION
#              | |         |   |||||||      |         |
     kworker/0:2-212     [000] .......   197.687460: rtcpu_string: tstamp:6940224430 id:0x04010000 str:"VM0 deactivating."
        v4l2-ctl-3509    [000] .......   227.082462: tegra_channel_open: vi-output, fpga 9-001a
        v4l2-ctl-3509    [000] .......   227.082904: tegra_channel_close: vi-output, fpga 9-001a
        v4l2-ctl-3556    [000] .......   260.931823: tegra_channel_open: vi-output, fpga 9-001a
        v4l2-ctl-3556    [000] .......   260.932177: tegra_channel_close: vi-output, fpga 9-001a
 gst-plugin-scan-3604    [002] .......   279.258347: tegra_channel_open: vi-output, imx219 10-0010
 gst-plugin-scan-3604    [002] .......   279.258489: tegra_channel_close: vi-output, imx219 10-0010
 gst-plugin-scan-3604    [002] .......   279.258505: tegra_channel_open: vi-output, fpga 9-001a
 gst-plugin-scan-3604    [002] .......   279.258535: tegra_channel_close: vi-output, fpga 9-001a
  gst-launch-1.0-3603    [001] .......   279.319102: tegra_channel_open: vi-output, imx219 10-0010
  gst-launch-1.0-3603    [001] .......   279.319268: tegra_channel_close: vi-output, imx219 10-0010
  gst-launch-1.0-3603    [001] .......   279.319285: tegra_channel_open: vi-output, fpga 9-001a
  gst-launch-1.0-3603    [001] .......   279.319316: tegra_channel_close: vi-output, fpga 9-001a
  gst-launch-1.0-3603    [001] .......   279.364810: tegra_channel_open: vi-output, fpga 9-001a
    v4l2src0:src-3606    [002] .......   279.382362: tegra_channel_set_power: fpga 9-001a : 0x1
    v4l2src0:src-3606    [002] .......   279.382371: camera_common_s_power: status : 0x1
    v4l2src0:src-3606    [002] .......   279.682525: tegra_channel_set_power: 13e00000.host1x:nvcsi@15a00000- : 0x1
    v4l2src0:src-3606    [002] .......   279.682531: csi_s_power: enable : 0x1
    v4l2src0:src-3606    [002] .......   279.683685: tegra_channel_capture_setup: vnc_id 0 W 1920 H 1200 fmt 9
 vi-output, fpga-3608    [001] .......   279.691312: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
 vi-output, fpga-3608    [001] .......   279.691320: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
 vi-output, fpga-3608    [001] .......   279.691322: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
 vi-output, fpga-3608    [001] .......   279.691323: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
    v4l2src0:src-3606    [002] .......   279.691339: tegra_channel_set_stream: enable : 0x1
    v4l2src0:src-3606    [002] .......   279.691889: tegra_channel_set_stream: 13e00000.host1x:nvcsi@15a00000- : 0x1
    v4l2src0:src-3606    [002] .......   279.691891: csi_s_stream: enable : 0x1
    v4l2src0:src-3606    [002] .......   279.692404: tegra_channel_set_stream: fpga 9-001a : 0x1
     kworker/0:2-212     [000] .......   279.705598: rtcpu_string: tstamp:9504123560 id:0x04010000 str:"VM0 activating."
     kworker/0:2-212     [000] .......   279.705601: rtcpu_string: tstamp:9504192867 id:0x04010000 str:"calibration status1 23294a32 status2 2d294611
"
     kworker/0:2-212     [000] .......   279.705612: rtcpu_string: tstamp:9504193320 id:0x04010000 str:"calibration status1 29494261 status2 2af9de73
"
     kworker/0:2-212     [000] .......   279.705614: rtcpu_string: tstamp:9504193765 id:0x04010000 str:"calibration status1 2719d6f4 status2 2d5a4a54
"
     kworker/0:2-212     [000] .......   279.705617: rtcpu_string: tstamp:9504194208 id:0x04010000 str:"calibration status1 2f6a4eb2 status2 2b29ca93
"
     kworker/0:2-212     [000] .......   279.705620: rtcpu_string: tstamp:9504202958 id:0x04010000 str:"NVCSILP clock rate = 408000000 Hz.
"
     kworker/0:2-212     [000] .......   279.705622: rtcpu_string: tstamp:9504275751 id:0x04010000 str:"tegra_nvcsi_stream_set_config(vm0, stream=2, csi"
     kworker/0:2-212     [000] .......   279.705623: rtcpu_string: tstamp:9504275856 id:0x04010000 str:"=2)
"
     kworker/0:2-212     [000] .......   279.705625: rtcpu_string: tstamp:9504276228 id:0x04010000 str:"MIPI clock = 400000 kHz, tHS-SETTLE = 0, tCLK-SE"
     kworker/0:2-212     [000] .......   279.705625: rtcpu_string: tstamp:9504276332 id:0x04010000 str:"TTLE = 0
"
     kworker/0:2-212     [000] .......   279.705627: rtcpu_string: tstamp:9504276542 id:0x04010000 str:"===== NVCSI Stream Configuration =====
"
     kworker/0:2-212     [000] .......   279.705629: rtcpu_string: tstamp:9504276791 id:0x04010000 str:"stream_id: PP 2, csi_port: PORT C
"
     kworker/0:2-212     [000] .......   279.705630: rtcpu_string: tstamp:9504277031 id:0x04010000 str:"Brick: PHY 1, Mode: D-PHY
"
     kworker/0:2-212     [000] .......   279.705632: rtcpu_string: tstamp:9504277311 id:0x04010000 str:"Partition: CIL A, LP bypass: Enabled, Lanes: 2
"
     kworker/0:2-212     [000] .......   279.705633: rtcpu_string: tstamp:9504277490 id:0x04010000 str:"Clock information:
"
     kworker/0:2-212     [000] .......   279.705635: rtcpu_string: tstamp:9504277791 id:0x04010000 str:"MIPI clock rate: 400.00 MHz
"
     kworker/0:2-212     [000] .......   279.705636: rtcpu_string: tstamp:9504278032 id:0x04010000 str:"T_HS settle: 0, T_CLK settle: 0
"
     kworker/0:2-212     [000] .......   279.705638: rtcpu_string: tstamp:9504278255 id:0x04010000 str:"======================================
"
     kworker/0:2-212     [000] .......   279.705639: rtcpu_string: tstamp:9504279859 id:0x04010000 str:"tegra_nvcsi_stream_open(vm0, stream=2, csi=2)
"
     kworker/0:2-212     [000] .......   279.705641: rtcpu_string: tstamp:9504280471 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_"
     kworker/0:2-212     [000] .......   279.705642: rtcpu_string: tstamp:9504280574 id:0x04010000 str:"SW_RESET_0 = 00000003
"
     kworker/0:2-212     [000] .......   279.705643: rtcpu_string: tstamp:9504280937 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_"
     kworker/0:2-212     [000] .......   279.705644: rtcpu_string: tstamp:9504281068 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:2-212     [000] .......   279.705646: rtcpu_string: tstamp:9504281612 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET"
     kworker/0:2-212     [000] .......   279.705646: rtcpu_string: tstamp:9504281717 id:0x04010000 str:"_0 = 00000001
"
     kworker/0:2-212     [000] .......   279.705648: rtcpu_string: tstamp:9504287732 id:0x04010000 str:"nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET"
     kworker/0:2-212     [000] .......   279.705648: rtcpu_string: tstamp:9504287838 id:0x04010000 str:"_0 = 00000000
"
     kworker/0:2-212     [000] .......   279.705650: rtcpu_string: tstamp:9504288280 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 61
"
     kworker/0:2-212     [000] .......   279.705651: rtcpu_string: tstamp:9504288549 id:0x04010000 str:"nvcsi_calc_ths_settle ths_settle 61
"
     kworker/0:2-212     [000] .......   279.705653: rtcpu_string: tstamp:9504288810 id:0x04010000 str:"nvcsi_calc_tclk_settle tclk_settle 75
"
     kworker/0:2-212     [000] .......   279.705655: rtcpu_string: tstamp:9504289265 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_"
     kworker/0:2-212     [000] .......   279.705655: rtcpu_string: tstamp:9504289369 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:2-212     [000] .......   279.705657: rtcpu_string: tstamp:9504289728 id:0x04010000 str:"nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_"
     kworker/0:2-212     [000] .......   279.705657: rtcpu_string: tstamp:9504289831 id:0x04010000 str:"SW_RESET_0 = 00000000
"
     kworker/0:2-212     [000] .......   279.705661: rtcpu_vinotify_event: tstamp:9504586057 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:304136278528 data:0x799e300010000000
     kworker/0:2-212     [000] .......   279.705662: rtcpu_vinotify_event: tstamp:9504586197 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:304136284928 data:0x0000000031000001
     kworker/0:2-212     [000] .......   279.705662: rtcpu_vinotify_event: tstamp:9504586354 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:0 vi_tstamp:304136287968 data:0x0000000007020001
     kworker/0:2-212     [000] .......   279.705663: rtcpu_vinotify_event: tstamp:9504586489 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:304136335104 data:0x799e2d0010000000
     kworker/0:2-212     [000] .......   279.705663: rtcpu_vinotify_event: tstamp:9504586642 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:304136341600 data:0x0000000031000002
     kworker/0:2-212     [000] .......   279.761710: rtcpu_vinotify_error: tstamp:9506073656 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304194330720 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.761713: rtcpu_vinotify_event: tstamp:9506276228 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304194311776 data:0x0000000000000012
     kworker/0:2-212     [000] .......   279.761714: rtcpu_vinotify_event: tstamp:9506276381 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304194330720 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.817595: rtcpu_vinotify_error: tstamp:9508157261 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304261005984 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.873587: rtcpu_vinotify_event: tstamp:9508304513 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304260986464 data:0x0000000000000022
     kworker/0:2-212     [000] .......   279.873589: rtcpu_vinotify_event: tstamp:9508304667 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304260987072 data:0x0000000000000012
     kworker/0:2-212     [000] .......   279.873590: rtcpu_vinotify_event: tstamp:9508304803 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304261005984 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.929593: rtcpu_vinotify_error: tstamp:9510240852 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304327681248 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.929596: rtcpu_vinotify_event: tstamp:9510332644 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304327661760 data:0x0000000000000022
     kworker/0:2-212     [000] .......   279.929597: rtcpu_vinotify_event: tstamp:9510332779 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304327662368 data:0x0000000000000012
     kworker/0:2-212     [000] .......   279.929599: rtcpu_vinotify_event: tstamp:9510332930 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304327681248 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.985587: rtcpu_vinotify_error: tstamp:9512324445 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304394356544 data:0x0000000000000489
     kworker/0:2-212     [000] .......   279.985589: rtcpu_vinotify_event: tstamp:9512324932 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304394337024 data:0x0000000000000022
     kworker/0:2-212     [000] .......   279.985590: rtcpu_vinotify_event: tstamp:9512325086 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304394337600 data:0x0000000000000012
     kworker/0:2-212     [000] .......   279.985591: rtcpu_vinotify_event: tstamp:9512325221 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304394356544 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.041591: rtcpu_vinotify_error: tstamp:9514408071 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304461031808 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.041593: rtcpu_vinotify_event: tstamp:9514423084 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304461012288 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.041594: rtcpu_vinotify_event: tstamp:9514423217 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304461012896 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.041594: rtcpu_vinotify_event: tstamp:9514423369 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304461031808 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.097583: rtcpu_vinotify_error: tstamp:9516491667 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304527707104 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.097585: rtcpu_vinotify_event: tstamp:9516789453 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304527687584 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.097586: rtcpu_vinotify_event: tstamp:9516789614 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304527688192 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.097587: rtcpu_vinotify_event: tstamp:9516789746 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304527707104 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.153583: rtcpu_vinotify_error: tstamp:9518575262 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304594382368 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.209595: rtcpu_vinotify_event: tstamp:9518817583 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304594362848 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.209597: rtcpu_vinotify_event: tstamp:9518817721 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304594363456 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.209598: rtcpu_vinotify_event: tstamp:9518817871 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304594382368 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.269596: rtcpu_vinotify_error: tstamp:9520658875 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304661057664 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.269600: rtcpu_vinotify_event: tstamp:9520845861 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304661038144 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.269601: rtcpu_vinotify_event: tstamp:9520846012 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304661038720 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.269601: rtcpu_vinotify_event: tstamp:9520846148 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304661057664 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.325578: rtcpu_vinotify_error: tstamp:9522742474 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304727732928 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.325581: rtcpu_vinotify_event: tstamp:9522874168 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304727713408 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.325582: rtcpu_vinotify_event: tstamp:9522874304 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304727714016 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.325582: rtcpu_vinotify_event: tstamp:9522874453 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304727732928 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.381569: rtcpu_vinotify_event: tstamp:9524825382 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304794388704 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.381572: rtcpu_vinotify_error: tstamp:9524826075 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304794408224 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.381572: rtcpu_vinotify_event: tstamp:9525139036 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304794389312 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.381573: rtcpu_vinotify_event: tstamp:9525139171 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304794408224 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.437578: rtcpu_vinotify_error: tstamp:9526909672 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304861083488 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.437582: rtcpu_vinotify_event: tstamp:9527167315 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304861064000 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.437583: rtcpu_vinotify_event: tstamp:9527167449 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304861064576 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.437583: rtcpu_vinotify_event: tstamp:9527167600 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304861083488 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.493575: rtcpu_vinotify_error: tstamp:9528993277 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304927758752 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.493579: rtcpu_vinotify_event: tstamp:9529195611 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304927739264 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.493580: rtcpu_vinotify_event: tstamp:9529195765 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304927739840 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.493580: rtcpu_vinotify_event: tstamp:9529195900 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304927758752 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.605559: rtcpu_vinotify_error: tstamp:9531076881 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304994434048 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.605562: rtcpu_vinotify_event: tstamp:9531223912 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:304994414528 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.605563: rtcpu_vinotify_event: tstamp:9531224049 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:304994415136 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.605564: rtcpu_vinotify_event: tstamp:9531224208 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:304994434048 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.661544: rtcpu_vinotify_error: tstamp:9533160493 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305061109344 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.661547: rtcpu_vinotify_event: tstamp:9533252058 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305061089824 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.661548: rtcpu_vinotify_event: tstamp:9533252210 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305061090432 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.661548: rtcpu_vinotify_event: tstamp:9533252343 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305061109344 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.721548: rtcpu_vinotify_error: tstamp:9535244228 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305127784608 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.721550: rtcpu_vinotify_event: tstamp:9535244531 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305127765088 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.721551: rtcpu_vinotify_event: tstamp:9535244665 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305127765696 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.721552: rtcpu_vinotify_event: tstamp:9535550808 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305127784608 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.777552: rtcpu_vinotify_error: tstamp:9537327692 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305194459872 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.777554: rtcpu_vinotify_event: tstamp:9537579085 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305194440384 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.777554: rtcpu_vinotify_event: tstamp:9537579242 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305194440960 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.777555: rtcpu_vinotify_event: tstamp:9537579374 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305194459872 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.833550: rtcpu_vinotify_error: tstamp:9539411293 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305261135168 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.833551: rtcpu_vinotify_event: tstamp:9539607377 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305261115648 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.833552: rtcpu_vinotify_event: tstamp:9539607513 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305261116256 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.833553: rtcpu_vinotify_event: tstamp:9539607664 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305261135168 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.889539: rtcpu_vinotify_error: tstamp:9541494898 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305327810432 data:0x0000000000000489
     kworker/0:2-212     [000] .......   280.889541: rtcpu_vinotify_event: tstamp:9541635679 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305327790912 data:0x0000000000000022
     kworker/0:2-212     [000] .......   280.889542: rtcpu_vinotify_event: tstamp:9541635832 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305327791520 data:0x0000000000000012
     kworker/0:2-212     [000] .......   280.889542: rtcpu_vinotify_event: tstamp:9541635968 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305327810432 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.001542: rtcpu_vinotify_error: tstamp:9543578500 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305394485696 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.001544: rtcpu_vinotify_event: tstamp:9543663959 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305394466208 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.001545: rtcpu_vinotify_event: tstamp:9543664095 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305394466816 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.001546: rtcpu_vinotify_event: tstamp:9543664247 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305394485696 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.057542: rtcpu_vinotify_error: tstamp:9545662080 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305461160992 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.057544: rtcpu_vinotify_event: tstamp:9545662565 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305461141504 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.057545: rtcpu_vinotify_event: tstamp:9545662717 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305461142080 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.057549: rtcpu_vinotify_event: tstamp:9545662867 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305461160992 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.113539: rtcpu_vinotify_error: tstamp:9547745708 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305527836288 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.113541: rtcpu_vinotify_event: tstamp:9547754218 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305527816768 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.113542: rtcpu_vinotify_event: tstamp:9547754352 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305527817376 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.113543: rtcpu_vinotify_event: tstamp:9547754501 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305527836288 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.169519: rtcpu_vinotify_error: tstamp:9549829300 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305594511584 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.169521: rtcpu_vinotify_event: tstamp:9550120598 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305594492032 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.169522: rtcpu_vinotify_event: tstamp:9550120747 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305594492640 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.169523: rtcpu_vinotify_event: tstamp:9550120880 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305594511584 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.225530: rtcpu_vinotify_error: tstamp:9551912904 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305661186848 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.225532: rtcpu_vinotify_event: tstamp:9552148740 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305661167328 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.225533: rtcpu_vinotify_event: tstamp:9552148884 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305661167936 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.225534: rtcpu_vinotify_event: tstamp:9552149036 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305661186848 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.341523: rtcpu_vinotify_error: tstamp:9553996507 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305727862112 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.341526: rtcpu_vinotify_event: tstamp:9554177018 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305727842624 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.341527: rtcpu_vinotify_event: tstamp:9554177170 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305727843200 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.341528: rtcpu_vinotify_event: tstamp:9554177305 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305727862112 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.397522: rtcpu_vinotify_error: tstamp:9556080148 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305794537408 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.397525: rtcpu_vinotify_event: tstamp:9556205332 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305794517888 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.397526: rtcpu_vinotify_event: tstamp:9556205468 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305794518496 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.397526: rtcpu_vinotify_event: tstamp:9556205624 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305794537408 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.453514: rtcpu_vinotify_event: tstamp:9558163027 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305861193152 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.453516: rtcpu_vinotify_error: tstamp:9558163719 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305861212704 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.453517: rtcpu_vinotify_event: tstamp:9558470199 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305861193792 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.453518: rtcpu_vinotify_event: tstamp:9558470332 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305861212704 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.509511: rtcpu_vinotify_error: tstamp:9560247320 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305927887936 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.509516: rtcpu_vinotify_event: tstamp:9560498478 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305927868448 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.509516: rtcpu_vinotify_event: tstamp:9560498612 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305927869056 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.509517: rtcpu_vinotify_event: tstamp:9560498763 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305927887936 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.565521: rtcpu_vinotify_error: tstamp:9562330922 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305994563232 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.565525: rtcpu_vinotify_event: tstamp:9562526764 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:305994543712 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.565525: rtcpu_vinotify_event: tstamp:9562526914 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:305994544320 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.565526: rtcpu_vinotify_event: tstamp:9562527045 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:305994563232 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.621618: rtcpu_vinotify_error: tstamp:9564414525 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306061238496 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.621621: rtcpu_vinotify_event: tstamp:9564555069 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306061219008 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.621622: rtcpu_vinotify_event: tstamp:9564555204 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306061219584 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.621623: rtcpu_vinotify_event: tstamp:9564555357 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306061238496 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.737499: rtcpu_vinotify_error: tstamp:9566498127 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306127913792 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.737501: rtcpu_vinotify_event: tstamp:9566583365 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306127894272 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.737502: rtcpu_vinotify_event: tstamp:9566583517 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306127894880 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.737503: rtcpu_vinotify_event: tstamp:9566583658 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306127913792 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.793496: rtcpu_vinotify_error: tstamp:9568581868 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306194589056 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.793499: rtcpu_vinotify_event: tstamp:9568582179 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306194569536 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.793500: rtcpu_vinotify_event: tstamp:9568582314 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306194570144 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.793500: rtcpu_vinotify_event: tstamp:9568915847 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306194589056 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.849492: rtcpu_vinotify_error: tstamp:9570665327 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306261264320 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.849494: rtcpu_vinotify_event: tstamp:9570944152 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306261244832 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.849495: rtcpu_vinotify_event: tstamp:9570944308 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306261245440 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.849496: rtcpu_vinotify_event: tstamp:9570944442 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306261264320 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.905488: rtcpu_vinotify_error: tstamp:9572748955 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306327939616 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.905490: rtcpu_vinotify_event: tstamp:9572972292 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306327920096 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.905491: rtcpu_vinotify_event: tstamp:9572972430 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306327920672 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.905492: rtcpu_vinotify_event: tstamp:9572972586 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306327939616 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.961495: rtcpu_vinotify_error: tstamp:9574832560 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306394614912 data:0x0000000000000489
     kworker/0:2-212     [000] .......   281.961497: rtcpu_vinotify_event: tstamp:9575000558 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306394595360 data:0x0000000000000022
     kworker/0:2-212     [000] .......   281.961498: rtcpu_vinotify_event: tstamp:9575000710 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306394595968 data:0x0000000000000012
     kworker/0:2-212     [000] .......   281.961499: rtcpu_vinotify_event: tstamp:9575000846 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306394614912 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.017520: rtcpu_vinotify_error: tstamp:9576916132 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306461290176 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.073470: rtcpu_vinotify_event: tstamp:9577028845 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306461270656 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.073472: rtcpu_vinotify_event: tstamp:9577028978 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306461271264 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.073473: rtcpu_vinotify_event: tstamp:9577029129 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306461290176 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.129487: rtcpu_vinotify_error: tstamp:9578999748 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306527965440 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.129489: rtcpu_vinotify_event: tstamp:9579000265 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306527945952 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.129490: rtcpu_vinotify_event: tstamp:9579000418 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306527946560 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.129490: rtcpu_vinotify_event: tstamp:9579000550 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306527965440 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.185481: rtcpu_vinotify_error: tstamp:9581083372 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306594640736 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.185483: rtcpu_vinotify_event: tstamp:9581085400 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306594621216 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.185484: rtcpu_vinotify_event: tstamp:9581085533 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306594621792 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.185487: rtcpu_vinotify_event: tstamp:9581085717 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306594640736 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.241470: rtcpu_vinotify_error: tstamp:9583166971 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306661316000 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.241472: rtcpu_vinotify_event: tstamp:9583451786 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306661296480 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.241473: rtcpu_vinotify_event: tstamp:9583451940 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306661297088 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.241473: rtcpu_vinotify_event: tstamp:9583452075 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306661316000 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.301471: rtcpu_vinotify_error: tstamp:9585250571 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306727991296 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.301474: rtcpu_vinotify_event: tstamp:9585479926 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306727971776 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.301475: rtcpu_vinotify_event: tstamp:9585480065 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306727972384 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.301475: rtcpu_vinotify_event: tstamp:9585480218 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306727991296 data:0x0000000000000489
 vi-output, fpga-3609    [003] .......   282.333884: tegra_channel_capture_setup: vnc_id 0 W 1920 H 1200 fmt 9
    v4l2src0:src-3606    [002] .......   282.476155: job_submit: 15340000.vic class=5d id=1 fences=1 ts=9591282046
    v4l2src0:src-3606    [002] .......   282.476159: job_postfence: job_id=1 syncpt_id=54 threshold=3
     kworker/0:2-212     [000] .......   282.477124: job_timestamps: job_id=1 begin=9591283068 end=9591309216
 vi-output, fpga-3608    [001] .......   282.477567: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
    v4l2src0:src-3606    [003] .......   282.481401: job_submit: 15340000.vic class=5d id=2 fences=1 ts=9591446193
    v4l2src0:src-3606    [003] .......   282.481405: job_postfence: job_id=2 syncpt_id=54 threshold=7
     kworker/0:2-212     [000] .......   282.482343: job_timestamps: job_id=2 begin=9591446953 end=9591474037
 vi-output, fpga-3608    [000] .......   282.482851: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
    v4l2src0:src-3606    [001] .......   282.486287: job_submit: 15340000.vic class=5d id=3 fences=1 ts=9591599028
    v4l2src0:src-3606    [001] .......   282.486290: job_postfence: job_id=3 syncpt_id=54 threshold=11
     kworker/0:2-212     [000] .......   282.487266: job_timestamps: job_id=3 begin=9591599701 end=9591628370
 vi-output, fpga-3608    [002] .......   282.487624: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
    v4l2src0:src-3606    [001] .......   282.490971: job_submit: 15340000.vic class=5d id=4 fences=1 ts=9591745470
    v4l2src0:src-3606    [001] .......   282.490973: job_postfence: job_id=4 syncpt_id=54 threshold=15
     kworker/0:2-212     [000] .......   282.492010: job_timestamps: job_id=4 begin=9591746095 end=9591776655
 vi-output, fpga-3608    [002] .......   282.492359: vi_task_submit: class_id:48 ch:0 syncpt_id:34 syncpt_thresh:0 pid:3608 tid:3608
     kworker/0:2-212     [000] .......   282.529472: rtcpu_vinotify_error: tstamp:9591501485 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306928017120 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.529475: rtcpu_vinotify_event: tstamp:9591501791 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:306922536512 data:0x799e300010000000
     kworker/0:2-212     [000] .......   282.529475: rtcpu_vinotify_event: tstamp:9591501945 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:306922542880 data:0x0000000031000001
     kworker/0:2-212     [000] .......   282.529476: rtcpu_vinotify_event: tstamp:9591502079 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:0 vi_tstamp:306922545888 data:0x0000000007020001
     kworker/0:2-212     [000] .......   282.529476: rtcpu_vinotify_event: tstamp:9591502229 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:306927817760 data:0x799e2d0010000000
     kworker/0:2-212     [000] .......   282.529476: rtcpu_vinotify_event: tstamp:9591502362 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:306927824288 data:0x0000000031000002
     kworker/0:2-212     [000] .......   282.529477: rtcpu_vinotify_event: tstamp:9591502513 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306927997600 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.529477: rtcpu_vinotify_event: tstamp:9591502644 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306927998208 data:0x0000000000000012
     kworker/0:2-212     [000] .......   282.529478: rtcpu_vinotify_event: tstamp:9591835229 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306928017120 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.585470: rtcpu_vinotify_error: tstamp:9593584982 cch:-1 vi:1 tag:CHANSEL_NOMATCH channel:0xc4 frame:0 vi_tstamp:306994692416 data:0x0000000000000489
     kworker/0:2-212     [000] .......   282.585475: rtcpu_vinotify_event: tstamp:9593863478 cch:-1 vi:1 tag:FE channel:0x03 frame:0 vi_tstamp:306994672864 data:0x0000000000000022
     kworker/0:2-212     [000] .......   282.585476: rtcpu_vinotify_event: tstamp:9593863627 cch:-1 vi:1 tag:FS channel:0x03 frame:0 vi_tstamp:306994673472 data:0x0000000000000012
7

hello matthew147,

here’s VI error recovery, which has capture timeout and trying to restore the capture engine.

anyways,
please have some dummy try with below pipelines…
$ v4l2-ctl --set-fmt-video=width=1920,height=1200,pixelformat=AB24 --stream-mmap --set-ctrl bypass_mode=0 --stream-count=500 -d /dev/video0
or,
$ gst-launch-1.0 v4l2src ! 'video/x-raw,format=GRAY8, width=1920,height=1200,framerate=15/1' ! nvvidconv ! 'video/x-raw(memory:NVMM), format=I420' ! fpsdisplaysink text-overlay=0 video-sink=fakesink sync=0 -v
or,
gst-launch-1.0 nvv4l2camerasrc device=/dev/video0 num-buffers=300 ! 'video/x-raw(memory:NVMM),format=(string)BGRA, width=(int)1920, height=(int)1200,framerate=(fraction)15/1' ! videoconvert ! fpsdisplaysink video-sink=fakesink text-overlay=false sync=false -v

8

Hello JerryChang,

Here are the results of executing the commands you provided.

Command (1) prompt

ssw@orin-nano:~$ v4l2-ctl -d /dev/video1 --set-fmt-video=width=1920,height=1200,pixelformat=AB24 --stream-mmap --set-ctrl bypass_mode=0 --stream-count=500
^C
ssw@orin-nano:~$

Command (1) dmesg

[ 2933.334523] fpga 9-001a: fpga_power_on()
[ 2933.334533] fpga 9-001a: fpga_power_on: power on
[ 2933.644391] fpga 9-001a: fpga_set_mode()
[ 2933.644408] fpga 9-001a: fpga_start_streaming()
[ 2933.673940] [RCE] VM0 deactivating.VM0 activating.calibration status1 5210842 status2 5210842
[ 2933.673952] [RCE] calibration status1 29490695 status2 2af8de73
[ 2933.673955] [RCE] calibration status1 2719d6f3 status2 2d5a4a74
[ 2933.673957] [RCE] calibration status1 2f6a52b1 status2 2929ca93
[ 2933.673959] [RCE] NVCSILP clock rate = 408000000 Hz.
[ 2933.673962] [RCE] tegra_nvcsi_stream_set_config(vm0, stream=2, csi=2)
[ 2933.673965] [RCE] MIPI clock = 400000 kHz, tHS-SETTLE = 0, tCLK-SETTLE = 0
[ 2933.673967] [RCE] ===== NVCSI Stream Configuration =====
[ 2933.673971] [RCE] stream_id: PP 2, csi_port: PORT C
[ 2933.673972] [RCE] Brick: PHY 1, Mode: D-PHY
[ 2933.673974] [RCE] Partition: CIL A, LP bypass: Enabled, Lanes: 2
[ 2933.673976] [RCE] Clock information:
[ 2933.673977] [RCE] MIPI clock rate: 400.00 MHz
[ 2933.673979] [RCE] T_HS settle: 0, T_CLK settle: 0
[ 2933.673981] [RCE] ======================================
[ 2933.673983] [RCE] tegra_nvcsi_stream_open(vm0, stream=2, csi=2)
[ 2933.673985] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_SW_RESET_0 = 00000003
[ 2933.673988] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_SW_RESET_0 = 00000000
[ 2933.673990] [RCE] nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET_0 = 00000001
[ 2933.673992] [RCE] nvcsi_reset_lane_merger: NVCSI_PHY_1_LM_SW_RESET_0 = 00000000
[ 2933.673994] [RCE] nvcsi_calc_ths_settle ths_settle 61
[ 2933.673996] [RCE] nvcsi_calc_ths_settle ths_settle 61
[ 2933.673997] [RCE] nvcsi_calc_tclk_settle tclk_settle 75
[ 2933.674000] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_A_SW_RESET_0 = 00000000
[ 2933.674002] [RCE] nvcsi_reset_data_lanes: NVCSI_PHY_1_NVCSI_CIL_B_SW_RESET_0 = 00000000
[ 2936.269881] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 2936.269911] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 2936.270672] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 2938.829818] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 2938.829844] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 2938.830750] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 2941.389694] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 2941.389724] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 2941.390718] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 2943.949606] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 2943.949636] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 2943.950799] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 2946.477521] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 2946.477547] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 2946.478837] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 2946.478872] fpga 9-001a: fpga_stop_streaming()
[ 2946.480402] fpga 9-001a: fpga_power_off()
[ 2946.480405] fpga 9-001a: fpga_power_off: power off

Command (2) prompt

ssw@orin-nano:~$ gst-launch-1.0 v4l2src device=/dev/video1 ! 'video/x-raw,format=GRAY8, width=1920,height=1200,framerate=15/1' ! nvvidconv ! 'video/x-raw(memory:NVMM), format=I420' ! fpsdisplaysink text-overlay=0 video-sink=fakesink sync=0 -v
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
/GstPipeline:pipeline0/GstFPSDisplaySink:fpsdisplaysink0/GstFakeSink:fakesink0: sync = false
Pipeline is PREROLLED ...
Setting pipeline to PLAYING ...
ERROR: from element /GstPipeline:pipeline0/GstV4l2Src:v4l2src0: Internal data stream error.
Additional debug info:
../libs/gst/base/gstbasesrc.c(3127): gst_base_src_loop (): /GstPipeline:pipeline0/GstV4l2Src:v4l2src0:
streaming stopped, reason not-negotiated (-4)
New clock: GstSystemClock
Execution ended after 0:00:00.000245224
Setting pipeline to NULL ...
Freeing pipeline ...
ssw@orin-nano:~$

Command (2) dmesg
=> No output

Command (3) prompt

ssw@orin-nano:~$ gst-launch-1.0 nvv4l2camerasrc device=/dev/video1 num-buffers=300 ! 'video/x-raw(memory:NVMM),format=(string)BGRA, width=(int)1920, height=(int)1200,framerate=(fraction)15/1' ! videoconvert ! fpsdisplaysink video-sink=fakesink text-overlay=false sync=false -v
WARNING: erroneous pipeline: could not link nvv4l2camerasrc0 to videoconvert0, nvv4l2camerasrc0 can't handle caps video/x-raw(memory:NVMM), format=(string)BGRA, width=(int)1920, height=(int)1200, framerate=(fraction)15/1
ssw@orin-nano:~$

Command (3) dmesg
=> No output

9

hello matthew147,

let’s check with basic v4l2 IOCTLs before moving to v4l2src .

according to your 1st comments…

does it means it’s outputting frames as soon as system power-on?
is it possible for adding a reset, which make FPGA to initialize and re-send frames while software side calling s_stream()?

10

Hello JerryChang,

FPGA starts sending image data towards the AP as soon as it is powered on. Also, the functions to power on and start the stream in the current driver are empty and only output logs. Although there is a separate method to reset the FPGA, it is currently not possible to directly send a reset command to the FPGA from the driver logic.

11

hello matthew147,

may I know what exactly is this… did you meant it’s a dummy function?

we should keep using v4l2 IOCTLs to check stream stability.
according to the logs, it’s VI has timed out for waiting the frames,
please try adding --stream-skip options to skip some frames for fetching your stream.
for instance,
v4l2-ctl -d /dev/video1 --set-fmt-video=width=1920,height=1200,pixelformat=AB24 --stream-mmap --set-ctrl bypass_mode=0 --stream-skip=100 --stream-count=500

12

Hello JerryChang,

First of all, the command you provided results in the same situation as before when executed.

Additionally, it seems my explanation regarding the driver code was not accurate. To clarify, the current driver code is based on nv_imx477.c. The probe, remove, parse_dt, power_get, power_put, power_on, and power_off functions are almost identical to the existing ones. The remaining functions, including start_streaming and stop_streaming, only handle successful calls and output logs.

One notable point is that the FPGA power is not supplied from the AP side but from its own board, so the power control in the driver code does not actually turn the FPGA power on or off.

13

hello matthew147,

could you please give it a try by enabling FPGA power after software side calling s_stream()?

14

Hello JerryChang,

Are you referring to s_stream as v4l2_subdev_video_ops.s_stream?

Additionally, could you please provide more details on what you are trying to verify through this attempt? It seems that we might need assistance from other team members regarding the power supply, so I need to share the situation accordingly.

If we are unable to control the power supply, would attempting a reset be a viable alternative?

Thank you in advance, and I will try it and get back to you.

15

hello matthew147,

from MIPI signaling point-of-view, receiver it should recognize LP sequence (which should follow by LP11->LP01->LP00->LP11 sequence), and then high-speed signaling to indicate frames on CSI channel.
since you’ve FPGA starts sending image data towards the AP as soon as it is powered on. it’s assumption of out of sync failure.

that’s why the suggestion of…
(1) enabling FPGA power after software side calling start stream, or,
(2) adding a reset to make FPGA to initialize and re-send frames while start stream.

16

Hello JerryChang,

As you suggested, I added the logic to reset the FPGA at the start of the stream, but the situation remains the same.
I believe this is an issue that needs to be fixed, but I suspect there might be another underlying problem as well.

17

hello matthew147,

please also gather the latest VI tracing logs for reference.

18

The trace log file is attached. The reset part is in fpga_s_stream.
trace.1721111484.176.log (126.0 KB)

19

hello matthew147,

I’ve checking your DT settings again.
it’s mode_type + pixel_phase + csi_pixel_bit_depth to compose a pixel format,
and, sending to below API for setting its V4L2 pixel format.
please examine you’ve report pixel format correctly.
$public_sources/kernel_src/kernel/nvidia/drivers/media/platform/tegra/camera/sensor_common.c

static int extract_pixel_format(
        const char *pixel_t, u32 *format)
{
        size_t size = strnlen(pixel_t, OF_MAX_STR_LEN);

besides, csi_pixel_bit_depth is the bit depth of sensor output on the CSI bus.
it should be 8 for your RGB888 use-case.

20

Hello JerryChang,

As you mentioned, setting csi_pixel_bit_depth to 8 results in the pixel_t value in the extract_pixel_format function becoming rgb_rgb8888, which leads to failure. However, it seems like there is indeed an issue occurring in the pixel conversion part. While searching through the related code, I found something unusual in the vi5_formats.h file.

115: TEGRA_VIDEO_FORMAT(RGB888, 24, RGB888_1X24, 4, 1, T_A8B8G8R8,
116:             RGB888, RGBA32, "RGBA-8-8-8-8"),

I modified T_A8B8G8R8 to T_R8G8B8A8 and attempted streaming again. After that, the content of the trace log changed compared to before.

Upon searching for the trace content, I found it similar to the post below:

I would appreciate your advice on the current situation. I have also attached the trace log. trace.1721455292.069.log (943.3 KB)

21

hello matthew147,

you should not modify this, it’s mapping to internal memory format.
for instance,
TEGRA_VIDEO_FORMAT(RGB888, 24, RGB888_1X24, 4, 1, T_A8B8G8R8, RGB888, RGBA32, "RGBA-8-8-8-8"),
it’ll be…
Pixel memory format for VI channel: T_A8B8G8R8
Image data type: RGB888.
v4l2 format (fourcc): V4L2_PIX_FMT_RGBA32
GST format: GST_VIDEO_FORMAT_RGBA
you may see-also gst-plugins-good/sys/v4l2/gstv4l2object.c at master · GStreamer/gst-plugins-good · GitHub