Hi again, following up with trying to get the second IMX477 running on lanes CSI2 D0 and D1.
Firstly I’ve confirmed the sensor isn’t faulty by swapping the sensors and observing the imager on CSI2 persists. Second, I realized that running with the port-index values that Shane recommended did change the the error messages I’m receiving for this CSI port.
First, running sudo bash -c "echo 'file camera_common.c +p' > /sys/kernel/debug/dynamic_debug/control" and then following dmesg gets me:
[ 833.286349] imx477 9-001a: camera_common_mclk_enable: enable MCLK with 24000000 Hz
[ 833.286391] imx477 9-001a: camera_common_dpd_disable: csi 2
[ 833.627869] [RCE] vi5_hwinit: firmware CL2018101701 protocol version 2.2
[ 833.733390] tegra194-vi5 15c10000.vi: corr_err: discarding frame 1, flags: 112, err_data 39845986
[ 833.766745] tegra194-vi5 15c10000.vi: corr_err: discarding frame 2, flags: 112, err_data 39845986
[ 833.800056] tegra194-vi5 15c10000.vi: corr_err: discarding frame 3, flags: 112, err_data 39845986
[ 833.833380] tegra194-vi5 15c10000.vi: corr_err: discarding frame 4, flags: 112, err_data 39845986
[ 856.355334] imx477 9-001a: camera_common_dpd_enable: csi 2
[ 856.355343] imx477 9-001a: camera_common_mclk_disable: disable MCLK
Notably, the no reply from camera processor is gone, and after those first four frames, the corr_err message stops and does NOT output continuously.
Next, going back and enabling the same debug trace output with:
sudo bash -c "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”
and then sudo cat /sys/kernel/debug/tracing/trace gives:
kworker/1:0-8634 [001] .... 983.156616: rtcpu_nvcsi_intr: tstamp:31128915432 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006 [9465/9485]
kworker/1:0-8634 [001] .... 983.156616: rtcpu_nvcsi_intr: tstamp:31128915432 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156616: rtcpu_nvcsi_intr: tstamp:31128916044 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156617: rtcpu_nvcsi_intr: tstamp:31128916044 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156617: rtcpu_nvcsi_intr: tstamp:31128916656 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156617: rtcpu_nvcsi_intr: tstamp:31128916656 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156617: rtcpu_nvcsi_intr: tstamp:31128917270 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156617: rtcpu_nvcsi_intr: tstamp:31128917270 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156618: rtcpu_nvcsi_intr: tstamp:31128917884 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156618: rtcpu_nvcsi_intr: tstamp:31128917884 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156618: rtcpu_nvcsi_intr: tstamp:31128918495 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156618: rtcpu_nvcsi_intr: tstamp:31128918495 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:0-8634 [001] .... 983.156618: rtcpu_nvcsi_intr: tstamp:31128918495 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156619: rtcpu_nvcsi_intr: tstamp:31128918495 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:0-8634 [001] .... 983.156619: rtcpu_nvcsi_intr: tstamp:31128919461 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156619: rtcpu_nvcsi_intr: tstamp:31128919461 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156619: rtcpu_nvcsi_intr: tstamp:31128920073 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156619: rtcpu_nvcsi_intr: tstamp:31128920073 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156620: rtcpu_nvcsi_intr: tstamp:31128920689 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156620: rtcpu_nvcsi_intr: tstamp:31128920689 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:0-8634 [001] .... 983.156621: rtcpu_nvcsi_intr: tstamp:31128920689 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156621: rtcpu_nvcsi_intr: tstamp:31128920689 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:0-8634 [001] .... 983.156621: rtcpu_nvcsi_intr: tstamp:31128921656 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156621: rtcpu_nvcsi_intr: tstamp:31128921656 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156622: rtcpu_nvcsi_intr: tstamp:31128922270 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156622: rtcpu_nvcsi_intr: tstamp:31128922270 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156622: rtcpu_nvcsi_intr: tstamp:31128922884 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156622: rtcpu_nvcsi_intr: tstamp:31128922884 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156622: rtcpu_nvcsi_intr: tstamp:31128923495 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156623: rtcpu_nvcsi_intr: tstamp:31128923495 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156623: rtcpu_nvcsi_intr: tstamp:31128924107 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156623: rtcpu_nvcsi_intr: tstamp:31128924107 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156623: rtcpu_nvcsi_intr: tstamp:31128924719 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156623: rtcpu_nvcsi_intr: tstamp:31128924719 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156624: rtcpu_nvcsi_intr: tstamp:31128925331 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156624: rtcpu_nvcsi_intr: tstamp:31128925331 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156624: rtcpu_nvcsi_intr: tstamp:31128925943 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156624: rtcpu_nvcsi_intr: tstamp:31128925943 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156625: rtcpu_nvcsi_intr: tstamp:31128926597 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:0-8634 [001] .... 983.156625: rtcpu_nvcsi_intr: tstamp:31128926597 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
Based on @ShaneCCC’s recommendation in various posts and the eLinux wiki I went ahead and tried this again while boosting clocks. Reboot, run the previous command to enable trace logs, and now boost clocks to max:
sudo bash -c "echo 1 > /sys/kernel/debug/bpmp/debug/clk/vi/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/isp/mrq_rate_locked
echo 1 > /sys/kernel/debug/bpmp/debug/clk/nvcsi/mrq_rate_locked
cat /sys/kernel/debug/bpmp/debug/clk/vi/max_rate |tee /sys/kernel/debug/bpmp/debug/clk/vi/rate
cat /sys/kernel/debug/bpmp/debug/clk/isp/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/isp/rate
cat /sys/kernel/debug/bpmp/debug/clk/nvcsi/max_rate | tee /sys/kernel/debug/bpmp/debug/clk/nvcsi/rate"
This output adds a few more new messages:
sudo cat /sys/kernel/debug/tracing/trace:
kworker/1:3-2098 [001] .... 77.454435: rtcpu_nvcsi_intr: tstamp:2826656033 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454436: rtcpu_nvcsi_intr: tstamp:2826656033 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454437: rtcpu_nvcsi_intr: tstamp:2826656033 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454438: rtcpu_nvcsi_intr: tstamp:2826656033 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454438: rtcpu_nvcsi_intr: tstamp:2826656033 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454439: rtcpu_nvcsi_intr: tstamp:2826657331 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454440: rtcpu_nvcsi_intr: tstamp:2826657331 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454441: rtcpu_nvcsi_intr: tstamp:2826657331 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454441: rtcpu_nvcsi_intr: tstamp:2826657331 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454442: rtcpu_nvcsi_intr: tstamp:2826657331 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454443: rtcpu_nvcsi_intr: tstamp:2826657331 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454444: rtcpu_nvcsi_intr: tstamp:2826658641 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454444: rtcpu_nvcsi_intr: tstamp:2826658641 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454445: rtcpu_nvcsi_intr: tstamp:2826658641 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454446: rtcpu_nvcsi_intr: tstamp:2826658641 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454447: rtcpu_nvcsi_intr: tstamp:2826658641 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454447: rtcpu_nvcsi_intr: tstamp:2826658641 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454448: rtcpu_nvcsi_intr: tstamp:2826659932 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454449: rtcpu_nvcsi_intr: tstamp:2826659932 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454450: rtcpu_nvcsi_intr: tstamp:2826659932 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454450: rtcpu_nvcsi_intr: tstamp:2826659932 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454451: rtcpu_nvcsi_intr: tstamp:2826659932 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454452: rtcpu_nvcsi_intr: tstamp:2826661060 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454453: rtcpu_nvcsi_intr: tstamp:2826661060 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454453: rtcpu_nvcsi_intr: tstamp:2826661060 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454454: rtcpu_nvcsi_intr: tstamp:2826661060 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454455: rtcpu_nvcsi_intr: tstamp:2826661060 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454456: rtcpu_nvcsi_intr: tstamp:2826661060 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454456: rtcpu_nvcsi_intr: tstamp:2826662356 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454457: rtcpu_nvcsi_intr: tstamp:2826662356 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454458: rtcpu_nvcsi_intr: tstamp:2826662356 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454459: rtcpu_nvcsi_intr: tstamp:2826662356 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001
kworker/1:3-2098 [001] .... 77.454459: rtcpu_nvcsi_intr: tstamp:2826662356 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454460: rtcpu_nvcsi_intr: tstamp:2826662356 class:CORRECTABLE_ERR type:PHY_INTR phy:1 cil:0 st:0 vc:0 status:0x00000002
kworker/1:3-2098 [001] .... 77.454461: rtcpu_nvcsi_intr: tstamp:2826663651 class:GLOBAL type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006
kworker/1:3-2098 [001] .... 77.454462: rtcpu_nvcsi_intr: tstamp:2826663651 class:GLOBAL
Between some Shane’s past posts[3][4] and the Xavier technical reference, it seems like these are the main takeways from this output:
-
rtcpu_nvcsi_intr: tstamp:31128915432 class:CORRECTABLE_ERR type:STREAM_VC phy:0 cil:0 st:2 vc:0 status:0x00000006-
STREAM_VCis register NVCSI_STREAM_0_INTR_STATUS_VC0_0 - Getting error bits 2 and 1 named
intr_stat_pd_crc_err_vc0andintr_stat_ph_ecc_single_bit_err_vc0
-
-
rtcpu_nvcsi_intr: tstamp:2826656033 class:GLOBAL type:PHY_INTR0 phy:1 cil:0 st:0 vc:0 status:0x00000002-
PHY_INTROis register NVCSI_PHY_0_CILA_INTR_0_STATUS_CILA_0 - Bit 1 is intr_cil_data_lane_sot_sb_err0_a, which from Shane’s comments I assume
sbmeans single bit?
-
-
rtcpu_nvcsi_intr: tstamp:2826661060 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:2 vc:0 status:0x00000001-
STREAM_NOVCis register NVCSI_STREAM_0_INTR_STATUS_NOVC_0 - Bit 0 is intr_stat_ph_ecc_multi_bit_err
-
Clearly the SoC is unhappy about CRC/ECC issues. Any guidance for debugging this would be much appreciated.
Is the next step to mask these error bits as was recommended in Problem with capturing images by Video4Linux - #13 by ShaneCCC ? I’d like to understand why the integrity checks are failing…
Thanks again.
[3] How to interpret CSI debug information - #3 by ShaneCCC
[4] GMSL camera return “STREAM_NOVC" error and no image - #3 by ShaneCCC