AR0144 on TX2: fence timeouts, MIPI CRC?

Hi!

I’m trying to make an Onsemi AR0144CS work on a Jetson TX2 and L4T-R28.2.1. I have two boards from Leopard Imaging, a “li-ar0144-mipi” sensor connected to a “li-jtx1-mipi-adpt v1.2” (3x MIPI Board), which sits on a TX2 evalboard.

Since there’s no driver available for this hardware combination yet, I tried modifying existing drivers and dtbs. This works so far as I can grab frames via 4vl (yavta, v4l2ctl). However when I try to access the camera through argus_oneshot or gstreamer, I get fence timeouts.

Relevant parts of the syslog (full syslog is attached):

Oct 18 14:13:20 tegra-ubuntu kernel: [  151.886139] ar0144 31-0010: ar0144_power_off: power off
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.893120] ar0144 31-0010: ar0144_power_on: power on
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.904490] ar0144 31-0010: ar0144_power_off: power off
Oct 18 14:13:20 tegra-ubuntu argus_daemon[1226]: LSC: LSC surface is not based on full res!
Oct 18 14:13:20 tegra-ubuntu argus_daemon[1226]: LoadOverridesFile: looking for override file [/Calib/camera_override.isp] 1/16LoadOverridesFile: looking for override file [/data/nvcam/settings/camera_overrides.isp] 2/16LoadOverridesFile: looking for override file 
[/opt/nvidia/nvcam/settings/camera_overrides.isp] 3/16LoadOverridesFile: looking for override file [/var/nvidia/nvcam/settings/camera_overrides.isp] 4/16LoadOverridesFile: looking for override file [/data/nvcam/camera_overrides.isp] 5/16LoadOverridesFile: looking f
or override file [/data/nvcam/settings/ar0144_centerright_liar0144.isp] 6/16LoadOverridesFile: looking for override file [/opt/nvidia/nvcam/settings/ar0144_centerright_liar0144.isp] 7/16LoadOverridesFile: looking for override file [/var/nvidia/nvcam/settings/ar0144
_centerright_liar0144.isp] 8/16---- imager: No override file found. ----
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.933714] ar0144 32-0010: ar0144_power_on: power on
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.945989] ar0144 32-0010: ar0144_power_off: power off
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.952812] ar0144 32-0010: ar0144_power_on: power on
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.965234] ar0144 32-0010: ar0144_power_off: power off
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.972077] ar0144 32-0010: ar0144_power_on: power on
Oct 18 14:13:20 tegra-ubuntu kernel: [  151.984342] ar0144 32-0010: ar0144_power_off: power off
Oct 18 14:13:20 tegra-ubuntu argus_daemon[1226]: LSC: LSC surface is not based on full res!
Oct 18 14:13:20 tegra-ubuntu kernel: [  152.228453] ar0144 30-0010: ar0144_power_on: power on
Oct 18 14:13:20 tegra-ubuntu kernel: [  152.239496] video4linux video0: enable override control
Oct 18 14:13:20 tegra-ubuntu kernel: [  152.246826] misc tegra_camera_ctrl: ISO BW req 2147483647 > 2250000 (max) capping to max
Oct 18 14:13:20 tegra-ubuntu kernel: [  152.255058] misc tegra_camera_ctrl: vi_v4l2_update_isobw: requested iso bw is larger than max
Oct 18 14:13:20 tegra-ubuntu argus_daemon[1226]: LSC: LSC surface is not based on full res!
Oct 18 14:13:20 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  NonFatal ISO BW requested not set. Requested = 2147483647 Set = 2250000 (in src/services/power/PowerServiceCore.cpp, function setCameraBw(), line 653)
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.274450] ar0144 30-0010: ar0144_s_stream++
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.278851] ar0144 30-0010: ar0144_start_stream()
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.539169] ar0144 30-0010: ar0144_start_stream() - success
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.544842] ar0144 30-0010: ar0144_set_gain - val = 1
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.550048] ar0144 30-0010: input gain value: 128
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.554929] ar0144 30-0010: ar0144_set_gain: gain 0080 val: again 0000, dgain 0080
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.564050] ar0144 30-0010: ar0144_set_frame_length length = 831
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.570225] ar0144 30-0010: ar0144_set_frame_length: val: 831
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.576764] ar0144 30-0010: ar0144_set_coarse_time
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.581710] ar0144 30-0010: ar0144_set_coarse_time: input val: 400
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.588139] ar0144 30-0010: ar0144_set_coarse_time: set val: 400
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.594834] ar0144 30-0010: ar0144_set_frame_length length = 1663
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.600997] ar0144 30-0010: ar0144_set_frame_length: val: 1663
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.607391] ar0144 30-0010: ar0144_set_coarse_time
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.612315] ar0144 30-0010: ar0144_set_coarse_time: input val: 1232
Oct 18 14:13:21 tegra-ubuntu kernel: [  152.618667] ar0144 30-0010: ar0144_set_coarse_time: set val: 1232

Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: NvViErrorDecode Stream 0.0 failed: ts 180508842528 frame 7 error 2 data 0x00400060
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: NvViErrorDecode CaptureError: CsimuxFrameError (2)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: NvViErrorDecode See https://wiki.nvidia.com/wmpwiki/index.php/Camera_Debugging/CaptureError_debugging for more information and links to documents.
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: CsimuxFrameError_Regular : 0x00400060
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:     Stream ID                [ 2: 0]: 0
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:         
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:     VPR state from fuse block    [ 3]: 0
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:         
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:     Frame end (FE)              [ 5]: 1
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:         A frame end has been found on a regular mode stream.
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:     CSI_FAULT                   [ 6]: 1
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:         An FE packet was found and marked with a CSI Error
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:     CSI_CODE                 [25:20]: 0x4
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]:         Check the CSI specification for the meaning. See https://wiki.nvidia.com/wmpwiki/index.php/Camera_Debugging/CaptureError_debugging#CSI_CODE
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/services/capture/CaptureServiceDeviceViCsi.cpp, function startCapture(), line 708)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/services/capture/CaptureServiceCore.cpp, function doCSItoISPCapture(), line 481)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/services/capture/CaptureServiceCore.cpp, function issueCapture(), line 362)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: captureErrorCallback Stream 0.0 capture 1 failed: ts 180508842528 frame 7 error 2 data 0x00400060
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/services/capture/CaptureServiceDevice.cpp, function issueCaptures(), line 1213)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/services/capture/CaptureServiceDevice.cpp, function issueCaptures(), line 1043)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error OverFlow:  (propagating from src/services/capture/CaptureServiceDevice.cpp, function returnRequestPoolCaptures(), line 1163)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState:  (propagating from src/common/Utils.cpp, function workerThread(), line 114)
Oct 18 14:13:21 tegra-ubuntu argus_daemon[1226]: SCF: Error InvalidState: Worker thread CaptureScheduler frameStart failed (in src/common/Utils.cpp, function workerThread(), line 131)
Oct 18 14:13:22 tegra-ubuntu kernel: [  154.173105] fence timeout on [ffffffc1a08f1300] after 1500ms
Oct 18 14:13:22 tegra-ubuntu kernel: [  154.178851] name=[nvhost_sync:23], current value=7 waiting value=8
Oct 18 14:13:22 tegra-ubuntu kernel: [  154.185432] fence timeout on [ffffffc062f0dc00] after 1500ms
  • Any ideas / hints / documentation regarding these messages? wiki.nvidia.com isn't reachable :/
  • I've read this "CsimuxFrameError_Regular : 0x00400060" relates to MIPI CRC Errors. Why don't these appear when I access the camera through v4l? How can I track this down?
  • What about those "ISO BW req 2147483647 > 2250000 (max) capping to max"? I get this message also with a imx290, seems to be a warning?
  • What about the ISP Override Files? Do I need them? (imx290 works without)

I’ve tried the following modifiations of the driver - however not successfull:

  • My DTB File contains three cameras. In long term we want to use three cameras, right now I have only one camera here. I tried removing the entries for the second and third camera - this supresses messages about "ar0144 31-0010" and "ar0144 32-0010", but results in the same timeout error for "ar0144 30-0010".
  • Tried changing from pixel format GRBG to RGGB - no improvement.
  • Tried changing ammount of metadata - no improvement. Btw: how can I receive the metadata lines?

I’ve attached the whole syslog as well as two patches for the device tree files and the kernel sources. This is the version which uses RGGB pixel format.

Any hints / comments would be aprreciated.
syslog-3ar0144rggb.txt (292 KB)
tri_streaming_ar0144_base28.2_EVA_tx2_dtbs_20181019.patch.txt (24.5 KB)
tri_streaming_ar0144_base28.2_EVA_tx2_kernel_20181019.patch.txt (49.9 KB)

Hi!

I’ve attached the dtb and kernel patches used in the start post. I’ve also re-run the v4l compliance test. Before switching from GRBR to RGGB it ran without failed tests, now it fails at two tests.

nvidia@tegra-ubuntu:~$ v4l2-compliance -d /dev/video0
Driver Info:
        Driver name   : tegra-video
        Card type     : vi-output, ar0144 30-0010
        Bus info      : platform:15700000.vi:0
        Driver version: 4.4.38
        Capabilities  : 0x84200001
                Video Capture
                Streaming
                Extended Pix Format
                Device Capabilities
        Device Caps   : 0x04200001
                Video Capture
                Streaming
                Extended Pix Format

Compliance test for device /dev/video0 (not using libv4l2):

Required ioctls:
        test VIDIOC_QUERYCAP: OK

Allow for multiple opens:
        test second video open: OK
        test VIDIOC_QUERYCAP: OK
        test VIDIOC_G/S_PRIORITY: OK

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

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

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

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

Test input 0:

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

        Format ioctls:
                test VIDIOC_ENUM_FMT/FRAMESIZES/FRAMEINTERVALS: OK
                test VIDIOC_G/S_PARM: OK (Not Supported)
                test VIDIOC_G_FBUF: OK (Not Supported)
                fail: v4l2-test-formats.cpp(427): unknown pixelformat 32314752 for buftype 1
                test VIDIOC_G_FMT: FAIL
                test VIDIOC_TRY_FMT: OK (Not Supported)
                test VIDIOC_S_FMT: OK (Not Supported)
                test VIDIOC_G_SLICED_VBI_CAP: OK (Not Supported)
                test Cropping: OK (Not Supported)
                test Composing: OK (Not Supported)
                test Scaling: OK (Not Supported)

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

        Buffer ioctls:
                test VIDIOC_REQBUFS/CREATE_BUFS/QUERYBUF: OK
                fail: v4l2-test-buffers.cpp(571): q.has_expbuf(node)
                test VIDIOC_EXPBUF: FAIL

Test input 0:


Total: 42, Succeeded: 40, Failed: 2, Warnings: 0

hello c.bodenstedt,

Q&As

Why don’t these appear when I access the camera through v4l? How can I track this down?
v4l2-ctl and Argus were going through different path.
please check the [Camera Architecture Stack] from [NVIDIA Tegra Linux Driver Package]-> [Release 28.2 Development Guide]-> [Camera Development]-> [Camera Software Development Solution] for more details.

What about those “ISO BW req 2147483647 > 2250000 (max) capping to max”? I get this message also with a imx290, seems to be a warning?
you can determine it as warning message since this won’t harm the camera functionality.

What about the ISP Override Files? Do I need them? (imx290 works without)
ISP overrides file is used for image quality, you can ignore that for your working process to brinup the sensor streaming

several suggestions as below,

  1. please correct your sensor device tree settings according to your sensor specification, you should pass the v4l2-compliance test first.
  2. please check [Sensor Driver Programming Guide] for your “embedded_metadata_height” configuration.
  3. please also refer to https://elinux.org/Jetson_TX2/28.1_Camera_BringUp for more debug tips,
    thanks

Hello JerryChang,

Thanks for your reply.

Regarding the metadata_height: according to the datasheet, the sensor can replace 2 blanking rows before the pixel data with register data. It can also append two lines of statistics. At this time the driver enables both, I’ll try out some different values.

Meanwhile I did the following changes:

In hardware/nvidia/platform/t18x/common/kernel-dts/t18x-common-modules/tegra186-camera-ar0144-a00.dtsi I changed
pixel_t = “bayer_grbg”;
to
pixel_t = “bayer_grbg12”;

-> Now the compliance test reports no more errors. (Honestly I guessed this values, since I don’t know, where the valid strings are defined.)

$ v4l2-compliance -d /dev/video0
Driver Info:
        Driver name   : tegra-video
        Card type     : vi-output, ar0144 30-0010
        Bus info      : platform:15700000.vi:0
        Driver version: 4.4.38
        Capabilities  : 0x84200001
                Video Capture
                Streaming
                Extended Pix Format
                Device Capabilities
        Device Caps   : 0x04200001
                Video Capture
                Streaming
                Extended Pix Format

Compliance test for device /dev/video0 (not using libv4l2):

Required ioctls:
        test VIDIOC_QUERYCAP: OK

Allow for multiple opens:
        test second video open: OK
        test VIDIOC_QUERYCAP: OK
        test VIDIOC_G/S_PRIORITY: OK

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

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

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

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

Test input 0:

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

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

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

        Buffer ioctls:
                test VIDIOC_REQBUFS/CREATE_BUFS/QUERYBUF: OK
                test VIDIOC_EXPBUF: OK

Test input 0:


Total: 42, Succeeded: 42, Failed: 0, Warnings: 0

----------------- syslog --------------------------------------------------

Oct 22 15:29:35 tegra-ubuntu kernel: [  422.905995] ar0144 30-0010: ar0144_power_on: power on
Oct 22 15:29:35 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Mon Oct 22 15:30:05 2018 [v8.16.0 try http://www.rs
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.919158] nvcsi 150c0000.nvcsi: csi port:0
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.923761] nvcsi 150c0000.nvcsi: csi port:2
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.928523] nvcsi 150c0000.nvcsi: csi port:4
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.933987] tegra-vi4 15700000.vi: =================  START STATUS  =================
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.941951] tegra-vi4 15700000.vi: ==================  END STATUS  ==================
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.950817] ar0144 30-0010: ar0144_set_frame_length length = 8320
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.957004] ar0144 30-0010: ar0144_set_frame_length: val: 8320
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.964081] ar0144 30-0010: ar0144_set_frame_length length = 831
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.970214] ar0144 30-0010: ar0144_set_frame_length: val: 831
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.976484] ar0144 30-0010: ar0144_set_frame_length length = 8320
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.982642] ar0144 30-0010: ar0144_set_frame_length: val: 8320
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.989059] ar0144 30-0010: ar0144_set_frame_length length = 831
Oct 22 15:29:35 tegra-ubuntu kernel: [  422.995175] ar0144 30-0010: ar0144_set_frame_length: val: 831
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.001418] ar0144 30-0010: ar0144_set_coarse_time
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.006264] ar0144 30-0010: ar0144_set_coarse_time: input val: 10
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.012431] ar0144 30-0010: ar0144_set_coarse_time: set val: 10
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.018934] ar0144 30-0010: ar0144_set_coarse_time
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.023803] ar0144 30-0010: ar0144_set_coarse_time: input val: 8300
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.030255] ar0144 30-0010: ar0144_set_coarse_time: set val: 8300
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.036879] ar0144 30-0010: ar0144_set_coarse_time
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.041722] ar0144 30-0010: ar0144_set_coarse_time: input val: 10
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.047907] ar0144 30-0010: ar0144_set_coarse_time: set val: 10
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.054254] ar0144 30-0010: ar0144_set_coarse_time
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.059103] ar0144 30-0010: ar0144_set_coarse_time: input val: 8300
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.065454] ar0144 30-0010: ar0144_set_coarse_time: set val: 8300
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.071963] ar0144 30-0010: ar0144_set_coarse_time
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.076793] ar0144 30-0010: ar0144_set_coarse_time: input val: 400
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.083055] ar0144 30-0010: ar0144_set_coarse_time: set val: 400
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.089434] ar0144 30-0010: ar0144_set_gain - val = 31
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.094609] ar0144 30-0010: input gain value: 3968
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.099466] ar0144 30-0010: ar0144_set_gain: gain 0f80 val: again 0001, dgain 07c0
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.107721] ar0144 30-0010: ar0144_set_gain - val = 1
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.112787] ar0144 30-0010: input gain value: 128
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.117585] ar0144 30-0010: ar0144_set_gain: gain 0080 val: again 0000, dgain 0080
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.125849] ar0144 30-0010: ar0144_set_gain - val = 31
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.131032] ar0144 30-0010: input gain value: 3968
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.135844] ar0144 30-0010: ar0144_set_gain: gain 0f80 val: again 0001, dgain 07c0
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.144069] ar0144 30-0010: ar0144_set_gain - val = 1
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.149169] ar0144 30-0010: input gain value: 128
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.153878] ar0144 30-0010: ar0144_set_gain: gain 0080 val: again 0000, dgain 0080
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.162131] video4linux video0: enable override control
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.174161] video4linux video0: disable override control
Oct 22 15:29:35 tegra-ubuntu kernel: [  423.179529] ar0144 30-0010: ar0144_power_off: power off

I also reverted drivers/media/platform/tegra/camera/csi/csi4_fops.c to its original contents. Previously the driver contained the patch from https://elinux.org/Jetson_TX2/28.1_Camera_BringUp to disable the ECC check.

-> Now I already get Errors when I try to capture RAW frames through yavta (and syslog entries like “tegra-vi4 15700000.vi: timestamp sof 736578161792 eof 736592522336 data 0x00400060”, “tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11”).

Once again, I get this magic value of 0x00400060. Is this the value of a kind of status register? Can I look up its meaning in a datasheet, maybe the parker_trm? (The value gets printed from vi4_fops.c from a function “tegra_channel_notify_status_callback” which is passed as an argument to “vi_notify_channel_set_notify_funcs”, of which I don’t find a definition. Now I’m lost.)

$ yavta /dev/video0 -c10 -n1 -Fdata.ar0144
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7fa17f8000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7fa1636000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7fa1474000.
0 (0) [E] 0 1843200 bytes 0.000000 1540215260.995701
Unable to queue buffer (5).
Unable to requeue buffer (5).
Unable to release buffers: 16.
$ ls -l # just one file created...
-rw-rw-r-- 1 nvidia 52 1843200 Oct 22 15:34 data.ar0144-000000.bin

----------------- syslog --------------------------------------------------

Oct 22 15:34:20 tegra-ubuntu kernel: [  708.340656] ar0144 30-0010: ar0144_power_on: power on
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.353670] nvcsi 150c0000.nvcsi: csi port:0
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.358308] nvcsi 150c0000.nvcsi: csi port:2
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.363084] nvcsi 150c0000.nvcsi: csi port:4
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.387653] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.394856] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.399755] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.404756] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.412716] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.417488] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.423264] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.429902] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.436399] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.442778] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.449719] ar0144 30-0010: ar0144_s_stream++
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.454114] ar0144 30-0010: ar0144_start_stream()
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.709855] ar0144 30-0010: ar0144_start_stream() - success
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.730270] video4linux video0: release_buffer: capture init latency is 345 ms
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.737603] video4linux video0: release_buffer: release buf[ffffffc1b282f800] frame[1] to user-space
Oct 22 15:34:20 tegra-ubuntu kernel: [  708.747043] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0002
Oct 22 15:34:21 tegra-ubuntu kernel: [  708.753476] tegra-vi4 15700000.vi:          timestamp sof 736578161792 eof 736592522336 data 0x00400060
Oct 22 15:34:21 tegra-ubuntu kernel: [  708.763034] tegra-vi4 15700000.vi:          capture_id 1 stream  0 vchan  0
Oct 22 15:34:21 tegra-ubuntu kernel: [  709.727991] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 22 15:34:21 tegra-ubuntu kernel: [  709.734593] video4linux video0: release_buffer: release buf[ffffffc1b282f400] frame[2] to user-space
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.744009] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.749740] video4linux video0: release_buffer: release buf[ffffffc1b282f000] frame[3] to user-space
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.759548] ar0144 30-0010: ar0144_s_stream++
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.764690] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.771998] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.776768] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.782555] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.788073] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.795930] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.804132] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 22 15:34:23 tegra-ubuntu kernel: [  710.815574] ar0144 30-0010: ar0144_power_off: power off

I’ll continue with the embedded metadata and next I’ll try to work through the “NVIDIA JETSON TX1 MI
PI DSI/CSI DESIGN AND TUNING” Appnote (hope it’s still valid for TX2).

Best regards,
Christian

hello c.bodenstedt,

  1. FYI, pixel_t property is deprecated and replaced with these properties: mode_type, csi_pixel_bit_depth, and pixel_phase. please also check the details from [Sensor Driver Programming Guide]
  2. according to your kernel messages, your camera frames is coming with long latency.
    since VI driver’s default timeout values is 200ms, could you please have a try to increase that.
  3. following above, please follow the steps in https://elinux.org/Jetson_TX2/28.1_Camera_BringUp to enable tracing logs for more debugging information.

Hello Jerry,

sorry for the delay. I’ve been busy with other projects, but I haven’t given up on the ar0144, yet.

Seems I was working with an old version of the “Sensor Driver Programming Guide” from 24.1. Now I have the 28.2 documentation, which hopefully fits to my 28.2.1 Installation.

Meanwhile I did the following changes:

  • Removed the pixel_t property from the DTS. Now this value gets concatenated from mode_type, pixel_phase and csi_pixel_bit_depth and the result is the same string value.
  • I measured my sensor input clock to be 27MHz, while in the DTS mclk_khz was set to 24000. I changed the value to 27000 and corrected the multiplier from "25" to "2.75", to match my sensor-clock of 74.25MHz. This fits to the sensors PLL settings. However, I don't think this changes anything, since 27MHz were generated already with the previous DTS file. So why is there a DTS parameter anyways?
  • I configured the Sensor to not fit register dumps in the blanking lines - no change noticed.
  • I increased the timeout in vi4_fops.c from 250 (probably milliseconds?) to 1250. Now it takes longer for yavta to fail, but I still get the same error messages.

I created a trace of the yavta call:

# as root
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
echo file csi2_fops.c +p > /sys/kernel/debug/dynamic_debug/control
echo file csi4_fops.c +p > /sys/kernel/debug/dynamic_debug/control
echo file ar0144.c +p >    /sys/kernel/debug/dynamic_debug/control
echo file imx290.c +p >    /sys/kernel/debug/dynamic_debug/control
echo file nvidia.c +p >    /sys/kernel/debug/dynamic_debug/control
echo file channel.c +p >   /sys/kernel/debug/dynamic_debug/control

# as user nvidia
yavta /dev/video0 -c10 -n1 -Fdata.ar0144
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7fae205000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7fae043000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7fade81000.
0 (0) [E] 0 1843200 bytes 0.000000 1540556564.580436
Unable to queue buffer (5).
Unable to requeue buffer (5).
Unable to release buffers: 16.

---------- syslog ----------------------------------------------

Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.554158] ar0144 30-0010: ar0144_power_on: power on
Oct 26 14:11:52 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Fri Oct 26 14:12:22 2018 [v8.16.0 try http://www.rsys
log.com/e/2007 ]
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.567271] nvcsi 150c0000.nvcsi: csi port:0
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.572008] nvcsi 150c0000.nvcsi: csi port:2
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.576857] nvcsi 150c0000.nvcsi: csi port:4
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.604104] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.611408] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.616270] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.621300] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.629290] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.634208] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.640028] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.646699] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.653202] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.659588] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.666522] ar0144 30-0010: ar0144_s_stream++
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.670920] ar0144 30-0010: ar0144_start_stream()
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.941302] ar0144 30-0010: ar0144_start_stream() - success
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.961719] video4linux video0: release_buffer: capture init latency is 360 ms
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.969104] video4linux video0: release_buffer: release buf[ffffffc1ec5d7400] frame[1] to user-space
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.978439] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0002
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.984931] tegra-vi4 15700000.vi:          timestamp sof 1096786659040 eof 1096801019552 data 0x004
00060
Oct 26 14:11:52 tegra-ubuntu kernel: [ 1068.994649] tegra-vi4 15700000.vi:          capture_id 1 stream  0 vchan  0
Oct 26 14:11:57 tegra-ubuntu kernel: [ 1073.959864] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 26 14:11:57 tegra-ubuntu kernel: [ 1073.966480] video4linux video0: release_buffer: release buf[ffffffc1ec5d4800] frame[2] to user-space
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1074.975877] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1074.981678] video4linux video0: release_buffer: release buf[ffffffc1ec5d4c00] frame[3] to user-space
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1074.991361] ar0144 30-0010: ar0144_s_stream++
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1074.996444] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.003597] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.008445] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.014324] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.019984] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.027931] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.036214] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 26 14:11:58 tegra-ubuntu kernel: [ 1075.047528] ar0144 30-0010: ar0144_power_off: power off


---------- trace -----------------------------------------------

# tracer: nop
#
# entries-in-buffer/entries-written: 50/50   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/0:2-307   [000] ...1  1720.556840: rtos_queue_peek_from_isr_failed: tstamp:54636609092 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1720.556849: rtcpu_start: tstamp:54636611216
     kworker/0:2-307   [000] ...1  1720.712930: rtos_queue_peek_from_isr_failed: tstamp:54641610084 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1720.868891: rtos_queue_peek_from_isr_failed: tstamp:54646610630 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1720.920962: rtcpu_vinotify_handle_msg: tstamp:54647548652 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:3107940574 data:0x00400060
     kworker/0:2-307   [000] ...1  1720.920975: rtcpu_vinotify_handle_msg: tstamp:54647619719 tag:CHANSEL_PXL_SOF channel:0x00 frame:2 vi_tstamp:3108011514 data:0x00000001
     kworker/0:2-307   [000] ...1  1720.920979: rtcpu_vinotify_handle_msg: tstamp:54647620100 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:3108011525 data:0x00000000
     kworker/0:2-307   [000] ...1  1720.920982: rtcpu_vinotify_handle_msg: tstamp:54647625754 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:2 vi_tstamp:3108017703 data:0x08000000
     kworker/0:2-307   [000] ...1  1720.920986: rtcpu_vinotify_handle_msg: tstamp:54648067093 tag:CHANSEL_PXL_EOF channel:0x00 frame:2 vi_tstamp:3108459017 data:0x02cf0002
     kworker/0:2-307   [000] ...1  1720.920989: rtcpu_vinotify_handle_msg: tstamp:54648068624 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:3108460281 data:0x00400060
     kworker/0:2-307   [000] ...1  1720.920992: rtcpu_vinotify_handle_msg: tstamp:54648068965 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:2 vi_tstamp:3108460281 data:0x00001000
     kworker/0:2-307   [000] ...1  1720.920996: rtcpu_vinotify_handle_msg: tstamp:54648069254 tag:ATOMP_FE channel:0x00 frame:2 vi_tstamp:3108460284 data:0x00000000
     kworker/0:2-307   [000] ...1  1721.076867: rtos_queue_peek_from_isr_failed: tstamp:54651611056 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1721.232895: rtos_queue_peek_from_isr_failed: tstamp:54656611635 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1721.388911: rtos_queue_peek_from_isr_failed: tstamp:54661612138 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1721.544883: rtos_queue_peek_from_isr_failed: tstamp:54666612648 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1721.700887: rtos_queue_peek_from_isr_failed: tstamp:54671613151 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1721.856887: rtos_queue_peek_from_isr_failed: tstamp:54676613669 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.012860: rtos_queue_peek_from_isr_failed: tstamp:54681614168 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.168897: rtos_queue_peek_from_isr_failed: tstamp:54686614674 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.324881: rtos_queue_peek_from_isr_failed: tstamp:54691615187 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.480877: rtos_queue_peek_from_isr_failed: tstamp:54696615687 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.636923: rtos_queue_peek_from_isr_failed: tstamp:54701616195 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.792887: rtos_queue_peek_from_isr_failed: tstamp:54706616706 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1722.948879: rtos_queue_peek_from_isr_failed: tstamp:54711617210 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.156914: rtos_queue_peek_from_isr_failed: tstamp:54716617712 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.312877: rtos_queue_peek_from_isr_failed: tstamp:54721618225 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.468883: rtos_queue_peek_from_isr_failed: tstamp:54726618743 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.624869: rtos_queue_peek_from_isr_failed: tstamp:54731619246 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.780869: rtos_queue_peek_from_isr_failed: tstamp:54736619760 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1723.936891: rtos_queue_peek_from_isr_failed: tstamp:54741620260 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.092891: rtos_queue_peek_from_isr_failed: tstamp:54746620769 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.248892: rtos_queue_peek_from_isr_failed: tstamp:54751621278 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.404883: rtos_queue_peek_from_isr_failed: tstamp:54756621781 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.560905: rtos_queue_peek_from_isr_failed: tstamp:54761622289 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.716889: rtos_queue_peek_from_isr_failed: tstamp:54766622794 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1724.872889: rtos_queue_peek_from_isr_failed: tstamp:54771623302 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.028873: rtos_queue_peek_from_isr_failed: tstamp:54776623811 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.236929: rtos_queue_peek_from_isr_failed: tstamp:54781624317 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.392894: rtos_queue_peek_from_isr_failed: tstamp:54786624824 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.548885: rtos_queue_peek_from_isr_failed: tstamp:54791625328 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.704887: rtos_queue_peek_from_isr_failed: tstamp:54796625837 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1725.860888: rtos_queue_peek_from_isr_failed: tstamp:54801626344 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.016903: rtos_queue_peek_from_isr_failed: tstamp:54806626851 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.172909: rtos_queue_peek_from_isr_failed: tstamp:54811627359 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.328877: rtos_queue_peek_from_isr_failed: tstamp:54816627864 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.484885: rtos_queue_peek_from_isr_failed: tstamp:54821628371 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.640950: rtos_queue_peek_from_isr_failed: tstamp:54826628878 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.796870: rtos_queue_peek_from_isr_failed: tstamp:54831629386 queue:0x0b4a3c58
     kworker/0:2-307   [000] ...1  1726.952925: rtos_queue_peek_from_isr_failed: tstamp:54836196465 queue:0x0b4a3c58

Excerpt from “dtc -I fs -O dts -o /tmp/extracted.dts /proc/device-tree”

i2c@0 {
        reg = <0x0>;
        #address-cells = <0x1>;
        i2c-mux,deselect-on-exit;
        #size-cells = <0x0>;

        pca9570_a@24 {
                reg = <0x24>;
                compatible = "nvidia,pca9570";
                drive_ic = "DRV8838";
                channel = [61 00];
        };

        ar0144_a@10 {
                reg = <0x10>;
                mclk = "extperiph1";
                post_crop_frame_drop = [30 00];
                avdd-reg = "vana";
                compatible = "nvidia,ar0144";
                clock-names = "extperiph1", "pllp_grtba";
                reset-gpios = <0x12 0x8d 0x0>;
                clock-frequency = <0x19bfcc0>;
                physical_h = "1.109";
                physical_w = "1.948";
                clocks = <0xd 0x59 0xd 0x10d>;
                vana-supply = <0x20>;
                sensor_model = "ar0144";
                iovdd-reg = "vif";
                delayed_gain = "true";
                vif-supply = <0x1f>;
                dvdd-reg = "vdig";
                vdig-supply = <0x21>;

                mode0 {
                        pixel_phase = "rggb";
                        embedded_metadata_height = [34 00];
                        dpcm_enable = "false";
                        inherent_gain = [31 00];
                        pix_clk_hz = "74250000";
                        max_gain_val = "31";
                        min_hdr_ratio = [31 00];
                        mode_type = "bayer";
                        min_framerate = [36 00];
                        cil_settletime = [30 00];
                        max_exp_time = "166332";
                        active_h = "720";
                        active_w = "1280";
                        dynamic_pixel_bit_depth = "12";
                        mclk_khz = "27000";
                        min_gain_val = [31 00];
                        max_hdr_ratio = "64";
                        max_framerate = "60";
                        tegra_sinterface = "serial_a";
                        line_length = "1488";
                        readout_orientation = [30 00];
                        mclk_multiplier = "2.75";
                        num_lanes = [32 00];
                        discontinuous_clk = "yes";
                        csi_pixel_bit_depth = "12";
                        min_exp_time = "200";
                };

                ports {
                        #address-cells = <0x1>;
                        #size-cells = <0x0>;

                        port@0 {
                                reg = <0x0>;

                                endpoint {
                                        bus-width = <0x2>;
                                        remote-endpoint = <0x22>;
                                        phandle = <0xa3>;
                                        csi-port = <0x0>;
                                        linux,phandle = <0xa3>;
                                };
                        };
                };
        };
};

hello c.bodenstedt,

your tracing message show below failures.

tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:3108460281 data:0x00400060

FE_CSI_FAULT

tag:CHANSEL_SHORT_FRAME channel:0x01 frame:2 vi_tstamp:3108460281 data:0x00001000

EMBED_INCOMPLETE

it shows you got a failure in the end-of-frame, it may caused by incomplete embedded metadata lines.
could you please double check the embedded metadata property with the sensor specification.
thanks

Hello Jerry.

The AR0144 can prepend 2 lines of “embedded data” before the pixel data. It can also append 2 lines of “embedded statistics” after the pixel data. On the last post, I had disabled the embedded statistics but the embedded_metadata_heigth parameter was still set to 4.

I tried out various combinations meanwhile. In all traces I got at least one line with “tag:CSIMUX_FRAME…data:0x00400060”. Where is this data value 0x00400060 coming from? Can I look up its meaning myself somewhere in nvidias documentation?

With embedded_metadata_height = 2 and only “embedded data” I get a trace without the EMBED_INCOMPLETE entry. With embedded_metadata_height = 4 and both “embedded data” and “embedded statistics” enabled I get a similar trace, differing only in timestamp values. Every now and then yavta produces a whole RAW frame, often it creates an empty file.

4 lines of metadata: embedded data and statistics. yavta + trace + syslog. Empty file output.

logger '=== yavta + trace a ===' ; ~/soft/yavta/yavta-master/yavta /dev/video0 -c10 -n1 -Fdata.ar0144a
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7f9cec3000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7f9cd01000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7f9cb3f000.
Warning: bytes used 0 != image size 1843200
0 (0) [-] 0 0 bytes 0.000000 1540908633.784294
Unable to queue buffer (22).
Unable to requeue buffer (22).
Unable to release buffers: 16.

Oct 30 15:10:33 tegra-ubuntu nvidia: === yavta + trace a ===
Oct 30 15:10:33 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Tue Oct 30 15:11:03 2018 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.844747] ar0144 30-0010: ar0144_power_on: power on
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.857981] nvcsi 150c0000.nvcsi: csi port:0
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.862622] nvcsi 150c0000.nvcsi: csi port:2
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.867456] nvcsi 150c0000.nvcsi: csi port:4
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.887617] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.894826] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.899662] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.904660] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.912600] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.917324] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.923102] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.929763] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.936220] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.942585] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.949504] ar0144 30-0010: ar0144_s_stream++
Oct 30 15:10:33 tegra-ubuntu kernel: [   71.953894] ar0144 30-0010: ar0144_start_stream()
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.209173] ar0144 30-0010: ar0144_start_stream() R0x3064=1982, data=1, stats=1
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.218848] ar0144 30-0010: ar0144_start_stream() - success
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.239252] video4linux video0: release_buffer: capture init latency is 354 ms
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.246588] video4linux video0: release_buffer: release buf[ffffffc1e48b4c00] frame[1] to user-space
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.253590] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0002
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.253610] tegra-vi4 15700000.vi:          timestamp sof 100053266720 eof 100067627264 data 0x00400060
Oct 30 15:10:33 tegra-ubuntu kernel: [   72.253623] tegra-vi4 15700000.vi:          capture_id 1 stream  0 vchan  0
Oct 30 15:10:38 tegra-ubuntu kernel: [   77.235698] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 15:10:38 tegra-ubuntu kernel: [   77.242213] video4linux video0: release_buffer: release buf[ffffffc1e31d7800] frame[2] to user-space
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.251486] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.257231] video4linux video0: release_buffer: release buf[ffffffc1e31d6c00] frame[3] to user-space
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.267013] ar0144 30-0010: ar0144_s_stream++
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.272190] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.279399] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.284348] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.290203] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.295810] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.303741] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.312027] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 30 15:10:39 tegra-ubuntu kernel: [   78.320500] ar0144 30-0010: ar0144_power_off: power off

# tracer: nop
#
# entries-in-buffer/entries-written: 49/49   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/0:1-114   [000] ...1    71.925181: rtos_queue_peek_from_isr_failed: tstamp:3115646092 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    71.925185: rtcpu_start: tstamp:3115647477
     kworker/0:1-114   [000] ...1    72.077169: rtos_queue_peek_from_isr_failed: tstamp:3120647032 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    72.233174: rtos_queue_peek_from_isr_failed: tstamp:3125647580 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    72.285112: rtcpu_vinotify_handle_msg: tstamp:3126594171 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:3126593645 data:0x00400060
     kworker/0:1-114   [000] ...1    72.285124: rtcpu_vinotify_handle_msg: tstamp:3126663882 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:3126663357 data:0x00000000
     kworker/0:1-114   [000] ...1    72.285127: rtcpu_vinotify_handle_msg: tstamp:3126665076 tag:CHANSEL_PXL_SOF channel:0x00 frame:2 vi_tstamp:3126664585 data:0x00000001
     kworker/0:1-114   [000] ...1    72.285131: rtcpu_vinotify_handle_msg: tstamp:3126670705 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:2 vi_tstamp:3126670207 data:0x08000000
     kworker/0:1-114   [000] ...1    72.285134: rtcpu_vinotify_handle_msg: tstamp:3127112610 tag:CHANSEL_PXL_EOF channel:0x00 frame:2 vi_tstamp:3127112088 data:0x02cf0002
     kworker/0:1-114   [000] ...1    72.285138: rtcpu_vinotify_handle_msg: tstamp:3127114011 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:3127113352 data:0x00400060
     kworker/0:1-114   [000] ...1    72.285141: rtcpu_vinotify_handle_msg: tstamp:3127114354 tag:ATOMP_FE channel:0x00 frame:2 vi_tstamp:3127113356 data:0x00000000
     kworker/0:1-114   [000] ...1    72.389087: rtos_queue_peek_from_isr_failed: tstamp:3130648102 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    72.545048: rtos_queue_peek_from_isr_failed: tstamp:3135648591 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    72.700979: rtos_queue_peek_from_isr_failed: tstamp:3140649098 queue:0x0b4a3c58
     kworker/0:1-114   [000] ...1    72.856942: rtos_queue_peek_from_isr_failed: tstamp:3145649603 queue:0x0b4a3c58
[...]

4 lines of metadata: embedded data and statistics. yavta + trace + syslog. One frame output.

nvidia@tegra-ubuntu:~/soft/kernel/debuging/metadata-tests/4ds$ logger '=== yavta + trace b ===' ; ~/soft/yavta/yavta-master/yavta /dev/video0 -c10 -n1 -Fdata.ar0144b
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7f8b339000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7f8b177000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7f8afb5000.
0 (0) [E] 0 1843200 bytes 0.000000 1540908678.598426
Unable to queue buffer (5).
Unable to requeue buffer (5).
Unable to release buffers: 16.

Oct 30 15:11:18 tegra-ubuntu nvidia: === yavta + trace b ===
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.646333] ar0144 30-0010: ar0144_power_on: power on
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.659834] nvcsi 150c0000.nvcsi: csi port:0
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.664486] nvcsi 150c0000.nvcsi: csi port:2
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.669239] nvcsi 150c0000.nvcsi: csi port:4
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.696963] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.704125] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.708956] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.713954] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.721888] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.726614] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.732368] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.738982] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.745426] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.751779] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.758660] ar0144 30-0010: ar0144_s_stream++
Oct 30 15:11:18 tegra-ubuntu kernel: [  116.763021] ar0144 30-0010: ar0144_start_stream()
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.016079] ar0144 30-0010: ar0144_start_stream() R0x3064=1982, data=1, stats=1
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.025600] ar0144 30-0010: ar0144_start_stream() - success
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.046040] video4linux video0: release_buffer: capture init latency is 355 ms
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.053504] video4linux video0: release_buffer: release buf[ffffffc07516b400] frame[1] to user-space
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.062876] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0002
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.069286] tegra-vi4 15700000.vi:          timestamp sof 144860017632 eof 144874378176 data 0x00400060
Oct 30 15:11:18 tegra-ubuntu kernel: [  117.078814] tegra-vi4 15700000.vi:          capture_id 3 stream  0 vchan  0
Oct 30 15:11:23 tegra-ubuntu kernel: [  122.044018] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 15:11:23 tegra-ubuntu kernel: [  122.050525] video4linux video0: release_buffer: release buf[ffffffc075169000] frame[2] to user-space
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.060015] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.065728] video4linux video0: release_buffer: release buf[ffffffc075168400] frame[3] to user-space
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.075502] ar0144 30-0010: ar0144_s_stream++
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.080590] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.087905] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.092688] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.098568] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.104330] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.112482] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.121085] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 30 15:11:24 tegra-ubuntu kernel: [  123.134591] ar0144 30-0010: ar0144_power_off: power off

# tracer: nop
#
# entries-in-buffer/entries-written: 49/49   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/0:3-1331  [000] ...1   116.696015: rtos_queue_peek_from_isr_failed: tstamp:4515814881 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   116.696028: rtcpu_start: tstamp:4515816416
     kworker/0:3-1331  [000] ...1   116.852007: rtos_queue_peek_from_isr_failed: tstamp:4520815815 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.062873: rtos_queue_peek_from_isr_failed: tstamp:4525816401 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.062894: rtcpu_vinotify_handle_msg: tstamp:4526805127 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:231837315 data:0x00400060
     kworker/0:3-1331  [000] ...1   117.062897: rtcpu_vinotify_handle_msg: tstamp:4526874836 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:231907028 data:0x00000000
     kworker/0:3-1331  [000] ...1   117.062900: rtcpu_vinotify_handle_msg: tstamp:4526876046 tag:CHANSEL_PXL_SOF channel:0x00 frame:2 vi_tstamp:231908255 data:0x00000001
     kworker/0:3-1331  [000] ...1   117.062903: rtcpu_vinotify_handle_msg: tstamp:4526882492 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:2 vi_tstamp:231914699 data:0x08000000
     kworker/0:3-1331  [000] ...1   117.062905: rtcpu_vinotify_handle_msg: tstamp:4527323559 tag:CHANSEL_PXL_EOF channel:0x00 frame:2 vi_tstamp:232355758 data:0x02cf0002
     kworker/0:3-1331  [000] ...1   117.062908: rtcpu_vinotify_handle_msg: tstamp:4527324978 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:232357022 data:0x00400060
     kworker/0:3-1331  [000] ...1   117.062911: rtcpu_vinotify_handle_msg: tstamp:4527325320 tag:ATOMP_FE channel:0x00 frame:2 vi_tstamp:232357025 data:0x00000000
     kworker/0:3-1331  [000] ...1   117.216061: rtos_queue_peek_from_isr_failed: tstamp:4530817006 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.372052: rtos_queue_peek_from_isr_failed: tstamp:4535817400 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.528098: rtos_queue_peek_from_isr_failed: tstamp:4540817902 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.684074: rtos_queue_peek_from_isr_failed: tstamp:4545818409 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.840074: rtos_queue_peek_from_isr_failed: tstamp:4550818915 queue:0x0b4a3c58
     kworker/0:3-1331  [000] ...1   117.996057: rtos_queue_peek_from_isr_failed: tstamp:4555819424 queue:0x0b4a3c58
[...]

I also tried setting embedded_metadata_height to 1 (which should be nonsense). With at least embedded data enabled, yavta produces 10 valid looking RAW files. But it took about 5 seconds for each grabbed frame.

1 lines of metadata: embedded data and statistics. yavta + trace + syslog. Ten frames output @ 0.2fps.

logger '=== yavta + trace a ===' ; ~/soft/yavta/yavta-master/yavta /dev/video0 -c10 -n1 -Fdata.ar0144a
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7f8201b000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7f81e59000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7f81c97000.
0 (0) [E] 0 1843200 bytes 0.000000 1540912798.307103
1 (1) [E] 1 1843200 bytes 0.000000 1540912803.303505
2 (2) [-] 2 1843200 bytes 0.000000 1540912808.307594
3 (0) [-] 3 1843200 bytes 0.000000 1540912813.311579
4 (1) [-] 4 1843200 bytes 0.000000 1540912818.315485
5 (2) [-] 5 1843200 bytes 0.000000 1540912823.319572
6 (0) [-] 6 1843200 bytes 0.000000 1540912828.323487
7 (1) [-] 7 1843200 bytes 0.000000 1540912833.327464
8 (2) [-] 8 1843200 bytes 0.000000 1540912838.331516
9 (0) [-] 9 1843200 bytes 0.000000 1540912843.335605
Captured 9 frames in 45.109949 seconds (0.199513 fps, 408601.659026 B/s).
3 buffers released.

Oct 30 16:19:52 tegra-ubuntu nvidia: === yavta + trace a ===
Oct 30 16:19:52 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Tue Oct 30 16:20:22 2018 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.266890] ar0144 30-0010: ar0144_power_on: power on
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.279029] nvcsi 150c0000.nvcsi: csi port:0
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.283474] nvcsi 150c0000.nvcsi: csi port:2
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.287930] nvcsi 150c0000.nvcsi: csi port:4
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.298105] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.305263] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 30 16:19:52 tegra-ubuntu kernel: [   82.310088] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.315080] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.323014] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.327740] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.333518] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.340146] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.346669] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.353054] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.359955] ar0144 30-0010: ar0144_s_stream++
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.364331] ar0144 30-0010: ar0144_start_stream()
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.594069] ar0144 30-0010: ar0144_start_stream() R0x3064=1982, data=1, stats=1
Oct 30 16:19:53 tegra-ubuntu kernel: [   82.602742] ar0144 30-0010: ar0144_start_stream() - success
Oct 30 16:19:58 tegra-ubuntu kernel: [   87.606197] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:19:58 tegra-ubuntu kernel: [   87.612822] video4linux video0: release_buffer: capture init latency is 5316 ms
Oct 30 16:19:58 tegra-ubuntu kernel: [   87.620317] video4linux video0: release_buffer: release buf[ffffffc1ca7f2400] frame[1] to user-space
Oct 30 16:20:03 tegra-ubuntu kernel: [   92.610155] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:03 tegra-ubuntu kernel: [   92.616700] video4linux video0: release_buffer: release buf[ffffffc1ca7f3c00] frame[2] to user-space
Oct 30 16:20:08 tegra-ubuntu kernel: [   97.614178] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:08 tegra-ubuntu kernel: [   97.620722] video4linux video0: release_buffer: release buf[ffffffc1ca7f3000] frame[3] to user-space
Oct 30 16:20:13 tegra-ubuntu kernel: [  102.618185] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:13 tegra-ubuntu kernel: [  102.624731] video4linux video0: release_buffer: release buf[ffffffc1ca7f2400] frame[4] to user-space
Oct 30 16:20:18 tegra-ubuntu kernel: [  107.622182] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:18 tegra-ubuntu kernel: [  107.628718] video4linux video0: release_buffer: release buf[ffffffc1ca7f3c00] frame[5] to user-space
Oct 30 16:20:23 tegra-ubuntu kernel: [  112.626185] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:23 tegra-ubuntu kernel: [  112.632779] video4linux video0: release_buffer: release buf[ffffffc1ca7f3000] frame[6] to user-space
Oct 30 16:20:23 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Tue Oct 30 16:20:53 2018 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Oct 30 16:20:28 tegra-ubuntu kernel: [  117.630153] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:28 tegra-ubuntu kernel: [  117.636695] video4linux video0: release_buffer: release buf[ffffffc1ca7f2400] frame[7] to user-space
Oct 30 16:20:33 tegra-ubuntu kernel: [  122.634173] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:33 tegra-ubuntu kernel: [  122.640713] video4linux video0: release_buffer: release buf[ffffffc1ca7f3c00] frame[8] to user-space
Oct 30 16:20:38 tegra-ubuntu kernel: [  127.638190] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:38 tegra-ubuntu kernel: [  127.644740] video4linux video0: release_buffer: release buf[ffffffc1ca7f3000] frame[9] to user-space
Oct 30 16:20:43 tegra-ubuntu kernel: [  132.642179] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:43 tegra-ubuntu kernel: [  132.648721] video4linux video0: release_buffer: release buf[ffffffc1ca7f2400] frame[10] to user-space
Oct 30 16:20:48 tegra-ubuntu kernel: [  137.646201] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 16:20:48 tegra-ubuntu kernel: [  137.652741] video4linux video0: release_buffer: release buf[ffffffc1ca7f3000] frame[11] to user-space
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.662187] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.667928] video4linux video0: release_buffer: release buf[ffffffc1ca7f2400] frame[12] to user-space
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.677974] ar0144 30-0010: ar0144_s_stream++
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.682974] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.690724] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.696050] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.701891] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.707474] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.715467] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.723723] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 30 16:20:49 tegra-ubuntu kernel: [  138.736560] ar0144 30-0010: ar0144_power_off: power off

# tracer: nop
#
# entries-in-buffer/entries-written: 3786/3786   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/3:2-266   [003] ...1    82.306057: rtos_queue_peek_from_isr_failed: tstamp:3441790745 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    82.306062: rtcpu_start: tstamp:3441791496
     kworker/3:2-266   [003] ...1    82.462066: rtos_queue_peek_from_isr_failed: tstamp:3446791607 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    82.618077: rtos_queue_peek_from_isr_failed: tstamp:3451792110 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    82.670110: rtcpu_vinotify_handle_msg: tstamp:3451900454 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:3451900035 data:0x00400060
     kworker/3:2-266   [003] ...1    82.670112: rtcpu_vinotify_handle_msg: tstamp:3451970162 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:3451969747 data:0x00000000
     kworker/3:2-266   [003] ...1    82.670113: rtcpu_vinotify_handle_msg: tstamp:3451970765 tag:CHANSEL_FAULT channel:0x00 frame:2 vi_tstamp:3451970353 data:0x00010800
     kworker/3:2-266   [003] ...1    82.670114: rtcpu_vinotify_handle_msg: tstamp:3451971378 tag:CHANSEL_FAULT channel:0x00 frame:2 vi_tstamp:3451970975 data:0x00000801
     kworker/3:2-266   [003] ...1    82.670114: rtcpu_vinotify_handle_msg: tstamp:3452418885 tag:CHANSEL_FAULT channel:0x00 frame:2 vi_tstamp:3452418478 data:0x02cf0802
     kworker/3:2-266   [003] ...1    82.670115: rtcpu_vinotify_handle_msg: tstamp:3452420316 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:3452419742 data:0x00400060
     kworker/3:2-266   [003] ...1    82.670115: rtcpu_vinotify_handle_msg: tstamp:3452420451 tag:ATOMP_FE channel:0x00 frame:2 vi_tstamp:3452419745 data:0x00000000
     kworker/3:2-266   [003] ...1    82.670116: rtcpu_vinotify_handle_msg: tstamp:3452939859 tag:CSIMUX_FRAME channel:0x00 frame:3 vi_tstamp:3452939448 data:0x00400060
     kworker/3:2-266   [003] ...1    82.722081: rtcpu_vinotify_handle_msg: tstamp:3453459566 tag:CSIMUX_FRAME channel:0x00 frame:4 vi_tstamp:3453459155 data:0x00400060
     kworker/3:2-266   [003] ...1    82.722084: rtcpu_vinotify_handle_msg: tstamp:3453979269 tag:CSIMUX_FRAME channel:0x00 frame:5 vi_tstamp:3453978862 data:0x00400060
     kworker/3:2-266   [003] ...1    82.722085: rtcpu_vinotify_handle_msg: tstamp:3454498976 tag:CSIMUX_FRAME channel:0x00 frame:6 vi_tstamp:3454498568 data:0x00400060
     kworker/3:2-266   [003] ...1    82.722085: rtcpu_vinotify_handle_msg: tstamp:3455018686 tag:CSIMUX_FRAME channel:0x00 frame:7 vi_tstamp:3455018275 data:0x00400060
     kworker/3:2-266   [003] ...1    82.774073: rtcpu_vinotify_handle_msg: tstamp:3455538392 tag:CSIMUX_FRAME channel:0x00 frame:8 vi_tstamp:3455537981 data:0x00400060
     kworker/3:2-266   [003] ...1    82.774076: rtcpu_vinotify_handle_msg: tstamp:3456058095 tag:CSIMUX_FRAME channel:0x00 frame:9 vi_tstamp:3456057688 data:0x00400060
     kworker/3:2-266   [003] ...1    82.774076: rtcpu_vinotify_handle_msg: tstamp:3456577807 tag:CSIMUX_FRAME channel:0x00 frame:10 vi_tstamp:3456577395 data:0x00400060
     kworker/3:2-266   [003] ...1    82.826077: rtos_queue_peek_from_isr_failed: tstamp:3456792612 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    82.826080: rtcpu_vinotify_handle_msg: tstamp:3457097512 tag:CSIMUX_FRAME channel:0x00 frame:11 vi_tstamp:3457097101 data:0x00400060
     kworker/3:2-266   [003] ...1    82.826081: rtcpu_vinotify_handle_msg: tstamp:3457617219 tag:CSIMUX_FRAME channel:0x00 frame:12 vi_tstamp:3457616808 data:0x00400060
     kworker/3:2-266   [003] ...1    82.826081: rtcpu_vinotify_handle_msg: tstamp:3458136922 tag:CSIMUX_FRAME channel:0x00 frame:13 vi_tstamp:3458136514 data:0x00400060
     kworker/3:2-266   [003] ...1    82.878123: rtcpu_vinotify_handle_msg: tstamp:3458656632 tag:CSIMUX_FRAME channel:0x00 frame:14 vi_tstamp:3458656221 data:0x00400060
     kworker/3:2-266   [003] ...1    82.878126: rtcpu_vinotify_handle_msg: tstamp:3459176338 tag:CSIMUX_FRAME channel:0x00 frame:15 vi_tstamp:3459175928 data:0x00400060
     kworker/3:2-266   [003] ...1    82.878127: rtcpu_vinotify_handle_msg: tstamp:3459696044 tag:CSIMUX_FRAME channel:0x00 frame:16 vi_tstamp:3459695634 data:0x00400060
     kworker/3:2-266   [003] ...1    82.930078: rtcpu_vinotify_handle_msg: tstamp:3460215749 tag:CSIMUX_FRAME channel:0x00 frame:17 vi_tstamp:3460215341 data:0x00400060
     kworker/3:2-266   [003] ...1    82.930080: rtcpu_vinotify_handle_msg: tstamp:3460735455 tag:CSIMUX_FRAME channel:0x00 frame:18 vi_tstamp:3460735047 data:0x00400060
     kworker/3:2-266   [003] ...1    82.930081: rtcpu_vinotify_handle_msg: tstamp:3461255161 tag:CSIMUX_FRAME channel:0x00 frame:19 vi_tstamp:3461254754 data:0x00400060
     kworker/3:2-266   [003] ...1    82.982075: rtcpu_vinotify_handle_msg: tstamp:3461774871 tag:CSIMUX_FRAME channel:0x00 frame:20 vi_tstamp:3461774460 data:0x00400060
     kworker/3:2-266   [003] ...1    82.982080: rtos_queue_peek_from_isr_failed: tstamp:3461793116 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    82.982081: rtcpu_vinotify_handle_msg: tstamp:3462294578 tag:CSIMUX_FRAME channel:0x00 frame:21 vi_tstamp:3462294167 data:0x00400060
     kworker/3:2-266   [003] ...1    82.982081: rtcpu_vinotify_handle_msg: tstamp:3462814285 tag:CSIMUX_FRAME channel:0x00 frame:22 vi_tstamp:3462813874 data:0x00400060
     kworker/3:2-266   [003] ...1    83.034084: rtcpu_vinotify_handle_msg: tstamp:3463333991 tag:CSIMUX_FRAME channel:0x00 frame:23 vi_tstamp:3463333580 data:0x00400060
     kworker/3:2-266   [003] ...1    83.034087: rtcpu_vinotify_handle_msg: tstamp:3463853712 tag:CSIMUX_FRAME channel:0x00 frame:24 vi_tstamp:3463853287 data:0x00400060
     kworker/3:2-266   [003] ...1    83.034087: rtcpu_vinotify_handle_msg: tstamp:3464373406 tag:CSIMUX_FRAME channel:0x00 frame:25 vi_tstamp:3464372993 data:0x00400060
     kworker/3:2-266   [003] ...1    83.086067: rtcpu_vinotify_handle_msg: tstamp:3464893116 tag:CSIMUX_FRAME channel:0x00 frame:26 vi_tstamp:3464892700 data:0x00400060
     kworker/3:2-266   [003] ...1    83.086070: rtcpu_vinotify_handle_msg: tstamp:3465412817 tag:CSIMUX_FRAME channel:0x00 frame:27 vi_tstamp:3465412407 data:0x00400060
     kworker/3:2-266   [003] ...1    83.086071: rtcpu_vinotify_handle_msg: tstamp:3465932522 tag:CSIMUX_FRAME channel:0x00 frame:28 vi_tstamp:3465932113 data:0x00400060
     kworker/3:2-266   [003] ...1    83.138072: rtcpu_vinotify_handle_msg: tstamp:3466452227 tag:CSIMUX_FRAME channel:0x00 frame:29 vi_tstamp:3466451820 data:0x00400060
     kworker/3:2-266   [003] ...1    83.138076: rtos_queue_peek_from_isr_failed: tstamp:3466793625 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.138077: rtcpu_vinotify_handle_msg: tstamp:3466971937 tag:CSIMUX_FRAME channel:0x00 frame:30 vi_tstamp:3466971526 data:0x00400060
     kworker/3:2-266   [003] ...1    83.138077: rtcpu_vinotify_handle_msg: tstamp:3467491641 tag:CSIMUX_FRAME channel:0x00 frame:31 vi_tstamp:3467491233 data:0x00400060
     kworker/3:2-266   [003] ...1    83.138078: rtcpu_vinotify_handle_msg: tstamp:3468011348 tag:CSIMUX_FRAME channel:0x00 frame:32 vi_tstamp:3468010940 data:0x00400060
     kworker/3:2-266   [003] ...1    83.190111: rtcpu_vinotify_handle_msg: tstamp:3468531053 tag:CSIMUX_FRAME channel:0x00 frame:33 vi_tstamp:3468530646 data:0x00400060
     kworker/3:2-266   [003] ...1    83.190114: rtcpu_vinotify_handle_msg: tstamp:3469050760 tag:CSIMUX_FRAME channel:0x00 frame:34 vi_tstamp:3469050353 data:0x00400060
     kworker/3:2-266   [003] ...1    83.190114: rtcpu_vinotify_handle_msg: tstamp:3469570471 tag:CSIMUX_FRAME channel:0x00 frame:35 vi_tstamp:3469570059 data:0x00400060
     kworker/3:2-266   [003] ...1    83.242131: rtcpu_vinotify_handle_msg: tstamp:3470090174 tag:CSIMUX_FRAME channel:0x00 frame:36 vi_tstamp:3470089766 data:0x00400060
     kworker/3:2-266   [003] ...1    83.242134: rtcpu_vinotify_handle_msg: tstamp:3470609881 tag:CSIMUX_FRAME channel:0x00 frame:37 vi_tstamp:3470609472 data:0x00400060
     kworker/3:2-266   [003] ...1    83.242135: rtcpu_vinotify_handle_msg: tstamp:3471129592 tag:CSIMUX_FRAME channel:0x00 frame:38 vi_tstamp:3471129179 data:0x00400060
     kworker/3:2-266   [003] ...1    83.294110: rtcpu_vinotify_handle_msg: tstamp:3471649294 tag:CSIMUX_FRAME channel:0x00 frame:39 vi_tstamp:3471648886 data:0x00400060
     kworker/3:2-266   [003] ...1    83.294114: rtos_queue_peek_from_isr_failed: tstamp:3471794133 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.294114: rtcpu_vinotify_handle_msg: tstamp:3472169001 tag:CSIMUX_FRAME channel:0x00 frame:40 vi_tstamp:3472168592 data:0x00400060
     kworker/3:2-266   [003] ...1    83.294115: rtcpu_vinotify_handle_msg: tstamp:3472688706 tag:CSIMUX_FRAME channel:0x00 frame:41 vi_tstamp:3472688299 data:0x00400060
     kworker/3:2-266   [003] ...1    83.346079: rtcpu_vinotify_handle_msg: tstamp:3473208414 tag:CSIMUX_FRAME channel:0x00 frame:42 vi_tstamp:3473208005 data:0x00400060
     kworker/3:2-266   [003] ...1    83.346082: rtcpu_vinotify_handle_msg: tstamp:3473728120 tag:CSIMUX_FRAME channel:0x00 frame:43 vi_tstamp:3473727712 data:0x00400060
     kworker/3:2-266   [003] ...1    83.346083: rtcpu_vinotify_handle_msg: tstamp:3474247826 tag:CSIMUX_FRAME channel:0x00 frame:44 vi_tstamp:3474247418 data:0x00400060
     kworker/3:2-266   [003] ...1    83.398109: rtcpu_vinotify_handle_msg: tstamp:3474767537 tag:CSIMUX_FRAME channel:0x00 frame:45 vi_tstamp:3474767125 data:0x00400060
     kworker/3:2-266   [003] ...1    83.398111: rtcpu_vinotify_handle_msg: tstamp:3475287239 tag:CSIMUX_FRAME channel:0x00 frame:46 vi_tstamp:3475286832 data:0x00400060
     kworker/3:2-266   [003] ...1    83.398112: rtcpu_vinotify_handle_msg: tstamp:3475806946 tag:CSIMUX_FRAME channel:0x00 frame:47 vi_tstamp:3475806538 data:0x00400060
     kworker/3:2-266   [003] ...1    83.450110: rtcpu_vinotify_handle_msg: tstamp:3476326652 tag:CSIMUX_FRAME channel:0x00 frame:48 vi_tstamp:3476326245 data:0x00400060
     kworker/3:2-266   [003] ...1    83.450114: rtos_queue_peek_from_isr_failed: tstamp:3476794641 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.450115: rtcpu_vinotify_handle_msg: tstamp:3476846358 tag:CSIMUX_FRAME channel:0x00 frame:49 vi_tstamp:3476845951 data:0x00400060
     kworker/3:2-266   [003] ...1    83.450115: rtcpu_vinotify_handle_msg: tstamp:3477366066 tag:CSIMUX_FRAME channel:0x00 frame:50 vi_tstamp:3477365658 data:0x00400060
     kworker/3:2-266   [003] ...1    83.502085: rtcpu_vinotify_handle_msg: tstamp:3477885772 tag:CSIMUX_FRAME channel:0x00 frame:51 vi_tstamp:3477885365 data:0x00400060
     kworker/3:2-266   [003] ...1    83.502088: rtcpu_vinotify_handle_msg: tstamp:3478405479 tag:CSIMUX_FRAME channel:0x00 frame:52 vi_tstamp:3478405071 data:0x00400060
     kworker/3:2-266   [003] ...1    83.502088: rtcpu_vinotify_handle_msg: tstamp:3478925185 tag:CSIMUX_FRAME channel:0x00 frame:53 vi_tstamp:3478924778 data:0x00400060
     kworker/3:2-266   [003] ...1    83.554076: rtcpu_vinotify_handle_msg: tstamp:3479444891 tag:CSIMUX_FRAME channel:0x00 frame:54 vi_tstamp:3479444484 data:0x00400060
     kworker/3:2-266   [003] ...1    83.554079: rtcpu_vinotify_handle_msg: tstamp:3479964598 tag:CSIMUX_FRAME channel:0x00 frame:55 vi_tstamp:3479964191 data:0x00400060
     kworker/3:2-266   [003] ...1    83.554080: rtcpu_vinotify_handle_msg: tstamp:3480484306 tag:CSIMUX_FRAME channel:0x00 frame:56 vi_tstamp:3480483898 data:0x00400060
     kworker/3:2-266   [003] ...1    83.554080: rtcpu_vinotify_handle_msg: tstamp:3481004015 tag:CSIMUX_FRAME channel:0x00 frame:57 vi_tstamp:3481003604 data:0x00400060
     kworker/3:2-266   [003] ...1    83.606063: rtcpu_vinotify_handle_msg: tstamp:3481523719 tag:CSIMUX_FRAME channel:0x00 frame:58 vi_tstamp:3481523311 data:0x00400060
     kworker/3:2-266   [003] ...1    83.606067: rtos_queue_peek_from_isr_failed: tstamp:3481795146 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.606068: rtcpu_vinotify_handle_msg: tstamp:3482043428 tag:CSIMUX_FRAME channel:0x00 frame:59 vi_tstamp:3482043017 data:0x00400060
     kworker/3:2-266   [003] ...1    83.606069: rtcpu_vinotify_handle_msg: tstamp:3482563133 tag:CSIMUX_FRAME channel:0x00 frame:60 vi_tstamp:3482562724 data:0x00400060
     kworker/3:2-266   [003] ...1    83.658058: rtcpu_vinotify_handle_msg: tstamp:3483082840 tag:CSIMUX_FRAME channel:0x00 frame:61 vi_tstamp:3483082430 data:0x00400060
     kworker/3:2-266   [003] ...1    83.658061: rtcpu_vinotify_handle_msg: tstamp:3483602546 tag:CSIMUX_FRAME channel:0x00 frame:62 vi_tstamp:3483602137 data:0x00400060
     kworker/3:2-266   [003] ...1    83.658061: rtcpu_vinotify_handle_msg: tstamp:3484122251 tag:CSIMUX_FRAME channel:0x00 frame:63 vi_tstamp:3484121844 data:0x00400060
     kworker/3:2-266   [003] ...1    83.710062: rtcpu_vinotify_handle_msg: tstamp:3484641958 tag:CSIMUX_FRAME channel:0x00 frame:64 vi_tstamp:3484641550 data:0x00400060
     kworker/3:2-266   [003] ...1    83.710065: rtcpu_vinotify_handle_msg: tstamp:3485161664 tag:CSIMUX_FRAME channel:0x00 frame:65 vi_tstamp:3485161257 data:0x00400060
     kworker/3:2-266   [003] ...1    83.710066: rtcpu_vinotify_handle_msg: tstamp:3485681372 tag:CSIMUX_FRAME channel:0x00 frame:66 vi_tstamp:3485680964 data:0x00400060
     kworker/3:2-266   [003] ...1    83.762063: rtcpu_vinotify_handle_msg: tstamp:3486201078 tag:CSIMUX_FRAME channel:0x00 frame:67 vi_tstamp:3486200670 data:0x00400060
     kworker/3:2-266   [003] ...1    83.762065: rtcpu_vinotify_handle_msg: tstamp:3486720785 tag:CSIMUX_FRAME channel:0x00 frame:68 vi_tstamp:3486720377 data:0x00400060
     kworker/3:2-266   [003] ...1    83.762068: rtos_queue_peek_from_isr_failed: tstamp:3486795655 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.762068: rtcpu_vinotify_handle_msg: tstamp:3487240492 tag:CSIMUX_FRAME channel:0x00 frame:69 vi_tstamp:3487240083 data:0x00400060
     kworker/3:2-266   [003] ...1    83.814057: rtcpu_vinotify_handle_msg: tstamp:3487760199 tag:CSIMUX_FRAME channel:0x00 frame:70 vi_tstamp:3487759790 data:0x00400060
     kworker/3:2-266   [003] ...1    83.814059: rtcpu_vinotify_handle_msg: tstamp:3488279904 tag:CSIMUX_FRAME channel:0x00 frame:71 vi_tstamp:3488279497 data:0x00400060
     kworker/3:2-266   [003] ...1    83.814060: rtcpu_vinotify_handle_msg: tstamp:3488799612 tag:CSIMUX_FRAME channel:0x00 frame:72 vi_tstamp:3488799203 data:0x00400060
     kworker/3:2-266   [003] ...1    83.866082: rtcpu_vinotify_handle_msg: tstamp:3489319319 tag:CSIMUX_FRAME channel:0x00 frame:73 vi_tstamp:3489318910 data:0x00400060
     kworker/3:2-266   [003] ...1    83.866086: rtcpu_vinotify_handle_msg: tstamp:3489839025 tag:CSIMUX_FRAME channel:0x00 frame:74 vi_tstamp:3489838616 data:0x00400060
     kworker/3:2-266   [003] ...1    83.866086: rtcpu_vinotify_handle_msg: tstamp:3490358732 tag:CSIMUX_FRAME channel:0x00 frame:75 vi_tstamp:3490358323 data:0x00400060
     kworker/3:2-266   [003] ...1    83.918088: rtcpu_vinotify_handle_msg: tstamp:3490878439 tag:CSIMUX_FRAME channel:0x00 frame:76 vi_tstamp:3490878029 data:0x00400060
     kworker/3:2-266   [003] ...1    83.918091: rtcpu_vinotify_handle_msg: tstamp:3491398144 tag:CSIMUX_FRAME channel:0x00 frame:77 vi_tstamp:3491397736 data:0x00400060
     kworker/3:2-266   [003] ...1    83.918094: rtos_queue_peek_from_isr_failed: tstamp:3491796159 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    83.918094: rtcpu_vinotify_handle_msg: tstamp:3491917852 tag:CSIMUX_FRAME channel:0x00 frame:78 vi_tstamp:3491917443 data:0x00400060
     kworker/3:2-266   [003] ...1    83.918095: rtcpu_vinotify_handle_msg: tstamp:3492437558 tag:CSIMUX_FRAME channel:0x00 frame:79 vi_tstamp:3492437149 data:0x00400060
     kworker/3:2-266   [003] ...1    83.970095: rtcpu_vinotify_handle_msg: tstamp:3492957261 tag:CSIMUX_FRAME channel:0x00 frame:80 vi_tstamp:3492956856 data:0x00400060
     kworker/3:2-266   [003] ...1    83.970100: rtcpu_vinotify_handle_msg: tstamp:3493476971 tag:CSIMUX_FRAME channel:0x00 frame:81 vi_tstamp:3493476562 data:0x00400060
     kworker/3:2-266   [003] ...1    83.970101: rtcpu_vinotify_handle_msg: tstamp:3493996678 tag:CSIMUX_FRAME channel:0x00 frame:82 vi_tstamp:3493996269 data:0x00400060
     kworker/3:2-266   [003] ...1    84.022091: rtcpu_vinotify_handle_msg: tstamp:3494516383 tag:CSIMUX_FRAME channel:0x00 frame:83 vi_tstamp:3494515976 data:0x00400060
     kworker/3:2-266   [003] ...1    84.022096: rtcpu_vinotify_handle_msg: tstamp:3495036113 tag:CSIMUX_FRAME channel:0x00 frame:84 vi_tstamp:3495035682 data:0x00400060
     kworker/3:2-266   [003] ...1    84.022098: rtcpu_vinotify_handle_msg: tstamp:3495555814 tag:CSIMUX_FRAME channel:0x00 frame:85 vi_tstamp:3495555389 data:0x00400060
     kworker/3:2-266   [003] ...1    84.074060: rtcpu_vinotify_handle_msg: tstamp:3496075521 tag:CSIMUX_FRAME channel:0x00 frame:86 vi_tstamp:3496075095 data:0x00400060
     kworker/3:2-266   [003] ...1    84.074063: rtcpu_vinotify_handle_msg: tstamp:3496595227 tag:CSIMUX_FRAME channel:0x00 frame:87 vi_tstamp:3496594802 data:0x00400060
     kworker/3:2-266   [003] ...1    84.074065: rtos_queue_peek_from_isr_failed: tstamp:3496796667 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.074066: rtcpu_vinotify_handle_msg: tstamp:3497114914 tag:CSIMUX_FRAME channel:0x00 frame:88 vi_tstamp:3497114509 data:0x00400060
     kworker/3:2-266   [003] ...1    84.126062: rtcpu_vinotify_handle_msg: tstamp:3497634624 tag:CSIMUX_FRAME channel:0x00 frame:89 vi_tstamp:3497634215 data:0x00400060
     kworker/3:2-266   [003] ...1    84.126065: rtcpu_vinotify_handle_msg: tstamp:3498154329 tag:CSIMUX_FRAME channel:0x00 frame:90 vi_tstamp:3498153922 data:0x00400060
     kworker/3:2-266   [003] ...1    84.126066: rtcpu_vinotify_handle_msg: tstamp:3498674034 tag:CSIMUX_FRAME channel:0x00 frame:91 vi_tstamp:3498673628 data:0x00400060
     kworker/3:2-266   [003] ...1    84.178054: rtcpu_vinotify_handle_msg: tstamp:3499193743 tag:CSIMUX_FRAME channel:0x00 frame:92 vi_tstamp:3499193335 data:0x00400060
     kworker/3:2-266   [003] ...1    84.178056: rtcpu_vinotify_handle_msg: tstamp:3499713449 tag:CSIMUX_FRAME channel:0x00 frame:93 vi_tstamp:3499713042 data:0x00400060
     kworker/3:2-266   [003] ...1    84.178057: rtcpu_vinotify_handle_msg: tstamp:3500233156 tag:CSIMUX_FRAME channel:0x00 frame:94 vi_tstamp:3500232748 data:0x00400060
     kworker/3:2-266   [003] ...1    84.230048: rtcpu_vinotify_handle_msg: tstamp:3500752863 tag:CSIMUX_FRAME channel:0x00 frame:95 vi_tstamp:3500752455 data:0x00400060
     kworker/3:2-266   [003] ...1    84.230051: rtcpu_vinotify_handle_msg: tstamp:3501272566 tag:CSIMUX_FRAME channel:0x00 frame:96 vi_tstamp:3501272161 data:0x00400060
     kworker/3:2-266   [003] ...1    84.230052: rtcpu_vinotify_handle_msg: tstamp:3501792273 tag:CSIMUX_FRAME channel:0x00 frame:97 vi_tstamp:3501791868 data:0x00400060
     kworker/3:2-266   [003] ...1    84.230054: rtos_queue_peek_from_isr_failed: tstamp:3501797179 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.282056: rtcpu_vinotify_handle_msg: tstamp:3502311983 tag:CSIMUX_FRAME channel:0x00 frame:98 vi_tstamp:3502311574 data:0x00400060
     kworker/3:2-266   [003] ...1    84.282058: rtcpu_vinotify_handle_msg: tstamp:3502831689 tag:CSIMUX_FRAME channel:0x00 frame:99 vi_tstamp:3502831281 data:0x00400060
     kworker/3:2-266   [003] ...1    84.282059: rtcpu_vinotify_handle_msg: tstamp:3503351396 tag:CSIMUX_FRAME channel:0x00 frame:100 vi_tstamp:3503350988 data:0x00400060
     kworker/3:2-266   [003] ...1    84.334063: rtcpu_vinotify_handle_msg: tstamp:3503871103 tag:CSIMUX_FRAME channel:0x00 frame:101 vi_tstamp:3503870694 data:0x00400060
     kworker/3:2-266   [003] ...1    84.334066: rtcpu_vinotify_handle_msg: tstamp:3504390809 tag:CSIMUX_FRAME channel:0x00 frame:102 vi_tstamp:3504390401 data:0x00400060
     kworker/3:2-266   [003] ...1    84.334067: rtcpu_vinotify_handle_msg: tstamp:3504910517 tag:CSIMUX_FRAME channel:0x00 frame:103 vi_tstamp:3504910107 data:0x00400060
     kworker/3:2-266   [003] ...1    84.334068: rtcpu_vinotify_handle_msg: tstamp:3505430223 tag:CSIMUX_FRAME channel:0x00 frame:104 vi_tstamp:3505429814 data:0x00400060
     kworker/3:2-266   [003] ...1    84.386058: rtcpu_vinotify_handle_msg: tstamp:3505949930 tag:CSIMUX_FRAME channel:0x00 frame:105 vi_tstamp:3505949520 data:0x00400060
     kworker/3:2-266   [003] ...1    84.386060: rtcpu_vinotify_handle_msg: tstamp:3506469638 tag:CSIMUX_FRAME channel:0x00 frame:106 vi_tstamp:3506469227 data:0x00400060
     kworker/3:2-266   [003] ...1    84.386062: rtos_queue_peek_from_isr_failed: tstamp:3506797681 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.386063: rtcpu_vinotify_handle_msg: tstamp:3506989344 tag:CSIMUX_FRAME channel:0x00 frame:107 vi_tstamp:3506988934 data:0x00400060
     kworker/3:2-266   [003] ...1    84.438057: rtcpu_vinotify_handle_msg: tstamp:3507509050 tag:CSIMUX_FRAME channel:0x00 frame:108 vi_tstamp:3507508640 data:0x00400060
     kworker/3:2-266   [003] ...1    84.438060: rtcpu_vinotify_handle_msg: tstamp:3508028757 tag:CSIMUX_FRAME channel:0x00 frame:109 vi_tstamp:3508028347 data:0x00400060
     kworker/3:2-266   [003] ...1    84.438061: rtcpu_vinotify_handle_msg: tstamp:3508548463 tag:CSIMUX_FRAME channel:0x00 frame:110 vi_tstamp:3508548054 data:0x00400060
     kworker/3:2-266   [003] ...1    84.490139: rtcpu_vinotify_handle_msg: tstamp:3509068169 tag:CSIMUX_FRAME channel:0x00 frame:111 vi_tstamp:3509067760 data:0x00400060
     kworker/3:2-266   [003] ...1    84.490143: rtcpu_vinotify_handle_msg: tstamp:3509587897 tag:CSIMUX_FRAME channel:0x00 frame:112 vi_tstamp:3509587467 data:0x00400060
     kworker/3:2-266   [003] ...1    84.490145: rtcpu_vinotify_handle_msg: tstamp:3510107604 tag:CSIMUX_FRAME channel:0x00 frame:113 vi_tstamp:3510107173 data:0x00400060
     kworker/3:2-266   [003] ...1    84.542136: rtcpu_vinotify_handle_msg: tstamp:3510627333 tag:CSIMUX_FRAME channel:0x00 frame:114 vi_tstamp:3510626880 data:0x00400060
     kworker/3:2-266   [003] ...1    84.542140: rtcpu_vinotify_handle_msg: tstamp:3511147040 tag:CSIMUX_FRAME channel:0x00 frame:115 vi_tstamp:3511146586 data:0x00400060
     kworker/3:2-266   [003] ...1    84.542143: rtcpu_vinotify_handle_msg: tstamp:3511666747 tag:CSIMUX_FRAME channel:0x00 frame:116 vi_tstamp:3511666293 data:0x00400060
     kworker/3:2-266   [003] ...1    84.542150: rtos_queue_peek_from_isr_failed: tstamp:3511798233 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.594118: rtcpu_vinotify_handle_msg: tstamp:3512186518 tag:CSIMUX_FRAME channel:0x00 frame:117 vi_tstamp:3512186000 data:0x00400060
     kworker/3:2-266   [003] ...1    84.594123: rtcpu_vinotify_handle_msg: tstamp:3512706225 tag:CSIMUX_FRAME channel:0x00 frame:118 vi_tstamp:3512705706 data:0x00400060
     kworker/3:2-266   [003] ...1    84.594126: rtcpu_vinotify_handle_msg: tstamp:3513225932 tag:CSIMUX_FRAME channel:0x00 frame:119 vi_tstamp:3513225413 data:0x00400060
     kworker/3:2-266   [003] ...1    84.646107: rtcpu_vinotify_handle_msg: tstamp:3513745637 tag:CSIMUX_FRAME channel:0x00 frame:120 vi_tstamp:3513745119 data:0x00400060
     kworker/3:2-266   [003] ...1    84.646112: rtcpu_vinotify_handle_msg: tstamp:3514265345 tag:CSIMUX_FRAME channel:0x00 frame:121 vi_tstamp:3514264826 data:0x00400060
     kworker/3:2-266   [003] ...1    84.646115: rtcpu_vinotify_handle_msg: tstamp:3514785052 tag:CSIMUX_FRAME channel:0x00 frame:122 vi_tstamp:3514784533 data:0x00400060
     kworker/3:2-266   [003] ...1    84.698113: rtcpu_vinotify_handle_msg: tstamp:3515304758 tag:CSIMUX_FRAME channel:0x00 frame:123 vi_tstamp:3515304239 data:0x00400060
     kworker/3:2-266   [003] ...1    84.698119: rtcpu_vinotify_handle_msg: tstamp:3515824464 tag:CSIMUX_FRAME channel:0x00 frame:124 vi_tstamp:3515823946 data:0x00400060
     kworker/3:2-266   [003] ...1    84.698122: rtcpu_vinotify_handle_msg: tstamp:3516344196 tag:CSIMUX_FRAME channel:0x00 frame:125 vi_tstamp:3516343652 data:0x00400060
     kworker/3:2-266   [003] ...1    84.698128: rtos_queue_peek_from_isr_failed: tstamp:3516798803 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.750109: rtcpu_vinotify_handle_msg: tstamp:3516863878 tag:CSIMUX_FRAME channel:0x00 frame:126 vi_tstamp:3516863359 data:0x00400060
     kworker/3:2-266   [003] ...1    84.750113: rtcpu_vinotify_handle_msg: tstamp:3517383585 tag:CSIMUX_FRAME channel:0x00 frame:127 vi_tstamp:3517383065 data:0x00400060
     kworker/3:2-266   [003] ...1    84.750116: rtcpu_vinotify_handle_msg: tstamp:3517903289 tag:CSIMUX_FRAME channel:0x00 frame:128 vi_tstamp:3517902772 data:0x00400060
     kworker/3:2-266   [003] ...1    84.750120: rtcpu_vinotify_handle_msg: tstamp:3518422996 tag:CSIMUX_FRAME channel:0x00 frame:129 vi_tstamp:3518422479 data:0x00400060
     kworker/3:2-266   [003] ...1    84.802102: rtcpu_vinotify_handle_msg: tstamp:3518942704 tag:CSIMUX_FRAME channel:0x00 frame:130 vi_tstamp:3518942185 data:0x00400060
     kworker/3:2-266   [003] ...1    84.802108: rtcpu_vinotify_handle_msg: tstamp:3519462407 tag:CSIMUX_FRAME channel:0x00 frame:131 vi_tstamp:3519461892 data:0x00400060
     kworker/3:2-266   [003] ...1    84.802111: rtcpu_vinotify_handle_msg: tstamp:3519982124 tag:CSIMUX_FRAME channel:0x00 frame:132 vi_tstamp:3519981598 data:0x00400060
     kworker/3:2-266   [003] ...1    84.854146: rtcpu_vinotify_handle_msg: tstamp:3520501821 tag:CSIMUX_FRAME channel:0x00 frame:133 vi_tstamp:3520501305 data:0x00400060
     kworker/3:2-266   [003] ...1    84.854158: rtcpu_vinotify_handle_msg: tstamp:3521021529 tag:CSIMUX_FRAME channel:0x00 frame:134 vi_tstamp:3521021012 data:0x00400060
     kworker/3:2-266   [003] ...1    84.854162: rtcpu_vinotify_handle_msg: tstamp:3521541237 tag:CSIMUX_FRAME channel:0x00 frame:135 vi_tstamp:3521540718 data:0x00400060
     kworker/3:2-266   [003] ...1    84.906178: rtos_queue_peek_from_isr_failed: tstamp:3521799311 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    84.906182: rtcpu_vinotify_handle_msg: tstamp:3522060944 tag:CSIMUX_FRAME channel:0x00 frame:136 vi_tstamp:3522060425 data:0x00400060
     kworker/3:2-266   [003] ...1    84.906186: rtcpu_vinotify_handle_msg: tstamp:3522580646 tag:CSIMUX_FRAME channel:0x00 frame:137 vi_tstamp:3522580131 data:0x00400060
     kworker/3:2-266   [003] ...1    84.906189: rtcpu_vinotify_handle_msg: tstamp:3523100356 tag:CSIMUX_FRAME channel:0x00 frame:138 vi_tstamp:3523099838 data:0x00400060
     kworker/3:2-266   [003] ...1    84.958172: rtcpu_vinotify_handle_msg: tstamp:3523620060 tag:CSIMUX_FRAME channel:0x00 frame:139 vi_tstamp:3523619544 data:0x00400060
     kworker/3:2-266   [003] ...1    84.958177: rtcpu_vinotify_handle_msg: tstamp:3524139769 tag:CSIMUX_FRAME channel:0x00 frame:140 vi_tstamp:3524139251 data:0x00400060
     kworker/3:2-266   [003] ...1    84.958180: rtcpu_vinotify_handle_msg: tstamp:3524659476 tag:CSIMUX_FRAME channel:0x00 frame:141 vi_tstamp:3524658958 data:0x00400060
     kworker/3:2-266   [003] ...1    85.010114: rtcpu_vinotify_handle_msg: tstamp:3525179182 tag:CSIMUX_FRAME channel:0x00 frame:142 vi_tstamp:3525178664 data:0x00400060
     kworker/3:2-266   [003] ...1    85.010119: rtcpu_vinotify_handle_msg: tstamp:3525698888 tag:CSIMUX_FRAME channel:0x00 frame:143 vi_tstamp:3525698371 data:0x00400060
     kworker/3:2-266   [003] ...1    85.010122: rtcpu_vinotify_handle_msg: tstamp:3526218600 tag:CSIMUX_FRAME channel:0x00 frame:144 vi_tstamp:3526218077 data:0x00400060
     kworker/3:2-266   [003] ...1    85.062141: rtcpu_vinotify_handle_msg: tstamp:3526738303 tag:CSIMUX_FRAME channel:0x00 frame:145 vi_tstamp:3526737784 data:0x00400060
     kworker/3:2-266   [003] ...1    85.062149: rtos_queue_peek_from_isr_failed: tstamp:3526799816 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    85.062154: rtcpu_vinotify_handle_msg: tstamp:3527258010 tag:CSIMUX_FRAME channel:0x00 frame:146 vi_tstamp:3527257491 data:0x00400060
     kworker/3:2-266   [003] ...1    85.062157: rtcpu_vinotify_handle_msg: tstamp:3527777715 tag:CSIMUX_FRAME channel:0x00 frame:147 vi_tstamp:3527777197 data:0x00400060
     kworker/3:2-266   [003] ...1    85.114171: rtcpu_vinotify_handle_msg: tstamp:3528297423 tag:CSIMUX_FRAME channel:0x00 frame:148 vi_tstamp:3528296904 data:0x00400060
     kworker/3:2-266   [003] ...1    85.114176: rtcpu_vinotify_handle_msg: tstamp:3528817130 tag:CSIMUX_FRAME channel:0x00 frame:149 vi_tstamp:3528816610 data:0x00400060
     kworker/3:2-266   [003] ...1    85.114179: rtcpu_vinotify_handle_msg: tstamp:3529336837 tag:CSIMUX_FRAME channel:0x00 frame:150 vi_tstamp:3529336317 data:0x00400060
     kworker/3:2-266   [003] ...1    85.166130: rtcpu_vinotify_handle_msg: tstamp:3529856552 tag:CSIMUX_FRAME channel:0x00 frame:151 vi_tstamp:3529856023 data:0x00400060
     kworker/3:2-266   [003] ...1    85.166134: rtcpu_vinotify_handle_msg: tstamp:3530376250 tag:CSIMUX_FRAME channel:0x00 frame:152 vi_tstamp:3530375730 data:0x00400060
     kworker/3:2-266   [003] ...1    85.166137: rtcpu_vinotify_handle_msg: tstamp:3530895957 tag:CSIMUX_FRAME channel:0x00 frame:153 vi_tstamp:3530895437 data:0x00400060
     kworker/3:2-266   [003] ...1    85.166141: rtcpu_vinotify_handle_msg: tstamp:3531415662 tag:CSIMUX_FRAME channel:0x00 frame:154 vi_tstamp:3531415143 data:0x00400060
     kworker/3:2-266   [003] ...1    85.218118: rtos_queue_peek_from_isr_failed: tstamp:3531800324 queue:0x0b4a3c58
     kworker/3:2-266   [003] ...1    85.218123: rtcpu_vinotify_handle_msg: tstamp:3531935370 tag:CSIMUX_FRAME channel:0x00 frame:155 vi_tstamp:3531934850 data:0x00400060
     kworker/3:2-266   [003] ...1    85.218126: rtcpu_vinotify_handle_msg: tstamp:3532455090 tag:CSIMUX_FRAME channel:0x00 frame:156 vi_tstamp:3532454557 data:0x00400060
     kworker/3:2-266   [003] ...1    85.218129: rtcpu_vinotify_handle_msg: tstamp:3532974781 tag:CSIMUX_FRAME channel:0x00 frame:157 vi_tstamp:3532974263 data:0x00400060
     kworker/3:2-266   [003] ...1    85.270114: rtcpu_vinotify_handle_msg: tstamp:3533494489 tag:CSIMUX_FRAME channel:0x00 frame:158 vi_tstamp:3533493970 data:0x00400060
     kworker/3:2-266   [003] ...1    85.270118: rtcpu_vinotify_handle_msg: tstamp:3534014194 tag:CSIMUX_FRAME channel:0x00 frame:159 vi_tstamp:3534013676 data:0x00400060
     kworker/3:2-266   [003] ...1    85.270122: rtcpu_vinotify_handle_msg: tstamp:3534533901 tag:CSIMUX_FRAME channel:0x00 frame:160 vi_tstamp:3534533383 data:0x00400060
     kworker/3:2-266   [003] ...1    85.322110: rtcpu_vinotify_handle_msg: tstamp:3535053605 tag:CSIMUX_FRAME channel:0x00 frame:161 vi_tstamp:3535053089 data:0x00400060
     kworker/3:2-266   [003] ...1    85.322115: rtcpu_vinotify_handle_msg: tstamp:3535573312 tag:CSIMUX_FRAME channel:0x00 frame:162 vi_tstamp:3535572796 data:0x00400060
     kworker/3:2-266   [003] ...1    85.322118: rtcpu_vinotify_handle_msg: tstamp:3536093021 tag:CSIMUX_FRAME channel:0x00 frame:163 vi_tstamp:3536092502 data:0x00400060
     kworker/3:2-266   [003] ...1    85.374229: rtcpu_vinotify_handle_msg: tstamp:3536612729 tag:CSIMUX_FRAME channel:0x00 frame:164 vi_tstamp:3536612209 data:0x00400060
[...]

patch.txt (74.7 KB)
data.ar0144b-000000.bin.zip (640 KB)

hello c.bodenstedt,

  1. “tag:CSIMUX_FRAME…data:0x00400060”. Where is this data value 0x00400060 coming from? Can I look up its meaning myself somewhere in nvidias documentation?
    sorry, we don’t have public documentation for you to analysis those details.

  2. we only support embedded metadata line “before” pixel data, you should configure your sensor driver to disable outputting embedded metadata lines after pixel data. please also update device tree properties to match exactly metadata lines of the sensor outputting.

Hello Jerry,

  1. Would such information be available under NDA?

  2. I had tried that variant “only metadata before the pixeldata” already. The trace differs only in timestamp values, compared to 4 lines of metadata from the last post.

DTB: embedded_metadata_heigth=2
AR0144: two lines of metadata before pixel data. Statistics after pixel data disabled.

$ logger '=== yavta + trace a ===' ; ~/soft/yavta/yavta-master/yavta /dev/video0 -c10 -n1 -Fdata.ar0144a
Device /dev/video0 opened: vi-output, ar0144 30-0010 (platform:15700000.vi:0).
Video format: RG12 (32314752) 1280x720
3 buffers requested.
length: 1843200 offset: 0
Buffer 0 mapped at address 0x7f84707000.
length: 1843200 offset: 1843200
Buffer 1 mapped at address 0x7f84545000.
length: 1843200 offset: 3686400
Buffer 2 mapped at address 0x7f84383000.
Warning: bytes used 0 != image size 1843200
0 (0) [-] 0 0 bytes 0.000000 1540905939.034083
Unable to queue buffer (22).
Unable to requeue buffer (22).
Unable to release buffers: 16.
# syslog
Oct 30 14:25:38 tegra-ubuntu nvidia: === yavta + trace a ===
Oct 30 14:25:38 tegra-ubuntu rsyslogd-2007: action 'action 9' suspended, next retry is Tue Oct 30 14:26:08 2018 [v8.16.0 try http://www.rsyslog.com/e/2007 ]
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.576304] ar0144 30-0010: ar0144_power_on: power on
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.589361] nvcsi 150c0000.nvcsi: csi port:0
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.593996] nvcsi 150c0000.nvcsi: csi port:2
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.598725] nvcsi 150c0000.nvcsi: csi port:4
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.625151] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=2
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.632330] nvcsi 150c0000.nvcsi: csi4_stream_init
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.637165] nvcsi 150c0000.nvcsi: csi4_stream_config
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.642160] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.650080] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.654793] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.660552] nvcsi 150c0000.nvcsi: cil_settingtime is pulled from device
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.667166] nvcsi 150c0000.nvcsi: cil core clock: 204, csi clock: 102
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.673610] nvcsi 150c0000.nvcsi: cil_settingtime was autocalculated
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.679963] nvcsi 150c0000.nvcsi: csi settle time: 33, cil settle time: 25
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.686844] ar0144 30-0010: ar0144_s_stream++
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.691206] ar0144 30-0010: ar0144_start_stream()
Oct 30 14:25:38 tegra-ubuntu kernel: [  123.939289] ar0144 30-0010: ar0144_start_stream() R0x3064=1902, data=1, stats=0
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.948858] ar0144 30-0010: ar0144_start_stream() - success
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.969263] video4linux video0: release_buffer: capture init latency is 349 ms
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.976651] video4linux video0: release_buffer: release buf[ffffffc1c3f9b400] frame[1] to user-space
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.983578] tegra-vi4 15700000.vi: Status:  2 channel:00 frame:0002
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.983598] tegra-vi4 15700000.vi:          timestamp sof 151820868960 eof 151835189728 data 0x00400060
Oct 30 14:25:39 tegra-ubuntu kernel: [  123.983613] tegra-vi4 15700000.vi:          capture_id 1 stream  0 vchan  0
Oct 30 14:25:44 tegra-ubuntu kernel: [  128.966976] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
Oct 30 14:25:44 tegra-ubuntu kernel: [  128.973466] video4linux video0: release_buffer: release buf[ffffffc1c3f9b000] frame[2] to user-space
Oct 30 14:25:45 tegra-ubuntu kernel: [  129.982927] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!
Oct 30 14:25:45 tegra-ubuntu kernel: [  129.988704] video4linux video0: release_buffer: release buf[ffffffc1c3f98400] frame[3] to user-space
Oct 30 14:25:45 tegra-ubuntu kernel: [  129.998471] ar0144 30-0010: ar0144_s_stream++
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.003602] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=2
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.010744] nvcsi 150c0000.nvcsi: csi4_phy_config
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.015627] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000002
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.021455] nvcsi 150c0000.nvcsi: csi4_stream_check_status
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.027071] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000004
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.035051] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000004
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.043289] nvcsi 150c0000.nvcsi: csi4_cil_check_status 353
Oct 30 14:25:45 tegra-ubuntu kernel: [  130.055270] ar0144 30-0010: ar0144_power_off: power off
# tracer: nop
#
# entries-in-buffer/entries-written: 49/49   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     kworker/0:2-266   [000] ...1   123.651256: rtos_queue_peek_from_isr_failed: tstamp:4733561241 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   123.651260: rtcpu_start: tstamp:4733563080
     kworker/0:2-266   [000] ...1   123.807232: rtos_queue_peek_from_isr_failed: tstamp:4738562168 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   123.963265: rtos_queue_peek_from_isr_failed: tstamp:4743562749 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.015344: rtcpu_vinotify_handle_msg: tstamp:4744330498 tag:CSIMUX_FRAME channel:0x00 frame:1 vi_tstamp:449362676 data:0x00400060
     kworker/0:2-266   [000] ...1   124.015354: rtcpu_vinotify_handle_msg: tstamp:4744401455 tag:ATOMP_FS channel:0x00 frame:2 vi_tstamp:449433631 data:0x00000000
     kworker/0:2-266   [000] ...1   124.015358: rtcpu_vinotify_handle_msg: tstamp:4744402647 tag:CHANSEL_PXL_SOF channel:0x00 frame:2 vi_tstamp:449434859 data:0x00000001
     kworker/0:2-266   [000] ...1   124.015362: rtcpu_vinotify_handle_msg: tstamp:4744408453 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:2 vi_tstamp:449440660 data:0x08000000
     kworker/0:2-266   [000] ...1   124.015365: rtcpu_vinotify_handle_msg: tstamp:4744850477 tag:CHANSEL_PXL_EOF channel:0x00 frame:2 vi_tstamp:449882362 data:0x02cf0002
     kworker/0:2-266   [000] ...1   124.015368: rtcpu_vinotify_handle_msg: tstamp:4744850759 tag:CSIMUX_FRAME channel:0x00 frame:2 vi_tstamp:449882383 data:0x00400060
     kworker/0:2-266   [000] ...1   124.015372: rtcpu_vinotify_handle_msg: tstamp:4744851100 tag:ATOMP_FE channel:0x00 frame:2 vi_tstamp:449882386 data:0x00000000
     kworker/0:2-266   [000] ...1   124.119250: rtos_queue_peek_from_isr_failed: tstamp:4748563256 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.275224: rtos_queue_peek_from_isr_failed: tstamp:4753563764 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.431220: rtos_queue_peek_from_isr_failed: tstamp:4758564265 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.587176: rtos_queue_peek_from_isr_failed: tstamp:4763564774 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.743217: rtos_queue_peek_from_isr_failed: tstamp:4768565279 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   124.951241: rtos_queue_peek_from_isr_failed: tstamp:4773565792 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.107234: rtos_queue_peek_from_isr_failed: tstamp:4778566292 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.263151: rtos_queue_peek_from_isr_failed: tstamp:4783566800 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.419148: rtos_queue_peek_from_isr_failed: tstamp:4788567305 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.575132: rtos_queue_peek_from_isr_failed: tstamp:4793567814 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.731122: rtos_queue_peek_from_isr_failed: tstamp:4798568322 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   125.887146: rtos_queue_peek_from_isr_failed: tstamp:4803568842 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.043146: rtos_queue_peek_from_isr_failed: tstamp:4808569343 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.199169: rtos_queue_peek_from_isr_failed: tstamp:4813569844 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.355099: rtos_queue_peek_from_isr_failed: tstamp:4818570351 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.511080: rtos_queue_peek_from_isr_failed: tstamp:4823570862 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.667072: rtos_queue_peek_from_isr_failed: tstamp:4828571378 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   126.823056: rtos_queue_peek_from_isr_failed: tstamp:4833571870 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.031032: rtos_queue_peek_from_isr_failed: tstamp:4838572375 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.187027: rtos_queue_peek_from_isr_failed: tstamp:4843572883 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.343065: rtos_queue_peek_from_isr_failed: tstamp:4848573391 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.499063: rtos_queue_peek_from_isr_failed: tstamp:4853573909 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.655042: rtos_queue_peek_from_isr_failed: tstamp:4858574404 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.811020: rtos_queue_peek_from_isr_failed: tstamp:4863574909 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   127.966972: rtos_queue_peek_from_isr_failed: tstamp:4868575417 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.122951: rtos_queue_peek_from_isr_failed: tstamp:4873575921 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.278932: rtos_queue_peek_from_isr_failed: tstamp:4878576430 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.434949: rtos_queue_peek_from_isr_failed: tstamp:4883576934 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.590919: rtos_queue_peek_from_isr_failed: tstamp:4888577443 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.746901: rtos_queue_peek_from_isr_failed: tstamp:4893577952 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   128.902916: rtos_queue_peek_from_isr_failed: tstamp:4898578456 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.110909: rtos_queue_peek_from_isr_failed: tstamp:4903578965 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.266879: rtos_queue_peek_from_isr_failed: tstamp:4908579470 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.422877: rtos_queue_peek_from_isr_failed: tstamp:4913579978 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.578852: rtos_queue_peek_from_isr_failed: tstamp:4918580486 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.734845: rtos_queue_peek_from_isr_failed: tstamp:4923580992 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   129.890849: rtos_queue_peek_from_isr_failed: tstamp:4928581499 queue:0x0b4a3c58
     kworker/0:2-266   [000] ...1   130.048977: rtos_queue_peek_from_isr_failed: tstamp:4932819526 queue:0x0b4a3c58

Best regards,
Christian

hello c.bodenstedt,

  1. Would such information be available under NDA?
    sorry, it’s not available even under NDA.

  2. you may apply these fixes from Topic 1038067, which fix CSI Camera Capture on r28.2.1/TX2.

Hello JerryChang,

thanks for your help. I’ve changed the initialisation sequence to the default values provided from Onsemi (with embedded_metadata_heigth=2 and two lines of metadata before the pixels). The sensor is now working with argus. :)

hello c.bodenstedt,

glad to know that.
since there are several comments and suggestions,
could you please have summarize and let’s close this topic.
thanks

Hello JerryChang,

I have built the kernel using the patch above. However, I am not sure how to update the device tree. What is the correct procedure?

Thanks,

hello vviswan2,

please refer to Flashing and Booting the Target Device session, and check the [Flash Script Usage] for the steps.
thanks