MIPI driver creation issue

We are here creating a driver for TC358748, we are stuck by some issue, looking for help…

Issue:

  1. Test
    v4l2-ctl -d /dev/video0 --stream-mmap --stream-count=1 --stream-to=test.raw --set-ctrl bypass_mode=0 --verbose
    result from dmesg: tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! err = -11
    result from test.raw: all 0x00

  2. with kernel trace, which are enabled with these:
    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
    cat /sys/kernel/debug/tracing/trace
    we get:
    kworker/4:1-115 [004] …1 262.936789: rtos_queue_peek_from_isr_failed: tstamp:8518276173 queue:0x0b4a3c58
    kworker/4:1-115 [004] …1 263.092761: rtos_queue_peek_from_isr_failed: tstamp:8523276679 queue:0x0b4a3c58
    kworker/4:1-115 [004] …1 263.248759: rtos_queue_peek_from_isr_failed: tstamp:8528277176 queue:0x0b4a3c58
    kworker/4:1-115 [004] …1 263.404767: rtos_queue_peek_from_isr_failed: tstamp:8533277691 queue:0x0b4a3c58
    kworker/4:1-115 [004] …1 263.456817: rtos_queue_peek_from_isr_failed: tstamp:8534410698 queue:0x0b4a3c58
    (hundreds lines more…)

What we have done:

  1. TC358748 is configured for using 2 lanes (csi0), we are make use of color bar generation function for driver debugging.
  2. dtsi file
  3. driver file (.c and .h)
    We create dtsi file and driver reference to ov5693 and tc358840

What we have get:

  1. Video device node shows (/dev/video0),
  2. probe function could be loaded when booting,
  3. there are some fails with v4l2-compilance, but seems like not major issues, just s_fmt not work complaint from system
  4. s_stream function could be called with v4l2 test,
  5. in s_stream function, bunch of i2c access function (both read and write) are called to setup registers map for TC358748, we had verify tx status with accessing some tx status register from this chip, the results looks fine.
  6. I have try to attach embedded_metadata_height in dtsi file, result does not change (without this setting, set with 1, 2, 3, 4)

Appreciate for any kind of helps…

@adonishong
Form the trace log shows CSI/VI didn’t receive any validate package from the MIPI bus. Try to probe the to check the TC35xxx is output data to the bus.

Does this means this situation should not related to pixel format and resolution setting from host side(tc35xxxxx driver for tx2)? And does this means, I should look into Clock Controller setting from CSI-TX side?

after adjusting tx side parameter, now, I could get these type of error

kworker/5:2-217 [005] …1 1396.437946: rtos_queue_peek_from_isr_failed: tstamp:43941730130 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1396.437960: rtcpu_vinotify_handle_msg: tstamp:43941771695 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:992097605 data:0x00000420
kworker/5:2-217 [005] …1 1396.437969: rtcpu_vinotify_handle_msg: tstamp:43941772757 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:992098112 data:0x00000400
kworker/5:2-217 [005] …1 1396.437980: rtcpu_vinotify_handle_msg: tstamp:43942160871 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:992486780 data:0x00000420
kworker/5:2-217 [005] …1 1396.437989: rtcpu_vinotify_handle_msg: tstamp:43942161910 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:992487287 data:0x00000400
kworker/5:2-217 [005] …1 1396.491422: rtcpu_vinotify_handle_msg: tstamp:43942550044 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:992875956 data:0x00000420
kworker/5:2-217 [005] …1 1396.491430: rtcpu_vinotify_handle_msg: tstamp:43942551087 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:992876463 data:0x00000400
kworker/5:2-217 [005] …1 1396.491433: rtcpu_vinotify_handle_msg: tstamp:43942939220 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:993265131 data:0x00000420
kworker/5:2-217 [005] …1 1396.491435: rtcpu_vinotify_handle_msg: tstamp:43942940260 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:993265639 data:0x00000400
kworker/5:2-217 [005] …1 1396.491438: rtcpu_vinotify_handle_msg: tstamp:43943328397 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:993654307 data:0x00000420
kworker/5:2-217 [005] …1 1396.491440: rtcpu_vinotify_handle_msg: tstamp:43943329437 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:993654814 data:0x00000400
kworker/5:2-217 [005] …1 1396.491443: rtcpu_vinotify_handle_msg: tstamp:43943717546 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:994043482 data:0x00000420
kworker/5:2-217 [005] …1 1396.491445: rtcpu_vinotify_handle_msg: tstamp:43943718615 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:994043989 data:0x00000400
kworker/5:2-217 [005] …1 1396.542003: rtcpu_vinotify_handle_msg: tstamp:43944106074 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:994432658 data:0x00000420
kworker/5:2-217 [005] …1 1396.542052: rtcpu_vinotify_handle_msg: tstamp:43944106468 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:994433165 data:0x00000400
kworker/5:2-217 [005] …1 1396.542066: rtcpu_vinotify_handle_msg: tstamp:43944495255 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:994821833 data:0x00000420
kworker/5:2-217 [005] …1 1396.542078: rtcpu_vinotify_handle_msg: tstamp:43944495670 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:994822340 data:0x00000400
kworker/5:2-217 [005] …1 1396.542088: rtcpu_vinotify_handle_msg: tstamp:43944885099 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:995211008 data:0x00000420
kworker/5:2-217 [005] …1 1396.542098: rtcpu_vinotify_handle_msg: tstamp:43944886137 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:995211515 data:0x00000400
kworker/5:2-217 [005] …1 1396.542108: rtcpu_vinotify_handle_msg: tstamp:43945274271 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:995600184 data:0x00000420
kworker/5:2-217 [005] …1 1396.542117: rtcpu_vinotify_handle_msg: tstamp:43945275326 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:995600692 data:0x00000400
kworker/5:2-217 [005] …1 1396.593814: rtcpu_vinotify_handle_msg: tstamp:43945663448 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:995989360 data:0x00000420
kworker/5:2-217 [005] …1 1396.593823: rtcpu_vinotify_handle_msg: tstamp:43945664486 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:995989867 data:0x00000400
kworker/5:2-217 [005] …1 1396.593826: rtcpu_vinotify_handle_msg: tstamp:43946053010 tag:CSIMUX_FRAME channel:0x00 frame:0 vi_tstamp:996378535 data:0x00000420
kworker/5:2-217 [005] …1 1396.593829: rtcpu_vinotify_handle_msg: tstamp:43946054137 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:996378586 data:0x00000001
kworker/5:2-217 [005] …1 1396.593832: rtcpu_vinotify_handle_msg: tstamp:43946055558 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:996378598 data:0x00000000
kworker/5:2-217 [005] …1 1396.593835: rtcpu_vinotify_handle_msg: tstamp:43946056572 tag:CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:996378935 data:0x00000100
kworker/5:2-217 [005] …1 1396.593838: rtcpu_vinotify_handle_msg: tstamp:43946058177 tag:CSIMUX_FRAME channel:0xac frame:0 vi_tstamp:996379042 data:0x00000400
kworker/5:2-217 [005] …1 1396.593841: rtcpu_vinotify_handle_msg: tstamp:43946059212 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:996384179 data:0x08000000
kworker/5:2-217 [005] …1 1396.593844: rtcpu_vinotify_handle_msg: tstamp:43946060227 tag:CHANSEL_FAULT_FE channel:0x01 frame:0 vi_tstamp:996384232 data:0x00000001
kworker/5:2-217 [005] …1 1396.593847: rtcpu_vinotify_handle_msg: tstamp:43946061263 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:996384235 data:0x00000000
kworker/5:2-217 [005] …1 1396.593854: rtos_queue_peek_from_isr_failed: tstamp:43946730632 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1396.749792: rtos_queue_peek_from_isr_failed: tstamp:43951730683 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1396.905834: rtos_queue_peek_from_isr_failed: tstamp:43956731200 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.113843: rtos_queue_peek_from_isr_failed: tstamp:43961732151 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.269837: rtos_queue_peek_from_isr_failed: tstamp:43966732658 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.425849: rtos_queue_peek_from_isr_failed: tstamp:43971733164 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.581982: rtos_queue_peek_from_isr_failed: tstamp:43976733673 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.737821: rtos_queue_peek_from_isr_failed: tstamp:43981733734 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1397.893861: rtos_queue_peek_from_isr_failed: tstamp:43986734686 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1398.049934: rtos_queue_peek_from_isr_failed: tstamp:43991734740 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1398.205869: rtos_queue_peek_from_isr_failed: tstamp:43996735840 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1398.361868: rtos_queue_peek_from_isr_failed: tstamp:44001736212 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1398.517882: rtos_queue_peek_from_isr_failed: tstamp:44006736719 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1398.622016: rtos_queue_peek_from_isr_failed: tstamp:44008932812 queue:0x0b4a3c58
kworker/5:2-217 [005] …1 1399.611112: rtos_queue_peek_from_isr_failed: tstamp:44040041724 queue:0x0b4a3c58

Below message show the PIXEL_SHORT_LINE that could be the width is’t as expect.

kworker/5:2-217 [005] …1 1396.593844: rtcpu_vinotify_handle_msg: tstamp:43946060227 tag:CHANSEL_FAULT_FE channel:0x01 frame:0 vi_tstamp:996384232 data:0x00000001

thanks for your response, and happy new year ^_^

During this holiday, we have made colorbar test mode from tc358748, image size is 384 x 228 with raw10 (we use MEDIA_BUS_FMT_SBGGR10_1X10 for testing purpose), we could get the data from tc358748 correctly, with v4l2-ctrl, and trace shows bunch of these messages

kworker/0:3-894   [000] ...1  1940.060976: rtcpu_vinotify_handle_msg: tstamp:60929085318 tag:CHANSEL_PXL_EOF channel:0x00 frame:0 vi_tstamp:799542262 data:0x011f0002
     kworker/0:3-894   [000] ...1  1940.060979: rtcpu_vinotify_handle_msg: tstamp:60929087621 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:799544506 data:0x00000000
     kworker/0:3-894   [000] ...1  1940.113052: rtcpu_vinotify_handle_msg: tstamp:60929458323 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:799915598 data:0x00000001
     kworker/0:3-894   [000] ...1  1940.113093: rtcpu_vinotify_handle_msg: tstamp:60929458571 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:799915615 data:0x00000000
     kworker/0:3-894   [000] ...1  1940.113103: rtcpu_vinotify_handle_msg: tstamp:60929464887 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:799922297 data:0x08000000

according to parker_trm, system is happy with image data from tc358748

Now, we are moving to tc358748 parallel data capture config, we met new issues
Here are the dmesg info

[ 2185.424599] tegra-vi4 15700000.vi: vi4_power_on:vi4 power on is called with tc358748
[ 2185.434245] nvcsi 150c0000.nvcsi: tegra_csi_power set csi power 1 with tc358748
[ 2185.441706] nvcsi 150c0000.nvcsi: tegra_csi_s_power set csi subdevice power 1 with tc358748
[ 2185.450120] tc358748 0-000e: camera_common_mclk_enable: enable MCLK with 24000000 Hz
[ 2185.457924] tc358748 0-000e: camera_common_dpd_disable: csi 0
[ 2185.463724] tc358748 0-000e: tc358748_power_on: power on
[ 2185.469393] tc358748 0-000e: tc358748_s_ctrl: going to set ctrl
[ 2185.475378] tc358748 0-000e: tc358748_s_ctrl: setting config height 288
[ 2185.482038] tc358748 0-000e: tc358748_s_ctrl: going to set ctrl
[ 2185.487977] tc358748 0-000e: tc358748_s_ctrl: setting config write mode 4
[ 2185.495518] video4linux video0: vi4_channel_start_streaming:vi4 start streaming with tc358748
[ 2185.504091] tc358748 0-000e: camera_common_g_fmt++
[ 2185.508919] video4linux video0: vi4_channel_start_streaming:height and width from s_data 384 288
[ 2185.521085] tegra-vi4 15700000.vi: Create Surface with imgW=384, imgH=288, memFmt=32
[ 2185.531901] tegra-vi4 15700000.vi: WAR:Calculation not precise.Ignore BW request failure
[ 2185.540324] nvcsi 150c0000.nvcsi: tegra_csi_s_stream going to set streaming 1 with tc358748
[ 2185.550771] nvcsi 150c0000.nvcsi: csi port:0
[ 2185.555062] nvcsi 150c0000.nvcsi: csi4_mipi_cal mipi calibrated suceessfully
[ 2186.059574] tegra_mipi_cal 3990000.mipical: Mipi cal timeout,val:107861, lanes:300000
[ 2186.067602] tegra_mipi_cal 3990000.mipical: MIPI_CAL_CTRL                  0x04 0x2a000010
[ 2186.076031] tegra_mipi_cal 3990000.mipical: CIL_MIPI_CAL_STATUS            0x0c 0x00107861
[ 2186.084702] tegra_mipi_cal 3990000.mipical: CIL_MIPI_CAL_STATUS_2          0x10 0x00000000
[ 2186.093185] tegra_mipi_cal 3990000.mipical: CILA_MIPI_CAL_CONFIG           0x18 0x00200000
[ 2186.101633] tegra_mipi_cal 3990000.mipical: CILB_MIPI_CAL_CONFIG           0x1c 0x00200000
[ 2186.110113] tegra_mipi_cal 3990000.mipical: CILC_MIPI_CAL_CONFIG           0x20 0x00000000
[ 2186.118464] tegra_mipi_cal 3990000.mipical: CILD_MIPI_CAL_CONFIG           0x24 0x00000000
[ 2186.126820] tegra_mipi_cal 3990000.mipical: CILE_MIPI_CAL_CONFIG           0x28 0x00000000
[ 2186.135168] tegra_mipi_cal 3990000.mipical: CILF_MIPI_CAL_CONFIG           0x2c 0x00000000
[ 2186.143511] tegra_mipi_cal 3990000.mipical: DSIA_MIPI_CAL_CONFIG           0x3c 0x00000200
[ 2186.151816] tegra_mipi_cal 3990000.mipical: DSIB_MIPI_CAL_CONFIG           0x40 0x00000200
[ 2186.160126] tegra_mipi_cal 3990000.mipical: DSIC_MIPI_CAL_CONFIG           0x44 0x00000200
[ 2186.168432] tegra_mipi_cal 3990000.mipical: DSID_MIPI_CAL_CONFIG           0x48 0x00000200
[ 2186.176741] tegra_mipi_cal 3990000.mipical: MIPI_BIAS_PAD_CFG0             0x5c 0x00000000
[ 2186.185051] tegra_mipi_cal 3990000.mipical: MIPI_BIAS_PAD_CFG1             0x60 0x00000000
[ 2186.193379] tegra_mipi_cal 3990000.mipical: MIPI_BIAS_PAD_CFG2             0x64 0x00010010
[ 2186.201736] tegra_mipi_cal 3990000.mipical: DSIA_MIPI_CAL_CONFIG_2         0x68 0x00000002
[ 2186.210062] tegra_mipi_cal 3990000.mipical: DSIB_MIPI_CAL_CONFIG_2         0x6c 0x00000002
[ 2186.218363] tegra_mipi_cal 3990000.mipical: DSIC_MIPI_CAL_CONFIG_2         0x74 0x00000002
[ 2186.226668] tegra_mipi_cal 3990000.mipical: DSID_MIPI_CAL_CONFIG_2         0x78 0x00000002
[ 2186.234965] nvcsi 150c0000.nvcsi: tegra_csi_start_streaming going to start streaming 0 with tc358748
[ 2186.244111] nvcsi 150c0000.nvcsi: csi4_start_streaming ports index=0, lanes=1
[ 2186.251269] nvcsi 150c0000.nvcsi: csi4_stream_init
[ 2186.256095] nvcsi 150c0000.nvcsi: csi4_stream_config
[ 2186.261085] nvcsi 150c0000.nvcsi: csi4_stream_config (0) read VC0_DPCM_CTRL = 00000000
[ 2186.269015] nvcsi 150c0000.nvcsi: csi4_phy_config port 0 lanes 1 status 1
[ 2186.275816] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000000

[ 2186.532670] tegra-vi4 15700000.vi: Status:  4 channel:00 frame:0000
[ 2186.538983] tegra-vi4 15700000.vi:          timestamp sof 2196202530272 eof 2196211840480 data 0x01200040
[ 2186.548606] tegra-vi4 15700000.vi:          capture_id 1170 stream  0 vchan  0
[ 2186.556169] video4linux video0: vi4_channel_stop_streaming:vi2 stop streaming with tc358748
[ 2187.520157] tegra-vi4 15700000.vi: PXL_SOF syncpt timeout! 8748 mod err = -11
[ 2188.527859] tegra-vi4 15700000.vi: ATOMP_FE syncpt timeout!

[ 2188.739897] nvcsi 150c0000.nvcsi: tegra_csi_s_stream going to set streaming 0 with tc358748
[ 2188.748414] nvcsi 150c0000.nvcsi: tegra_csi_stop_streaming going to stop streaming 0 with tc358748
[ 2188.757372] nvcsi 150c0000.nvcsi: csi4_stop_streaming ports index=0, lanes=1
[ 2188.764433] nvcsi 150c0000.nvcsi: csi4_phy_config port 0 lanes 1 status 0
[ 2188.771221] nvcsi 150c0000.nvcsi: NVCSI_CIL_CONFIG = 00000001
[ 2188.776971] nvcsi 150c0000.nvcsi: csi4_stream_check_status
[ 2188.782460] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERROR_STATUS2VI_VC2 = 0x00000008
[ 2188.791237] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) INTR_STATUS 0x00000800
[ 2188.800120] nvcsi 150c0000.nvcsi: csi4_stream_check_status (0) ERR_INTR_STATUS 0x00000800
[ 2188.808494] nvcsi 150c0000.nvcsi: csi4_cil_check_status 277
[ 2188.831413] tegra-vi4 15700000.vi: WAR:Calculation not precise.Ignore BW request failure
[ 2188.848477] tegra-vi4 15700000.vi: vi4_power_off:vi2 power off is called with tc358748
[ 2188.856419] tc358748 0-000e: tc358748_power_off: power off
[ 2188.861962] tc358748 0-000e: camera_common_dpd_enable: csi 0
[ 2188.867648] tc358748 0-000e: camera_common_mclk_disable: disable MCLK
[ 2188.874417] nvcsi 150c0000.nvcsi: tegra_csi_power set csi power 0 with tc358748
[ 2188.881744] nvcsi 150c0000.nvcsi: tegra_csi_s_power set csi subdevice power 0 with tc358748

Here are the trace info:

kworker/0:3-894   [000] ...1  2775.987369: rtos_queue_peek_from_isr_failed: tstamp:87051644203 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2775.987373: rtcpu_start: tstamp:87051646134
     kworker/0:3-894   [000] ...1  2776.143488: rtos_queue_peek_from_isr_failed: tstamp:87056645558 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.299390: rtos_queue_peek_from_isr_failed: tstamp:87061645617 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.455392: rtos_queue_peek_from_isr_failed: tstamp:87066646107 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.623483: rtos_queue_peek_from_isr_failed: tstamp:87071646595 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.734449: rtcpu_vinotify_handle_msg: tstamp:87075233333 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:1175886999 data:0x00000001
     kworker/0:3-894   [000] ...1  2776.783370: rtos_queue_peek_from_isr_failed: tstamp:87076647085 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.939432: rtos_queue_peek_from_isr_failed: tstamp:87081647590 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2776.991402: rtcpu_vinotify_handle_msg: tstamp:87082681482 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:1183335009 data:0x00000001
     kworker/0:3-894   [000] ...1  2776.991406: rtcpu_vinotify_handle_msg: tstamp:87082681628 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:1183335027 data:0x00000000
     kworker/0:3-894   [000] ...1  2776.991409: rtcpu_vinotify_handle_msg: tstamp:87082685023 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:1183338691 data:0x08000000
     kworker/0:3-894   [000] ...1  2776.991411: rtcpu_vinotify_handle_msg: tstamp:87082966908 tag:CHANSEL_PXL_EOF channel:0x00 frame:0 vi_tstamp:1183620441 data:0x011f0002
     kworker/0:3-894   [000] ...1  2776.991414: rtcpu_vinotify_handle_msg: tstamp:87082967006 tag:CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:1183620489 data:0x01200040
     kworker/0:3-894   [000] ...1  2776.991416: rtcpu_vinotify_handle_msg: tstamp:87082967508 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:1183621214 data:0x08000000
     kworker/0:3-894   [000] ...1  2776.991418: rtcpu_vinotify_handle_msg: tstamp:87082971891 tag:CHANSEL_FAULT_FE channel:0x01 frame:0 vi_tstamp:1183625384 data:0x00000001
     kworker/0:3-894   [000] ...1  2776.991421: rtcpu_vinotify_handle_msg: tstamp:87082972018 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:1183625387 data:0x00000000
     kworker/0:3-894   [000] ...1  2777.095406: rtos_queue_peek_from_isr_failed: tstamp:87086648103 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2777.303400: rtos_queue_peek_from_isr_failed: tstamp:87091648603 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2777.459423: rtos_queue_peek_from_isr_failed: tstamp:87096649120 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2777.615401: rtos_queue_peek_from_isr_failed: tstamp:87101649619 queue:0x0b4a3c58

With colorbar test, if I set active_h smaller than correct value, I will get almost same error, especially this one:
CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:423072523 data:0x011f0040
Image config is also 384 x 288 with raw 10;
So, I tried adjust active_h, with values <= 288; I get same trace result. When I set active_h > 288, I get this

kworker/0:3-894   [000] ...1  2825.741924: rtos_queue_peek_from_isr_failed: tstamp:88605594035 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2825.843467: rtcpu_vinotify_handle_msg: tstamp:88609415987 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:2710069644 data:0x00000001
     kworker/0:3-894   [000] ...1  2825.894928: rtos_queue_peek_from_isr_failed: tstamp:88610594492 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2826.050928: rtos_queue_peek_from_isr_failed: tstamp:88615594997 queue:0x0b4a3c58
          <idle>-0     [000] d.h1  2826.078905: arm_smmu_context_fault: Unhandled context fault: iova=0x5a5b6000, fsynr=0x13, cb=19, sid=4(0x4 - VI), pgd=26c2f9003 pud=26c2f9003, pmd=26c2fa003, pte=0
          <idle>-0     [000] dnH1  2826.079000: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  2826.079048: log_fault.part.1: (255) csw_viw: MC request violates VPR requirements
          <idle>-0     [000] dnH1  2826.079051: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079066: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079070: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  2826.079071: log_fault.part.1:   status = 0x00337072; addr = 0x3ffffffc0
          <idle>-0     [000] dnH1  2826.079076: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079081: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  2826.079085: log_fault.part.1:   secure: yes, access-type: write
          <idle>-0     [000] dnH1  2826.079106: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079111: tegra_mcerr_hard_irq: MCERR detected.

          <idle>-0     [000] dnH1  2826.079138: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079144: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  2826.079146: tegra_mcerr_thread: Too many MC errors; throttling prints
          <idle>-0     [000] dnH1  2826.079152: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] dnH1  2826.079157: tegra_mcerr_hard_irq: MCERR detected.
     kworker/0:3-894   [000] ...1  2826.102927: rtcpu_vinotify_handle_msg: tstamp:88616695508 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:2717349039 data:0x00000001
     kworker/0:3-894   [000] ...1  2826.102931: rtcpu_vinotify_handle_msg: tstamp:88616695656 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:2717349056 data:0x00000000
     kworker/0:3-894   [000] ...1  2826.102934: rtcpu_vinotify_handle_msg: tstamp:88616698952 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:2717352611 data:0x08000000
     kworker/0:3-894   [000] ...1  2826.102936: rtcpu_vinotify_handle_msg: tstamp:88616981423 tag:CHANSEL_PXL_EOF channel:0x00 frame:0 vi_tstamp:2717635097 data:0x01200002
     kworker/0:3-894   [000] ...1  2826.102939: rtcpu_vinotify_handle_msg: tstamp:88616985696 tag:CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:2717639358 data:0x01210040
     kworker/0:3-894   [000] ...1  2826.102941: rtcpu_vinotify_handle_msg: tstamp:88616986584 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:2717639903 data:0x08000000
     kworker/0:3-894   [000] ...1  2826.102943: rtcpu_vinotify_handle_msg: tstamp:88616986693 tag:CHANSEL_FAULT_FE channel:0x01 frame:0 vi_tstamp:2717639907 data:0x00000001
     kworker/0:3-894   [000] ...1  2826.102946: rtcpu_vinotify_handle_msg: tstamp:88616986820 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:2717639910 data:0x00000000
     kworker/0:3-894   [000] ...1  2826.206925: rtos_queue_peek_from_isr_failed: tstamp:88620595506 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  2826.362934: rtos_queue_peek_from_isr_failed: tstamp:88625596011 queue:0x0b4a3c58

When I set active_h larger enough like 900, I will get this:

When I set active_h larger enough like 900, I will get this:

kworker/0:3-894   [000] ...1  3076.189392: rtcpu_vinotify_handle_msg: tstamp:96433001473 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:1943720551 data:0x00000001
     kworker/0:3-894   [000] ...1  3076.239842: rtos_queue_peek_from_isr_failed: tstamp:96434019704 queue:0x0b4a3c58
     kworker/0:3-894   [000] ...1  3076.395843: rtos_queue_peek_from_isr_failed: tstamp:96439020209 queue:0x0b4a3c58
          <idle>-0     [000] d.h1  3076.427996: arm_smmu_context_fault: Unhandled context fault: iova=0x5a5b6000, fsynr=0x13, cb=19, sid=4(0x4 - VI), pgd=26c2f9003 pud=26c2f9003, pmd=26c2fa003, pte=0
          <idle>-0     [000] d.h1  3076.428050: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428065: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428071: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428078: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428086: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428092: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  3076.428095: log_fault.part.1: (255) csw_viw: MC request violates VPR requirements
          <idle>-0     [000] d.h1  3076.428099: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428105: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428111: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  3076.428114: log_fault.part.1:   status = 0x00337072; addr = 0x3ffffffc0
          <idle>-0     [000] d.h1  3076.428117: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428123: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  3076.428126: log_fault.part.1:   secure: yes, access-type: write
          <idle>-0     [000] d.h1  3076.428129: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428135: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428143: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428149: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428156: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428163: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428170: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428178: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428184: tegra_mcerr_hard_irq: MCERR detected.
 irq/55-mc_statu-40    [005] ....  3076.428187: tegra_mcerr_thread: Too many MC errors; throttling prints
          <idle>-0     [000] d.h1  3076.428191: tegra_mcerr_hard_irq: MCERR detected.
          <idle>-0     [000] d.h1  3076.428197: tegra_mcerr_hard_irq: MCERR detected.
     kworker/0:3-894   [000] ...1  3076.447836: rtcpu_vinotify_handle_msg: tstamp:96440104142 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:1950823094 data:0x00000001
     kworker/0:3-894   [000] ...1  3076.447841: rtcpu_vinotify_handle_msg: tstamp:96440104286 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:1950823111 data:0x00000000
     kworker/0:3-894   [000] ...1  3076.447843: rtcpu_vinotify_handle_msg: tstamp:96440107599 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:1950826665 data:0x08000000
     kworker/0:3-894   [000] ...1  3076.447845: rtcpu_vinotify_handle_msg: tstamp:96440721541 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:0 vi_tstamp:1951440438 data:0x00000001
     kworker/0:3-894   [000] ...1  3076.447848: rtcpu_vinotify_handle_msg: tstamp:96440721721 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:1951440441 data:0x00000000

Stuck here for more than 3 days… Looking forward to your guys help

Now you got short frame.
You need to know the output size exactly.

I mean, the actual image size from my device is 384 x 288; I have tried modify active_h from 100 - 900, one by one, when I set it less than 288, I will get this

kworker/0:3-894 [000] ...1 2776.734449: rtcpu_vinotify_handle_msg: tstamp:87075233333 tag:CSIMUX_STREAM channel:0xff frame:0 vi_tstamp:1175886999 data:0x00000001
kworker/0:3-894 [000] ...1 2776.783370: rtos_queue_peek_from_isr_failed: tstamp:87076647085 queue:0x0b4a3c58
kworker/0:3-894 [000] ...1 2776.939432: rtos_queue_peek_from_isr_failed: tstamp:87081647590 queue:0x0b4a3c58
kworker/0:3-894 [000] ...1 2776.991402: rtcpu_vinotify_handle_msg: tstamp:87082681482 tag:CHANSEL_PXL_SOF channel:0x00 frame:0 vi_tstamp:1183335009 data:0x00000001
kworker/0:3-894 [000] ...1 2776.991406: rtcpu_vinotify_handle_msg: tstamp:87082681628 tag:ATOMP_FS channel:0x00 frame:0 vi_tstamp:1183335027 data:0x00000000
kworker/0:3-894 [000] ...1 2776.991409: rtcpu_vinotify_handle_msg: tstamp:87082685023 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:1183338691 data:0x08000000
kworker/0:3-894 [000] ...1 2776.991411: rtcpu_vinotify_handle_msg: tstamp:87082966908 tag:CHANSEL_PXL_EOF channel:0x00 frame:0 vi_tstamp:1183620441 data:0x011f0002
kworker/0:3-894 [000] ...1 2776.991414: rtcpu_vinotify_handle_msg: tstamp:87082967006 tag:CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:1183620489 data:0x01200040
kworker/0:3-894 [000] ...1 2776.991416: rtcpu_vinotify_handle_msg: tstamp:87082967508 tag:CHANSEL_LOAD_FRAMED channel:0x01 frame:0 vi_tstamp:1183621214 data:0x08000000
kworker/0:3-894 [000] ...1 2776.991418: rtcpu_vinotify_handle_msg: tstamp:87082971891 tag:CHANSEL_FAULT_FE channel:0x01 frame:0 vi_tstamp:1183625384 data:0x00000001
kworker/0:3-894 [000] ...1 2776.991421: rtcpu_vinotify_handle_msg: tstamp:87082972018 tag:ATOMP_FE channel:0x00 frame:0 vi_tstamp:1183625387 data:0x00000000

when I set it to 289, I will get more type of error like

<idle>-0 [000] d.h1 3076.427996: arm_smmu_context_fault: Unhandled context fault: iova=0x5a5b6000, fsynr=0x13, cb=19, sid=4(0x4 - VI), pgd=26c2f9003 pud=26c2f9003, pmd=26c2fa003, pte=0
<idle>-0 [000] d.h1 3076.428050: tegra_mcerr_hard_irq: MCERR detected.

then, I make active_h even higher, finally I will get

kworker/0:3-894 [000] ...1 3076.447845: rtcpu_vinotify_handle_msg: tstamp:96440721541 tag:CHANSEL_SHORT_FRAME channel:0x01 frame:0 vi_tstamp:1951440438 data:0x00000001

[b]No “good” configuration found during this process…

The major error info we are interested is this:

CHANSEL_FAULT channel:0x00 frame:0 vi_tstamp:252969194 data:0x01200040

Is there any information we could get from this “0040”

[/b]

PXL_RUNAWAY(0040) means VI received more lines than expected.

Thanks to your response. ^_^

how about these two errors?

<idle>-0 [000] d.h1 3076.427996: arm_smmu_context_fault: Unhandled context fault: iova=0x5a5b6000, fsynr=0x13, cb=19, sid=4(0x4 - VI), pgd=26c2f9003 pud=26c2f9003, pmd=26c2fa003, pte=0
<idle>-0 [000] d.h1 3076.428050: tegra_mcerr_hard_irq: MCERR detected.

when we set the image size as 384 x 288, we get PXL_RUNAWAY(0040), but when we make it 384 x 289, we get bunch of

<idle>-0 [000] d.h1 3076.428050: tegra_mcerr_hard_irq: MCERR detected.

Only below message for 384x289? Any trace log while this message shows up?

<idle>-0 [000] d.h1 3076.427996: arm_smmu_context_fault: Unhandled context fault: iova=0x5a5b6000, fsynr=0x13, cb=19, sid=4(0x4 - VI), pgd=26c2f9003 pud=26c2f9003, pmd=26c2fa003, pte=0
<idle>-0 [000] d.h1 3076.428050: tegra_mcerr_hard_irq: MCERR detected.