Camera Porting Issues

Autonomous Machines Jetson & Embedded Systems Jetson AGX Xavier
1

I am working on porting a camera board (4-lane MIPI CSI-2 output) from another brand of SOM (where it works fine) to the AGX Xavier. We created a PWB to bring its CSI-2 output lanes and I2C control buses to the camera connector on the AGX Xavier Developer Kit. It seems to power up and boot fine. I can talk to it over the I2C buses correctly. I have ported non-camera drivers for I2C register access and they work well.

For video, the board is configured to output a colorbar pattern at 3840x2160@30fps over the MIPI CSI-2 port to 4 lanes (Port 0 / Port 1) of the Xavier. The only control the camera driver needs for this camera is to enable/disable streaming. I have written a simple driver patterned after existing drivers for other cameras. It builds, installs in Linux and boots. However, it doesn’t yet get any frames from the camera.

I have tried running v4l2-compliance and v4l2-ctl but they’re not really helping me to figure out where to look for issues with my code or device tree. I am posting my driver, device tree, and the output from the v4l2-compliance and v4l2-ctl programs to see if you can point me at something. I think I’m close, but am not sure.

Thanks in advance,

Chris
v4l2-compliance.txt (9.1 KB)
v4l2-ctl-kernel-log.txt (7.1 KB)

fury_video.c (14.8 KB)
tegra194-camera-fury-a00.dtsi (13.7 KB)
tegra194-p2822-0000-camera-fury-a00.dtsi (1.5 KB)

3

hello chrisrfq,

may I also know which Jetpack release version you’re working with?
please examine release tag, $ cat /etc/nv_tegra_release for confirmation.

this v4l2-compliance test failure looks harmful, it’s low-level driver to call v4l2 ioctl for buffer operations.
VI driver needs these operations to fetch camera buffers.

Buffer ioctls (Input 0):
		info: test buftype Video Capture
		fail: v4l2-test-buffers.cpp(751): q.create_bufs(node, 1, &fmt) != EINVAL
	test VIDIOC_REQBUFS/CREATE_BUFS/QUERYBUF: FAIL

please dig into driver side,
there’s VI driver for calling those operations,
$public_sources/kernel_src/kernel/nvidia/drivers/media/platform/tegra/camera/vi/channel.c

static const struct v4l2_ioctl_ops tegra_channel_ioctl_ops = {
        .vidioc_reqbufs                 = vb2_ioctl_reqbufs,

internally,
it’s videobuf2 core helper to implement VIDIOC_REQBUF() operation.
$public_sources/kernel_src/kernel/kernel-5.10/drivers/media/common/videobuf2/videobuf2-core.c
int vb2_core_reqbufs(struct vb2_queue *q, enum vb2_memory memory, unsigned int *count)

4

Thanks for your quick response. For the Jetpack release version (35.2.1, I think):

> cat /etc/nv_tegra_release
# R35 (release), REVISION: 2.1, GCID: 32413640, BOARD: t186ref, EABI: aarch64, DATE: Tue Jan 24 23:38:33 UTC 2023

It seems that there should be hooks into VI are used by existing camera drivers, such as nv_imx274.c and buffers would be provided for them. Are they attached using the device-tree?

The log when I do the v4l2-ctl test seems to indicate that buffers are getting allocated:

[ 3617.678951] video4linux video0: Entering vb2_ioctl_reqbufs(count = 4, type = 1, memory = 1, capabilities = ffff)
[ 3617.694094] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()
[ 3617.712513] fury_video 2-0054: fury_video_set_mode() (empty function)
[ 3620.391410] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 3620.391685] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 3620.395626] (NULL device *): vi_capture_control_message: NULL VI channel received
[ 3620.395879] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[ 3620.396136] (NULL device *): vi_capture_control_message: NULL VI channel received
[ 3620.396298] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[ 3620.396958] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[ 3622.951238] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 3622.951493] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 3622.952960] (NULL device *): vi_capture_control_message: NULL VI channel received
[ 3622.953283] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[ 3622.953547] (NULL device *): vi_capture_control_message: NULL VI channel received

But it says NULL VI channel received. Perhaps I don’t have the VI channel hooked up correctly in the device tree, but I’m not seeing any issues there.

Thanks again,

Chris

5

hello chrisrfq,

it’s device tree to define the camera node, you may see-also To verify the port binding result.
according to the logs, it looks you’ve sending operation to your driver, the following timeout is due to capture engine cannot wait for start-of-frame within 2500ms.

may I know when did you enable the camera stream, please also add some debug prints for examination.

6

Thanks, Jerry. Here’s the output from port binding. It looks pretty similar to the example output in the webpage you referred to:

> media-ctl -p -v -d /dev/media0
Opening media device /dev/media0
Enumerating entities
Found 3 entities
Enumerating pads and links
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: 13e10000.host1x:nvcsi@15a00000- (2 pads, 2 links)
            type V4L2 subdev subtype Unknown flags 0
            device node name /dev/v4l-subdev0
        pad0: Sink
                <- "fury_video 2-0054":0 [ENABLED]
        pad1: Source
                -> "vi-output, fury_video 2-0054":0 [ENABLED]

- entity 4: fury_video 2-0054 (1 pad, 1 link)
            type V4L2 subdev subtype Sensor flags 0
            device node name /dev/v4l-subdev1
        pad0: Source
                [fmt:UYVY8_1X16/3840x2160 field:none colorspace:srgb]
                -> "13e10000.host1x:nvcsi@15a00000-":0 [ENABLED]

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

Here is the output with the stream starting info:

> v4l2-ctl --set-fmt-video=width=3840,height=2160 --stream-mmap  --stream-count=100 -d /dev/video0
[   73.382792] video4linux video0: Entering vb2_ioctl_reqbufs(count = 4, type = 1, memory = 1, capabilities = ffff)
[   73.403863] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()
[   73.425208] fury_video 2-0054: fury_video_set_mode() (empty function)
[   73.425385] fury_video 2-0054: Entering fury_video_start_streaming()
[   73.425858] fury_video 2-0054: Successfully turned on MIPI CSI-2 data streaming
[   76.000506] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[   76.000845] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[   76.002068] (NULL device *): vi_capture_control_message: NULL VI channel received
[   76.002356] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[   76.002583] (NULL device *): vi_capture_control_message: NULL VI channel received
[   76.002758] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[   76.003656] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[   78.560429] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[   78.560671] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[   78.561714] (NULL device *): vi_capture_control_message: NULL VI channel received
[   78.561905] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[   78.562144] (NULL device *): vi_capture_control_message: NULL VI channel received
[   78.562308] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[   78.562929] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[   81.120442] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[   81.120730] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[   81.121704] (NULL device *): vi_capture_control_message: NULL VI channel received
[   81.121882] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[   81.122106] (NULL device *): vi_capture_control_message: NULL VI channel received
[   81.122285] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[   81.122876] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
^C
[   83.648465] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[   83.648744] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[   83.649670] (NULL device *): vi_capture_control_message: NULL VI channel received
[   83.649832] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[   83.650060] (NULL device *): vi_capture_control_message: NULL VI channel received
[   83.650220] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[   83.650843] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[   83.651255] fury_video 2-0054: Entering fury_video_stop_streaming()
[   83.651700] fury_video 2-0054: Successfully turned off MIPI CSI-2 data streaming

Again, I can tell by an LED on our camera board that streaming has started.

Another post suggested enabling some kernel debug tracing which yielded:

# tracer: nop
#
# entries-in-buffer/entries-written: 41/41   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
        v4l2-ctl-2462    [002] ....   212.107267: tegra_channel_open: vi-output, fury_video 2-0054
        v4l2-ctl-2462    [002] ....   212.128303: tegra_channel_set_power: fury_video 2-0054 : 0x1
        v4l2-ctl-2462    [002] ....   212.128327: camera_common_s_power: status : 0x1
        v4l2-ctl-2462    [002] ....   212.128340: tegra_channel_set_power: 13e10000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2462    [002] ....   212.128342: csi_s_power: enable : 0x1
        v4l2-ctl-2462    [002] ....   212.128794: tegra_channel_capture_setup: vnc_id 0 W 3840 H 2160 fmt 13
        v4l2-ctl-2462    [003] ....   212.129697: tegra_channel_set_stream: enable : 0x1
        v4l2-ctl-2462    [003] ....   212.133243: tegra_channel_set_stream: 13e10000.host1x:nvcsi@15a00000- : 0x1
        v4l2-ctl-2462    [003] ....   212.133246: csi_s_stream: enable : 0x1
        v4l2-ctl-2462    [003] ....   212.133712: tegra_channel_set_stream: fury_video 2-0054 : 0x1
     kworker/1:5-170     [001] ....   212.151321: rtcpu_vinotify_event: tstamp:7289586537 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:233250903936 data:0xcd9ce50010000000
     kworker/1:5-170     [001] ....   212.151324: rtcpu_vinotify_event: tstamp:7289586725 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:233250909440 data:0x0000000031000001
     kworker/1:5-170     [001] ....   212.151325: rtcpu_vinotify_event: tstamp:7289586916 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:233250967904 data:0xcd9ce20010000000
     kworker/1:5-170     [001] ....   212.151325: rtcpu_vinotify_event: tstamp:7289587079 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:233250973504 data:0x0000000031000002
 vi-output, fury-2464    [001] ....   214.757707: tegra_channel_capture_setup: vnc_id 0 W 3840 H 2160 fmt 13
     kworker/1:5-170     [001] ....   214.783321: rtcpu_vinotify_event: tstamp:7371509391 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:235879571840 data:0xcd9ce50010000000
     kworker/1:5-170     [001] ....   214.783324: rtcpu_vinotify_event: tstamp:7371509560 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:235879614656 data:0x0000000031000001
     kworker/1:5-170     [001] ....   214.783325: rtcpu_vinotify_event: tstamp:7371509750 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:235879633248 data:0xcd9ce20010000000
     kworker/1:5-170     [001] ....   214.783326: rtcpu_vinotify_event: tstamp:7371509914 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:235879693664 data:0x0000000031000002
 vi-output, fury-2464    [001] ....   217.317544: tegra_channel_capture_setup: vnc_id 0 W 3840 H 2160 fmt 13
     kworker/1:5-170     [001] ....   217.359348: rtcpu_vinotify_event: tstamp:7451263088 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:238439224832 data:0xcd9ce50010000000
     kworker/1:5-170     [001] ....   217.359352: rtcpu_vinotify_event: tstamp:7451263259 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:238439267648 data:0x0000000031000001
     kworker/1:5-170     [001] ....   217.359354: rtcpu_vinotify_event: tstamp:7451263447 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:238439286240 data:0xcd9ce20010000000
     kworker/1:5-170     [001] ....   217.359355: rtcpu_vinotify_event: tstamp:7451263609 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:238439346656 data:0x0000000031000002
 vi-output, fury-2464    [000] ....   219.877712: tegra_channel_capture_setup: vnc_id 0 W 3840 H 2160 fmt 13
     kworker/1:5-170     [001] ....   219.879396: rtcpu_vinotify_event: tstamp:7531238735 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:240999379904 data:0xcd9ce50010000000
     kworker/1:5-170     [001] ....   219.879400: rtcpu_vinotify_event: tstamp:7531238923 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:240999470976 data:0x0000000031000001
     kworker/1:5-170     [001] ....   219.879401: rtcpu_vinotify_event: tstamp:7531239112 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:240999489504 data:0xcd9ce20010000000
     kworker/1:5-170     [001] ....   219.879402: rtcpu_vinotify_event: tstamp:7531239276 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:240999549984 data:0x0000000031000002
        v4l2-ctl-2462    [002] ....   222.310975: tegra_channel_close: vi-output, fury_video 2-0054
 vi-output, fury-2464    [001] ....   222.381723: tegra_channel_capture_setup: vnc_id 0 W 3840 H 2160 fmt 13
        v4l2-ctl-2462    [002] ....   222.382303: tegra_channel_set_stream: enable : 0x0
        v4l2-ctl-2462    [002] ....   222.382306: tegra_channel_set_stream: fury_video 2-0054 : 0x0
        v4l2-ctl-2462    [002] ....   222.382907: tegra_channel_set_stream: 13e10000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2462    [002] ....   222.382910: csi_s_stream: enable : 0x0
        v4l2-ctl-2462    [003] ....   222.393910: tegra_channel_set_power: fury_video 2-0054 : 0x0
        v4l2-ctl-2462    [003] ....   222.393993: camera_common_s_power: status : 0x0
        v4l2-ctl-2462    [003] ....   222.394012: tegra_channel_set_power: 13e10000.host1x:nvcsi@15a00000- : 0x0
        v4l2-ctl-2462    [003] ....   222.394016: csi_s_power: enable : 0x0
     kworker/1:5-170     [001] ....   222.399476: rtcpu_nvcsi_intr: tstamp:7609592245 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001
     kworker/1:6-171     [001] ....   228.055482: rtcpu_string: tstamp:7786771595 id:0x04010000 str:"VM0 deactivating."

…in case that’s helpful. I’m also including an image of the the MIPI signal routing to the DevKit.

MIPI Input to AGX DevKit Camera Connector
MIPI Input to AGX DevKit Camera Connector957×239 30.2 KB

Are there registers or files I can check to confirm that the MIPI DPHY signals are reaching the Xavier on all the differential pairs?

7

hello chrisrfq,

it shows PHY interrupt error, the error code indicate it’s LP sequence error detected on clock-lane.
it usually the issue on the sensor configuration.

8

Thanks for your response, Jerry! You indicate that there’s a LP sequence error, and that it’s usually an issue with sensor configuration. Are you suggesting that

  1. The sensor parameters we’ve given the Xavier are incorrect, or
  2. The sensor needs to be configured differently?

(I’m hoping it’s the first, since we don’t have much control over the output format of the sensor itself right now.)

9

hello chrisrfq,

it usually the init timing issue of sensor side.
please check developer guide, there’s device tree settings, cil_settletime, it’s by default configure as 0 for auto-calibrate. you may try to tune THS settle time of the MIPI lane for your use-case.
you may see-also MIPI specification for the details of High-Speed Data-Clock Timing.

10

Thanks! I’ll try those.

11

I configured a value for cil_settletime (29) and the output changed quite a bit, but still isn’t working. The kernel log shows:

> v4l2-ctl --set-fmt-video=width=3840,height=2160 --stream-mmap  --stream-count=100 -d /dev/video0
[  381.273677] video4linux video0: Entering vb2_ioctl_reqbufs(count = 4, type = 1, memory = 1, capabilities = ffff)
[  381.287960] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()
[  381.306716] fury_video 2-0054: fury_video_set_mode() (empty function)
[  381.306885] fury_video 2-0054: Entering fury_video_start_streaming()
[  381.307235] fury_video 2-0054: Successfully turned on MIPI CSI-2 data streaming
[  383.953059] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  383.954167] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  383.954729] (NULL device *): vi_capture_control_message: NULL VI channel received
[  383.954891] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  383.955104] (NULL device *): vi_capture_control_message: NULL VI channel received
[  383.955273] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  383.955815] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  386.512976] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  386.513246] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  386.514734] (NULL device *): vi_capture_control_message: NULL VI channel received
[  386.514908] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  386.515147] (NULL device *): vi_capture_control_message: NULL VI channel received
[  386.515302] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  386.515914] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  389.072899] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  389.073212] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  389.074732] (NULL device *): vi_capture_control_message: NULL VI channel received
[  389.074960] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  389.075187] (NULL device *): vi_capture_control_message: NULL VI channel received
[  389.075356] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  389.075977] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  391.632832] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  391.633093] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  391.633739] (NULL device *): vi_capture_control_message: NULL VI channel received
[  391.633929] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  391.634170] (NULL device *): vi_capture_control_message: NULL VI channel received
[  391.634340] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  391.634963] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
^C
[  394.160719] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  394.160964] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  394.161683] (NULL device *): vi_capture_control_message: NULL VI channel received
[  394.161861] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  394.162084] (NULL device *): vi_capture_control_message: NULL VI channel received
[  394.162253] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  394.162857] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  394.163207] fury_video 2-0054: Entering fury_video_stop_streaming()
[  394.163648] fury_video 2-0054: Successfully turned off MIPI CSI-2 data streaming

and the trace output is:

> cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 23/23   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/3:1-81      [003] ....   373.149467: rtcpu_string: tstamp:12362749616 id:0x04010000 str:"VM0 deactivating."
     kworker/3:1-81      [003] ....   381.325154: rtcpu_string: tstamp:12618154712 id:0x04010000 str:"VM0 activating."
     kworker/3:1-81      [003] ....   381.325159: rtcpu_vinotify_event: tstamp:12618827951 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:403786477056 data:0xcd9ce50010000000
     kworker/3:1-81      [003] ....   381.325160: rtcpu_vinotify_event: tstamp:12618828123 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:403786482560 data:0x0000000031000001
     kworker/3:1-81      [003] ....   381.325161: rtcpu_vinotify_event: tstamp:12618828314 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:403786545504 data:0xcd9ce20010000000
     kworker/3:1-81      [003] ....   381.325161: rtcpu_vinotify_event: tstamp:12618828478 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:403786551040 data:0x0000000031000002
     kworker/3:3-426     [003] ....   384.013058: rtcpu_vinotify_event: tstamp:12701293684 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:406439954528 data:0xcd9ce50010000000
     kworker/3:3-426     [003] ....   384.013063: rtcpu_vinotify_event: tstamp:12701293872 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:406439997344 data:0x0000000031000001
     kworker/3:3-426     [003] ....   384.013064: rtcpu_vinotify_event: tstamp:12701294063 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:406440015936 data:0xcd9ce20010000000
     kworker/3:3-426     [003] ....   384.013065: rtcpu_vinotify_event: tstamp:12701294226 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:406440076384 data:0x0000000031000002
     kworker/3:1-81      [003] ....   386.532979: rtcpu_vinotify_event: tstamp:12781590284 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:409000039232 data:0xcd9ce50010000000
     kworker/3:1-81      [003] ....   386.532983: rtcpu_vinotify_event: tstamp:12781590454 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:409000082048 data:0x0000000031000001
     kworker/3:1-81      [003] ....   386.532984: rtcpu_vinotify_event: tstamp:12781590642 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:409000524160 data:0xcd9ce20010000000
     kworker/3:1-81      [003] ....   386.532985: rtcpu_vinotify_event: tstamp:12781590809 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:409000567680 data:0x0000000031000002
     kworker/3:1-81      [003] ....   389.108925: rtcpu_vinotify_event: tstamp:12861260640 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:411560126240 data:0xcd9ce50010000000
     kworker/3:1-81      [003] ....   389.108930: rtcpu_vinotify_event: tstamp:12861260809 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:411560169024 data:0x0000000031000001
     kworker/3:1-81      [003] ....   389.108931: rtcpu_vinotify_event: tstamp:12861261000 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:411560187552 data:0xcd9ce20010000000
     kworker/3:1-81      [003] ....   389.108932: rtcpu_vinotify_event: tstamp:12861261162 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:411560250912 data:0x0000000031000002
     kworker/3:4-427     [003] ....   391.688795: rtcpu_vinotify_event: tstamp:12941259898 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:414119072352 data:0xcd9ce50010000000
     kworker/3:4-427     [003] ....   391.688799: rtcpu_vinotify_event: tstamp:12941260109 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:414119130112 data:0x0000000031000001
     kworker/3:4-427     [003] ....   391.688800: rtcpu_vinotify_event: tstamp:12941260298 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:414119148576 data:0xcd9ce20010000000
     kworker/3:4-427     [003] ....   391.688801: rtcpu_vinotify_event: tstamp:12941260462 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:414119209024 data:0x0000000031000002
     kworker/3:4-427     [003] ....   394.212802: rtcpu_nvcsi_intr: tstamp:13020319124 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001

I will also look some more tomorrow. Thanks in advance for any insights!

12

hello chrisrfq,

in order to ignore clock configuration related issues,
please try with below commands to boost all the VI/CSI/ISP clocks.
for example,

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
13

That doesn’t seem to have made a difference in the trace. I did notice that there was a driver error message when running the commands you suggested:
bwmgr: clk_set_rate failed for freq 665000000 Hz with errno -22
Not sure if that’s significant.

Here’s the full log:

# 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
998400000
# cat /sys/kernel/debug/bpmp/debug/clk/isp/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/isp/rate
1190400000
# cat /sys/kernel/debug/bpmp/debug/clk/nvcsi/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/nvcsi/rate
400000000
# cat /sys/kernel/debug/bpmp/debug/clk/emc/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/emc/rate
2133000000
[  105.261082] bwmgr: clk_set_rate failed for freq 408000000 Hz with errno -22
# echo 1 > /sys/kernel/debug/tracing/tracing_on
# echo 30720 > /sys/kernel/debug/tracing/buffer_size_kb
# echo 1 > /sys/kernel/debug/tracing/events/tegra_rtcpu/enable
# echo 1 > /sys/kernel/debug/tracing/events/freertos/enable
# echo 2 > /sys/kernel/debug/camrtc/log-level
# echo > /sys/kernel/debug/tracing/trace
#
# v4l2-ctl --set-fmt-video=width=3840,height=2160,pixelformat=UYVY --stream-mmap  --stream-count=100 -d /dev/video0
[  128.508697] video4linux video0: Entering vb2_ioctl_reqbufs(count = 4, type = 1, memory = 1, capabilities = ffff)
[  128.521878] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()
[  128.538243] fury_video 2-0054: fury_video_set_mode() (empty function)
[  128.538419] fury_video 2-0054: Entering fury_video_start_streaming()
[  128.538908] fury_video 2-0054: Successfully turned on MIPI CSI-2 data streaming
[  131.040151] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  131.040448] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  131.041804] (NULL device *): vi_capture_control_message: NULL VI channel received
[  131.041970] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  131.042190] (NULL device *): vi_capture_control_message: NULL VI channel received
[  131.042344] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  131.042954] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  133.600141] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  133.600515] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  133.601760] (NULL device *): vi_capture_control_message: NULL VI channel received
[  133.601949] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  133.602207] (NULL device *): vi_capture_control_message: NULL VI channel received
[  133.602368] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  133.602956] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
^C[  136.128116] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[  136.128377] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[  136.129799] (NULL device *): vi_capture_control_message: NULL VI channel received
[  136.129981] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[  136.130204] (NULL device *): vi_capture_control_message: NULL VI channel received
[  136.130371] t194-nvcsi 13e10000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[  136.130938] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel
[  136.131339] fury_video 2-0054: Entering fury_video_stop_streaming()
[  136.131734] fury_video 2-0054: Successfully turned off MIPI CSI-2 data streaming

# cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 15/15   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
    kworker/0:13-215     [000] ....   125.408215: rtcpu_string: tstamp:4608386001 id:0x04010000 str:"VM0 deactivating."
    kworker/0:11-213     [000] ....   128.548100: rtcpu_string: tstamp:4705997383 id:0x04010000 str:"VM0 activating."
    kworker/0:11-213     [000] ....   128.548105: rtcpu_vinotify_event: tstamp:4706434782 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:150596426144 data:0xcd9ce50010000000
    kworker/0:11-213     [000] ....   128.548106: rtcpu_vinotify_event: tstamp:4706434922 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:150596431616 data:0x0000000031000001
    kworker/0:11-213     [000] ....   128.548106: rtcpu_vinotify_event: tstamp:4706435077 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:150596490432 data:0xcd9ce20010000000
    kworker/0:11-213     [000] ....   128.548107: rtcpu_vinotify_event: tstamp:4706435217 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:150596496000 data:0x0000000031000002
    kworker/0:11-213     [000] ....   131.068142: rtcpu_vinotify_event: tstamp:4784685765 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:153103226016 data:0xcd9ce50010000000
    kworker/0:11-213     [000] ....   131.068146: rtcpu_vinotify_event: tstamp:4784685905 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:153103231520 data:0x0000000031000001
    kworker/0:11-213     [000] ....   131.068147: rtcpu_vinotify_event: tstamp:4784686058 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:153103721952 data:0xcd9ce20010000000
    kworker/0:11-213     [000] ....   131.068148: rtcpu_vinotify_event: tstamp:4784686190 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:153103727552 data:0x0000000031000002
    kworker/0:11-213     [000] ....   133.644120: rtcpu_vinotify_event: tstamp:4864501827 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:155663480064 data:0xcd9ce50010000000
    kworker/0:11-213     [000] ....   133.644130: rtcpu_vinotify_event: tstamp:4864501967 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:155663485536 data:0x0000000031000001
    kworker/0:11-213     [000] ....   133.644132: rtcpu_vinotify_event: tstamp:4864502120 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:155663652256 data:0xcd9ce20010000000
    kworker/0:11-213     [000] ....   133.644133: rtcpu_vinotify_event: tstamp:4864502255 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:155663657824 data:0x0000000031000002
    kworker/0:11-213     [000] ....   136.164108: rtcpu_nvcsi_intr: tstamp:4943584437 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000001
#
14

hello chrisrfq,

do you have controls to this driver? could you please try issue a software reset before s_stream().

also,
it may be minor, but did your camera stream sending embedded metadata?
if no, please configure embedded_metadata_height = "0"; for testing.

15

It looks like the

embedded_metadata_height = "0";

made a big difference:

$ v4l2-ctl --set-fmt-video=width=3840,height=2160,pixelformat=UYVY --stream-mmap  --stream-count=100 -d /dev/video0
[  753.060032] video4linux video0: Entering vb2_ioctl_reqbufs(count = 4, type = 1, memory = 1, capabilities = ffff)
[  753.071336] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()
[  753.081103] fury_video 2-0054: fury_video_set_mode() (empty function)
[  753.081273] fury_video 2-0054: Entering fury_video_start_streaming()
[  753.081830] fury_video 2-0054: Successfully turned on MIPI CSI-2 data streaming
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< 30.00 fps
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< 30.00 fps
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< 30.00 fps
<<<<<<<<[  756.457843] fury_video 2-0054: Entering fury_video_stop_streaming()
[  756.458198] fury_video 2-0054: Successfully turned off MIPI CSI-2 data streaming

[  756.467249] video4linux video0: Entering vb2_ioctl_reqbufs(count = 0, type = 1, memory = 1, capabilities = ffff)
[  756.485953] video4linux video0: Returning 0 from vb2_ioctl_reqbufs()

Does the above indicate that frames were actually captured?

16

hello chrisrfq,

that’s correct. each of < indicate a success capture frame, and it also report frame-rate for every second.
you may refer to below example, please try running gst pipeline with v4l2src plugin to preview the stream,
i.e. $ gst-launch-1.0 -v v4l2src device=/dev/video1 ! video/x-raw,framerate=30/1,width=640,height=480 ! xvimagesink

17

That template worked. Thanks very much!

19

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