Can't get mipi csi trace log!

Hi,
I executed commands as followed to enable log tracing

#!/bin/sh

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 1 > /sys/kernel/debug/tracing/events/camera_common/enable
echo > /sys/kernel/debug/tracing/trace

echo file vi2_fops.c +p > /sys/kernel/debug/dynamic_debug/control
echo file csi2_fops.c +p > /sys/kernel/debug/dynamic_debug/control

echo file vi4_fops.c +p > /sys/kernel/debug/dynamic_debug/control
echo file csi.c +p > /sys/kernel/debug/dynamic_debug/control
echo file csi4_fops.c +p > /sys/kernel/debug/dynamic_debug/control
echo file nvcsi.c +p > /sys/kernel/debug/dynamic_debug/control

cat /sys/kernel/debug/tracing/trace

use v4l2-ctl to capture mipi input, only kernel error messages shows

# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:6
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
root@amoymn:/home/jetson# [ 1492.422697] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 1492.429191] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 1492.440449] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004
[ 1492.650670] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 1492.657070] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 1492.667227] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004
[ 1492.878706] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 1492.885108] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 1492.895632] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004
[ 1493.106740] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 1493.113274] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 1493.123142] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004
[ 1493.334694] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
[ 1493.341111] tegra-vi4 15700000.vi: tegra_channel_error_recovery: attempting to reset the capture channel
[ 1493.352214] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004

didn’t find any csi tracing log…

Could you read them back to check if both of them are correctly.

Yes, all of them are configured correctly

root@amoymn:/home/jetson# cat /sys/kernel/debug/tracing/tracing_on 
1
root@amoymn:/home/jetson# cat /sys/kernel/debug/tracing/buffer_size_kb 
30720
root@amoymn:/home/jetson# cat /sys/kernel/debug/tracing/events/tegra_rtcpu/enable
1
root@amoymn:/home/jetson# cat /sys/kernel/debug/tracing/events/freertos/enable
1
root@amoymn:/home/jetson# cat /sys/kernel/debug/camrtc/log-level
2
root@amoymn:/home/jetson# cat /sys/kernel/debug/tracing/events/camera_common/enable
1
root@amoymn:/home/jetson# 

Wow, that’s unreasonable.
Did you reboot the system to try again?

still no tracing log output after reboot…
without csi tracing log, i can not analogy what problems cause SOF timeout!
I am stucking here…
Is there any other way to output tracing log?

In website “Jetson/l4t/Camera BringUp - eLinux.org

TX2

if you saw below message it could be the sensor output embedded data line but DT didn't declare embedded_metadata_height or it value is 0
arm-smmu 12000000.iommu: Unhandled context fault: iova=0x00000000, fsynr=0x200011, cb=19, sid=4(0x4 - VI), pgd=0, pud=0, pmd=0, pte=0

Steps to enable more debug messages
To enable logs from user-space for more details
sudo su
kill the process of argus_daemon/nvargus-daemon or nvcamera-daemon 
export enableCamPclLogs=5
export enableCamScfLogs=5
/usr/sbin/argus_daemon(nvargus-daemon)      option for argus
/usr/sbin/nvcamera-daemon   option for gst-launch
 
launch camera from another console
To enable trace for more information
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 1 > /sys/kernel/debug/tracing/events/camera_common/enable
echo > /sys/kernel/debug/tracing/trace
cat /sys/kernel/debug/tracing/trace

I didn’t find argus_daemon(nvargus-daemon) or nvcamera-daemon on my tx2 board!

Have a check the kernel message to confirm the NVCSI and VI driver is loaded correct.

demsg | grep -i 'nvcsi\|vi'

The messages as below:

jetson@amoymn:~$ dmesg | grep -i 'nvcsi\|vi'
[    0.000000] Linux version 4.9.201-tegra (chino@chino-ZHENGJIUZHE-REN7000P-28APR) (gcc version 7.3.1 20180425 [linaro-7.3-2018.05 revision d29120a424ecfbc167ef90065c0eeb7f91977701] (Linaro GCC 7.3-2018.05) ) #29 SMP PREEMPT Thu Jun 10 17:52:36 CST 2021
[    0.000000] OF: reserved mem: initialized node vpr-carveout, compatible id nvidia,vpr-carveout
[    0.000000] OF: reserved mem: initialized node ramoops_carveout, compatible id nvidia,ramoops
[    0.000000] Kernel command line: root=/dev/mmcblk0p1 rw rootwait rootfstype=ext4 console=ttyS0,115200n8 console=tty0 fbcon=map:0 net.ifnames=0 root=/dev/mmcblk0p1 rw rootwait rootfstype=ext4 console=ttyS0,115200n8 console=tty0 fbcon=map:0 net.ifnames=0  video=tegrafb no_console_suspend=1 earlycon=uart8250,mmio32,0x3100000 nvdumper_reserved=0x2772e0000 gpt rootfs.slot_suffix= usbcore.old_scheme_first=1 tegraid=18.1.2.0.0 maxcpus=6 boot.slot_suffix= boot.ratchetvalues=0.2031647.1 vpr_resize bl_prof_dataptr=0x10000@0x275840000 sdhci_tegra.en_boot_part_access=1 quiet root=/dev/mmcblk0p1 rw rootwait rootfstype=ext4 console=ttyS0,115200n8 console=tty0 fbcon=map:0 net.ifnames=0 isolcpus=1-2 
[    0.000000] log_buf_len individual max cpu contribution: 32768 bytes
[    0.000000] Virtual kernel memory layout:
[    0.001258] Console: colour dummy device 80x25
[    0.163020] tegra-id: opt_subrevision=1.
[    0.163037] Tegra Revision: A02p SKU: 0xdc CPU Process: 0 SoC Process: 0
[    0.163044] DTS File Name: arch/arm64/boot/dts/../../../../../../hardware/nvidia/platform/t18x/quill/kernel-dts/tegra186-quill-p3310-1000-c03-00-base.dts
[    0.382785] OS set in device tree is not L4T.
[    0.412869] DTS File Name: arch/arm64/boot/dts/../../../../../../hardware/nvidia/platform/t18x/quill/kernel-dts/tegra186-quill-p3310-1000-c03-00-base.dts
[    0.416600] iommu: Adding device 3460000.sdhci to group 0
[    0.417312] iommu: Adding device 3400000.sdhci to group 1
[    0.418402] iommu: Adding device 3507000.ahci-sata to group 2
[    0.418868] iommu: Adding device 3160000.i2c to group 3
[    0.419349] iommu: Adding device c240000.i2c to group 4
[    0.419696] iommu: Adding device 3180000.i2c to group 5
[    0.420064] iommu: Adding device 3190000.i2c to group 6
[    0.420525] iommu: Adding device 31b0000.i2c to group 7
[    0.420861] iommu: Adding device 31c0000.i2c to group 8
[    0.421218] iommu: Adding device c250000.i2c to group 9
[    0.421563] iommu: Adding device 31e0000.i2c to group 10
[    0.423244] iommu: Adding device 3210000.spi to group 11
[    0.423618] iommu: Adding device c260000.spi to group 12
[    0.423951] iommu: Adding device 3240000.spi to group 13
[    0.424745] iommu: Adding device 3100000.serial to group 14
[    0.425110] iommu: Adding device 3110000.serial to group 15
[    0.425444] iommu: Adding device c280000.serial to group 16
[    0.425780] iommu: Adding device 3130000.serial to group 17
[    0.427161] iommu: Adding device 2490000.ether_qos to group 18
[    0.428103] iommu: Adding device b000000.rtcpu to group 19
[    0.430351] iommu: Adding device 13e10000.host1x to group 20
[    0.430661] iommu: Adding device 13e10000.host1x:ctx0 to group 21
[    0.430960] iommu: Adding device 13e10000.host1x:ctx1 to group 22
[    0.431267] iommu: Adding device 13e10000.host1x:ctx2 to group 23
[    0.431563] iommu: Adding device 13e10000.host1x:ctx3 to group 24
[    0.431861] iommu: Adding device 13e10000.host1x:ctx4 to group 25
[    0.432164] iommu: Adding device 13e10000.host1x:ctx5 to group 26
[    0.432472] iommu: Adding device 13e10000.host1x:ctx6 to group 27
[    0.432773] iommu: Adding device 13e10000.host1x:ctx7 to group 28
[    0.433259] iommu: Adding device 150c0000.nvcsi to group 29
[    0.433914] iommu: Adding device 15700000.vi to group 30
[    0.434269] iommu: Adding device 15600000.isp to group 31
[    0.434724] iommu: Adding device 15210000.nvdisplay to group 32
[    0.435332] iommu: Adding device 15340000.vic to group 33
[    0.435552] iommu: Adding device 154c0000.nvenc to group 34
[    0.435767] iommu: Adding device 15480000.nvdec to group 35
[    0.436113] iommu: Adding device 15380000.nvjpg to group 36
[    0.436339] iommu: Adding device 15500000.tsec to group 37
[    0.436595] iommu: Adding device 15100000.tsecb to group 38
[    0.437296] iommu: Adding device 15810000.se to group 39
[    0.437556] iommu: Adding device 15820000.se to group 40
[    0.437770] iommu: Adding device 15830000.se to group 41
[    0.437984] iommu: Adding device 15840000.se to group 42
[    0.438856] iommu: Adding device smmu_test to group 43
[    0.440816] iommu: Adding device 3530000.xhci to group 44
[    0.441356] iommu: Adding device 3550000.xudc to group 45
[    0.442733] iommu: Adding device 17000000.gp10b to group 46
[    0.446023] iommu: Adding device d000000.bpmp to group 47
[    0.451795] iommu: Adding device 2600000.dma to group 48
[    0.453772] gpiochip_setup_dev: registered GPIOs 320 to 511 on device: gpiochip0 (tegra-gpio)
[    0.457767] gpiochip_setup_dev: registered GPIOs 256 to 319 on device: gpiochip1 (tegra-gpio-aon)
[    0.459350] iommu: Adding device 10003000.pcie-controller to group 49
[    0.459691] iommu: Adding device sound to group 50
[    0.460049] iommu: Adding device 3510000.hda to group 51
[    0.467493] iommu: Adding device c1a0000.aon to group 52
[    0.500812] usbcore: registered new device driver usb
[    0.504603] gpiochip_setup_dev: registered GPIOs 240 to 255 on device: gpiochip2 (tca9539)
[    0.506079] gpiochip_setup_dev: registered GPIOs 224 to 239 on device: gpiochip3 (tca9539)
[    0.552496] gpiochip_setup_dev: registered GPIOs 216 to 223 on device: gpiochip4 (max77620-gpio)
[    0.553234] Linux video capture interface: v2.00
[    0.562943] Bluetooth: HCI device and connection manager initialized
[    0.585674] camchar: rtcpu character device driver loaded
[    0.968761] iommu: Adding device aconnect@2a41000:adsp_audio to group 53
[    1.003092] iommu: Adding device 2993000.adsp to group 54
[    1.016757] misc tegra_camera_ctrl: tegra_camera_isomgr_register isp_iso_bw=4687500, vi_iso_bw=750000, max_bw=4687500
[    1.029415] falcon 15340000.vic: initialized
[    1.062431] Console: switching to colour frame buffer device 80x30
[    1.099214] tun: Universal TUN/TAP device driver, 1.6
[    1.099890] igbvf: Intel(R) Gigabit Virtual Function Network Driver - version 2.4.0-k
[    1.126901] tegra-xudc-new 3550000.xudc: device count: 1
[    1.154231] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.154236] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.155075] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[    1.155080] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.321069] tegra-xudc-new 3550000.xudc: device mode on: 0
[    1.321837] mousedev: PS/2 mouse device common for all mice
[    1.452970] rtc rtc1: alarm rtc device
[    1.463336] device-mapper: uevent: version 1.0.3
[    1.463646] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[    1.463926] CPU EMC frequency mapping table: from device tree
[    1.502550] tegra-ivc ivc-b000000.rtcpu:vinotify@12c0: vinotify: ver=0 grp=1 RX[64x128]=0x2200-0x4280 TX[64x128]=0x4280-0x6300
[    1.508349] tegra18x_actmon d230000.actmon: initialization Completed for the device mc_all
[    1.511844] trusty-virtio trusty:virtio: initializing
[    1.511955] trusty_ipc virtio0: vring0: va(pa)  ffffffc1e8f64000(0) qsz 32 notifyid 1
[    1.511962] trusty_ipc virtio0: vring1: va(pa)  ffffffc1e8f66000(0) qsz 32 notifyid 2
[    1.512031] trusty-virtio trusty:virtio: initializing done
[    1.512120] trusty_ipc virtio0: is online
[    1.522197] input: tegra-hda HDMI/DP,pcm=3 as /devices/3510000.hda/sound/card0/input0
[    1.522318] input: tegra-hda HDMI/DP,pcm=7 as /devices/3510000.hda/sound/card0/input1
[    1.655144] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    1.665083] nvcsi 150c0000.nvcsi: initialized
[    1.666488] tegra-vi4 15700000.vi: using default number of vi channels,15
[    1.669210] input: gpio-keys as /devices/gpio-keys/input/input2
[    1.670718] tegra-vi4 15700000.vi: initialized
[    1.671601] tegra-vi4 15700000.vi: subdev 150c0000.nvcsi--1 bound
[    1.737303] ALSA device list:
[    1.760345] Root device found: mmcblk0p1
[    1.936008] systemd[1]: systemd 237 running in system mode. (+PAM +AUDIT +SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD -IDN2 +IDN -PCRE2 default-hierarchy=hybrid)
[    2.051876] systemd[1]: File /lib/systemd/system/systemd-journald.service:36 configures an IP firewall (IPAddressDeny=any), but the local system does not support BPF/cgroup based firewalling.
[    2.302345] bcpu-throttle-alert cooling device registered.
[    2.305025] mcpu-throttle-alert cooling device registered.
[    2.305229] gpu-throttle-alert cooling device registered.
[    3.608777] device rndis0 entered promiscuous mode
[    3.625320] device usb0 entered promiscuous mode
[    4.193032] zram: Added device: zram0
[    4.197504] zram: Added device: zram1
[    4.199079] zram: Added device: zram2
[    4.199908] zram: Added device: zram3
[    4.202181] zram: Added device: zram4
[    4.209027] zram: Added device: zram5
[    4.217281] found wifi platform device bcmdhd_wlan
[    4.428907] wifi_platform_bus_enumerate device present 1
[    4.449216] wifi_platform_bus_enumerate device present 0

Also check dmesg | grep -i rtcpu

The messages as below:

jetson@amoymn:~$ dmesg | grep -i rtcpu
[    0.428103] iommu: Adding device b000000.rtcpu to group 19
[    0.585674] camchar: rtcpu character device driver loaded
[    1.499798] tegra186-cam-rtcpu b000000.rtcpu: Trace buffer configured at IOVA=0xbff00000
[    1.501996] tegra-ivc ivc-b000000.rtcpu: region 0: iova=0xbfef0000-0xbfefdb7f size=56192
[    1.502226] tegra-ivc ivc-b000000.rtcpu:echo@0: echo: ver=0 grp=1 RX[16x64]=0x1000-0x1480 TX[16x64]=0x1480-0x1900
[    1.502356] tegra-ivc ivc-b000000.rtcpu:i2c@480: i2c: ver=0 grp=1 RX[8x128]=0x1900-0x1d80 TX[8x128]=0x1d80-0x2200
[    1.502550] tegra-ivc ivc-b000000.rtcpu:vinotify@12c0: vinotify: ver=0 grp=1 RX[64x128]=0x2200-0x4280 TX[64x128]=0x4280-0x6300
[    1.503241] tegra-ivc ivc-b000000.rtcpu:mods@32c0: mods: ver=0 grp=1 RX[1x64]=0x6300-0x63c0 TX[1x64]=0x63c0-0x6480
[    1.503333] tegra-ivc ivc-b000000.rtcpu:ivccontrol@52c0: ivccontrol: ver=0 grp=1 RX[16x320]=0x6480-0x7900 TX[16x320]=0x7900-0x8d80
[    1.503385] tegra-ivc ivc-b000000.rtcpu:ivccapture@72c0: ivccapture: ver=0 grp=1 RX[16x64]=0x8d80-0x9200 TX[16x64]=0x9200-0x9680
[    1.503456] tegra-ivc ivc-b000000.rtcpu:dbg@7c00: dbg: ver=0 grp=1 RX[1x384]=0x9680-0x9880 TX[1x384]=0x9880-0x9a80
[    1.503552] tegra-ivc ivc-b000000.rtcpu:dbg@7e00: dbg: ver=0 grp=1 RX[1x8192]=0x9a80-0xbb00 TX[1x8192]=0xbb00-0xdb80
[    1.503887] tegra186-cam-rtcpu b000000.rtcpu: using cam RTCPU IRQ (52)
[    1.503890] tegra186-cam-rtcpu b000000.rtcpu: tegra_camrtc_mon_create is successful
[    1.504425] tegra186-cam-rtcpu b000000.rtcpu: firmware version cpu=sce cmd=5 sha1=3ecb1dca25fa98771f988f238c025334776c9a96
jetson@amoymn:~$ 

Everything looks fine don’t know why !!
How ever for kernel error tell the Packet Payload CRC error, apply the patch from below link to try.

[ 1492.440449] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC0 = 0x00000004

In R32.1, the file is nvidia/drivers/media/platform/tegra/camera/csi/csi4_fops.c
and I modified as below:

static void csi4_stream_init(struct tegra_csi_channel *chan, int csi_port)
{
        struct tegra_csi_device *csi = chan->csi;
        bool cil_a = (csi_port & 0x1) ? false : true;

        dev_dbg(csi->dev, "%s\n", __func__);

        if (cil_a) {
                csi4_stream_write(chan, csi_port, CILA_INTR_STATUS, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILA_ERR_INTR_STATUS, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILA_INTR_MASK, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILA_ERR_INTR_MASK, 0xffffffff);
        }

        if (!cil_a || (chan->numlanes > 2)) {
                csi4_stream_write(chan, csi_port, CILB_INTR_STATUS, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILB_ERR_INTR_STATUS, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILB_INTR_MASK, 0xffffffff);
                csi4_stream_write(chan, csi_port, CILB_ERR_INTR_MASK, 0xffffffff);
        }

        csi4_stream_write(chan, csi_port, INTR_STATUS, 0x3ffff);
        csi4_stream_write(chan, csi_port, ERR_INTR_STATUS, 0x7ffff);
        csi4_stream_write(chan, csi_port, ERROR_STATUS2VI_MASK, 0x0);
        //csi4_stream_write(chan, csi_port, INTR_MASK, 0x0);
        //csi4_stream_write(chan, csi_port, ERR_INTR_MASK, 0x0);
        csi4_stream_write(chan, csi_port, INTR_MASK, PH_ECC_MULTI_BIT_ERR |
                        PD_CRC_ERR_VC0 | PH_ECC_SINGLE_BIT_ERR_VC0);
        csi4_stream_write(chan, csi_port, ERR_INTR_MASK, PH_ECC_MULTI_BIT_ERR |
                        PD_CRC_ERR_VC0 | PH_ECC_SINGLE_BIT_ERR_VC0);
        csi4_stream_write(chan, csi_port, ERROR_STATUS2VI_MASK,
                        CFG_ERR_STATUS2VI_MASK_VC0 |
                        CFG_ERR_STATUS2VI_MASK_VC1 |
                        CFG_ERR_STATUS2VI_MASK_VC2 |
                        CFG_ERR_STATUS2VI_MASK_VC3);
}

Is that right?

Yes, that is correct.