はじめに

前の記事: Jetsonのカメラドライバを書く[モード追加とGStreamer編]

前回、GStreamerで画像取得まで出来ました。
すんなり動いてわりと簡単じゃないかと思った方も多いと思いますが、そんなことはありません。
動くように作ったから動いているのです。

繋いだのに動かない!

もしもラズパイカメラV2(IMX219)をお持ちで、L4T35.3.1を使っている場合はCAM0ポートに繋いでみましょう。
Jetson Hacksに繋いでみた記事がありますし、繋いだら簡単に動きそうですね。
ケーブルを手に入れて、表裏を間違えずに差しましょう。
dmesgを見ればimx219は繋がってますし、v4l2-ctrでみても無事認識してます。
しかし、argus_cameraあたりでキャプチャーを試そうとしたら実際には動かず、dmesgに出てくるのは以下のように無情なエラーです

[ 498.418470] tegra-camrtc-capture-vi tegra-capture-vi: uncorr_err: request timed out after 2500 ms
[ 498.431214] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: attempting to reset the capture channel
[ 498.442011] (NULL device *): vi_capture_control_message: NULL VI channel received
[ 498.449743] t194-nvcsi 13e40000.host1x:nvcsi@15a00000: csi5_stream_close: Error in closing stream_id=0, csi_port=0
[ 498.460431] (NULL device *): vi_capture_control_message: NULL VI channel received
[ 498.468166] t194-nvcsi 13e40000.host1x:nvcsi@15a00000: csi5_stream_open: VI channel not found for stream- 0 vc- 0
[ 498.479038] tegra-camrtc-capture-vi tegra-capture-vi: err_rec: successfully reset the capture channel

他のボードでは動いていたのに? ケーブルの刺さりが甘いのか? そもそもこのエラーどういう意味だ? どうして動かない...。

実際開発で辛いのは書いてみたけど動かず、ケーブルが悪いのか、レジスタ設定どこか忘れたのか、間違ってセンサー壊したのではないかと全てを疑うときです。
そういう時に少しでもJetsonから情報を得て、開発を前に進めるためにはデバッグの方法を知る必要があります。

とりあえずForumを見る

トラブル情報がまず集まるのはNVIDIAのForumです。
この不具合に関してはIMX219 doesn’t stream on CAM0 port on Orin Nano DevKitのTopicにあり、配布されているL4T35.3.1デバイスツリーの設定ミスが原因とわかっています。
市販製品であれば誰かがtopicを上げてくれていることが多く、何らかの答えが出ていることもあります。

しかしForumのTopicはいつも解決するとは限りません。
モデレーターに上手く伝わらず答えにたどりつかないものや、本人がどこかで自己解決したがForumに書いてないため解決方法が不明だったり、本人が興味を失って自然消滅的にクローズ...そういう記事がかなり見つかります。

無いなら自分で調べるしかありません

トレースを使ったデバッグ

こちらがデバッグのためのおまじないです。

# need sudo
.PHONY: trace.enable
trace.enable:
	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

# need sudo
.PHONY: trace.disable
trace.disable:
	echo 0 > /sys/kernel/debug/tracing/tracing_on
	echo 0 > /sys/kernel/debug/tracing/events/tegra_rtcpu/enable	
	echo 0 > /sys/kernel/debug/tracing/events/freertos/enable
	echo 0 > /sys/kernel/debug/camrtc/log-level
	echo > /sys/kernel/debug/tracing/trace

.PHONY: trace.log
trace.log:
	sudo cat /sys/kernel/debug/tracing/trace > log.txt

.PHONY: check
check:
	v4l2-ctl -d /dev/video0 --set-ctrl bypass_mode=0 --stream-mmap --stream-count=1 --stream-to=test.raw

準備編でVI6に少しだけ触れましたが、JetsonでMIPIのデータがLinuxで扱えるまでは専用のHWで行われています。
このHWにはMIPIシグナルを解析した結果やエラーを通知機能があるため、これらを使ってデバッグをします。
上のコマンドそのトレース情報をlinuxに吸い上げるための設定です。

使い方はトレースを有効にする -> MIPIのストリーム開始 -> ログを書き出し -> disableに戻す、です。
ログを常に有効にしていると、大量のログが吐き出されてkernelがハングアップするので不要な時は無効にすることをおすすめします。

sudo make trace.enable
make check　# 正常にデータが得られない場合はCtrl+Cでキャンセル
make trace.log
sudo make trace.disable

トレースをみる

まずはIMX219のトレースを見てみましょう。
先のForumから引用すると以下のとおりです。

kworker/1:3-124 [001] … 495.790416: rtcpu_vinotify_event: tstamp:16447376025 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:526306026272 data:0x719d580010000000
kworker/1:3-124 [001] … 495.790417: rtcpu_vinotify_event: tstamp:16447376367 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:526306036000 data:0x0000000031000001
kworker/1:3-124 [001] … 495.790417: rtcpu_vinotify_event: tstamp:16447376709 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:526306134592 data:0x719d550010000000
kworker/1:3-124 [001] … 495.790418: rtcpu_vinotify_event: tstamp:16447376998 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:526306144448 data:0x0000000031000002
vi-output, imx2-2712 [005] … 498.478883: tegra_channel_capture_setup: vnc_id 0 W 3280 H 2464 fmt c4

VIFALC_TDSTATEというログしかでていません。
これはFalconというVI6全体のイベントを監視しているマイクロコントローラーからのログです。
カメラを起動するためLinuxからの指示を受けると出てくるログで、MIPIについてはなんの情報もありません。
もしセンサーが動いているなら、MIPIデータの解析結果が見えるはずです。

正常動作

CAM1での正常動作例を見てみましょう。

# tracer: nop
#
# entries-in-buffer/entries-written: 63/63   #P:6
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/1:9-145     [001] ....   203.451341: rtcpu_string: tstamp:7192509887 id:0x04010000 str:"VM0 deactivating."
     kworker/1:9-145     [001] ....   205.747299: rtcpu_string: tstamp:7264934208 id:0x04010000 str:"VM0 activating."
     kworker/1:9-145     [001] ....   205.747304: rtcpu_vinotify_event: tstamp:7265567958 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:232482245664 data:0x719e300010000000
     kworker/1:9-145     [001] ....   205.747304: rtcpu_vinotify_event: tstamp:7265568220 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:232482255456 data:0x0000000031000001
     kworker/1:9-145     [001] ....   205.747304: rtcpu_vinotify_event: tstamp:7265568514 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:232482347072 data:0x719e2d0010000000
     kworker/1:9-145     [001] ....   205.747304: rtcpu_vinotify_event: tstamp:7265568764 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:232482356992 data:0x0000000031000002
     kworker/1:9-145     [001] ....   205.859296: rtcpu_vinotify_event: tstamp:7267738354 cch:0 vi:1 tag:FS channel:0x00 frame:1 vi_tstamp:232554785056 data:0x0000000100000012
     kworker/1:9-145     [001] ....   205.859299: rtcpu_vinotify_event: tstamp:7267738624 cch:0 vi:1 tag:ATOMP_FS channel:0x00 frame:1 vi_tstamp:232554785120 data:0x0000000800000000
     kworker/1:9-145     [001] ....   205.859300: rtcpu_vinotify_event: tstamp:7267738912 cch:0 vi:1 tag:CHANSEL_EMBED_SOF channel:0x23 frame:1 vi_tstamp:232554785824 data:0x0000000000000004
     kworker/1:9-145     [001] ....   205.859301: rtcpu_vinotify_event: tstamp:7267739157 cch:0 vi:1 tag:CHANSEL_EMBED_EOF channel:0x23 frame:1 vi_tstamp:232554822304 data:0x0000000000010008
     kworker/1:9-145     [001] ....   205.859302: rtcpu_vinotify_event: tstamp:7267739436 cch:0 vi:1 tag:ATOMP_EMB_DATA_DONE channel:0x23 frame:1 vi_tstamp:232554823488 data:0x0000000000000000
     kworker/1:9-145     [001] ....   205.859302: rtcpu_vinotify_event: tstamp:7267739682 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:232554846912 data:0x0000000003020001
     kworker/1:9-145     [001] ....   205.859303: rtcpu_vinotify_event: tstamp:7267739960 cch:0 vi:1 tag:CHANSEL_PXL_SOF channel:0x23 frame:1 vi_tstamp:232554840992 data:0x0000000000000001
     kworker/1:9-145     [001] ....   205.859304: rtcpu_vinotify_event: tstamp:7267740202 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:232554870432 data:0x0000000008020001
     kworker/1:9-145     [001] ....   205.859305: rtcpu_vinotify_event: tstamp:7268802881 cch:0 vi:1 tag:CHANSEL_PXL_EOF channel:0x23 frame:1 vi_tstamp:232601417600 data:0x00000000099f0002
     kworker/1:9-145     [001] ....   205.859305: rtcpu_vinotify_event: tstamp:7268803130 cch:0 vi:1 tag:FE channel:0x00 frame:1 vi_tstamp:232601418176 data:0x0000000100000022
     kworker/1:9-145     [001] ....   205.859306: rtcpu_vinotify_event: tstamp:7268803419 cch:0 vi:1 tag:ATOMP_FE channel:0x00 frame:1 vi_tstamp:232601418240 data:0x0000000800000000
     kworker/1:9-145     [001] ....   205.859307: rtcpu_vinotify_event: tstamp:7268803663 cch:0 vi:1 tag:ATOMP_FRAME_DONE channel:0x23 frame:1 vi_tstamp:232601418848 data:0x0000000000000000
     kworker/1:9-145     [001] ....   205.859308: rtcpu_vinotify_event: tstamp:7269311979 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:232601479040 data:0x0000000002020001
     kworker/1:9-145     [001] ....   205.859308: rtcpu_vinotify_event: tstamp:7269312230 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:232601495712 data:0x0000000000020001

vi:0 -> vi:1なのはCAM1ポートの動作だからです。
それ以外は基本的には変わらないので読んでいくと以下のようになります

tag	vitstamp	data	desc
FS	232554785056	0x0000000100000012	CSIMUXがFrame start packetを検知
ATOMP_FS	232554785120	0x0000000800000000	ATOMPがFSを発行
CHANSEL_EMBED_SOF	232554785824	0x0000000000000004	埋め込みデータを検知
CHANSEL_EMBED_EOF	232554822304	0x0000000000010008	埋め込みデータ2lineを予定通りキャプチャ
ATOMP_EMB_DATA_DONE	232554823488	0x0000000000000000	ATOMPが埋め込みデータキャプチャ完了を報告
CHANSEL_PXL_SOF	232554840992	0x0000000000000001	0line目でピクセルデータ開始を検知
CHANSEL_PXL_EOF	232601417600	0x00000000099f0002	0x99f=2463lineでピクセルデータ終了を検知
FE	232601418176	0x0000000100000022	CSIMUXがFrame end packetを検知
ATOMP_FE	232601418240	0x0000000800000000	ATOMPがFrameEndを発行
ATOMP_FRAME_DONE	232601418848	0x0000000000000000	ATOMP/OFIFがメモリに転送完了を報告

CSIの受信、パケット解析、データのルーティング、メモリへの転送、完了通知という一連の流れがあるのがわかります。また、mode0の画像の大きさは3280x2464であるためEOFが期待通りのline numberで出ているのがわかります。

これを踏まえると、IMX219でログが何もないとなった場合はCSIまでデータがきていない可能性が高いです。実際この問題についてデバイスツリーを追った結果NVCSIのルーティングのミスが見つかったのが原因でした。このようにトレース機能を使うことでV4L2やArgusAPIからはわからないMIPIの動作情報を知ることが出来ます。

NOTIFY

NOTIFYはVI6にあるブロックの1つで、CSIMUXからメモリ書き込みまでのイベントを監視しFalconに通知しています。

L4Tではこの情報をLinux側に吸い上げることが出来、この実装に関する情報はtegra-rtcpu-trace.cに書かれています。
TRMに明記してあるタグの種類は以下の通りで、tagの数字は文字列に置き換えられて出力されています。

Source	Event	Desc
CSIMUX	Frame start / end	A/V同期に使う可能性がある FS=tag:0 and FE=tag:1
CSIMUX	Frame fault events	入力エラーが発生した場合で、FS/FE eventと同時に発生する場合がある tag:2
CSIMUX	Stream fault	フレームに関連付けることの出来ない入力エラーの場合。 CSIMUX_STREAM=tag:3
CHANSEL	{Start, end} of {frame, emb}	frame=tag4, 5 emb=tag:6, 7
CHANSEL	Line reached events	ラインタイマー切れ tag: 8
CHANSEL	Single-channel fault	CHANSEL_FAULT=tag:9 or 10
CHANSEL	Many-channel faults	tag: 11-14
ATOMP	Surface packer overflow	これを見つけたらVIアーキテクチャチームに連絡する。tag: 15
ATOMP	{Start, end} of frame	tag: 16, 17
ATOMP / OFIF	Frame done / embedded data / PDAF data done	tag:18, 19, 23
ATOMP / OFIF	Frame partial completion	tag: 20
ATOMP / OFIF	Frame truncated / frame tossed	tag: 21, 22
VGPIO	VGPIO interrupt	設定がされている時に。tag: 29, 30
FML	FM-Lite completion	tag: 31

CSIMUXのエラーはセンサーの出力異常が主で、ATOMPはVI6の実装が起因する可能性が高いです
必然的に、市販センサーを使って正常に映像が得られない場合、最も見つかるであろうエラーのタグはCHANSEL_FAULTと考えられます。

CHANSEL_FAULTの例(埋め込みデータ行数不一致)

IMX708のmode0を作る時におまじないとしてembedded_metadata_height = "4"を設定していました。
これがimx219のように2と設定していたらどうなるか見ましょう。
このケースではエラーが出て映像が得られません。

# tracer: nop
#
# entries-in-buffer/entries-written: 166/166   #P:6
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/1:3-124     [001] ....   244.100004: rtcpu_string: tstamp:8463177829 id:0x04010000 str:"VM0 deactivating."
     kworker/1:3-124     [001] ....   244.715822: rtcpu_string: tstamp:8481776229 id:0x04010000 str:"VM0 activating."
     kworker/1:3-124     [001] ....   244.715828: rtcpu_vinotify_event: tstamp:8482459849 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:271422387232 data:0x719e300010000000
     kworker/1:3-124     [001] ....   244.715828: rtcpu_vinotify_event: tstamp:8482460106 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:271422396992 data:0x0000000031000001
     kworker/1:3-124     [001] ....   244.715829: rtcpu_vinotify_event: tstamp:8482460395 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:271422488064 data:0x719e2d0010000000
     kworker/1:3-124     [001] ....   244.715829: rtcpu_vinotify_event: tstamp:8482460640 cch:0 vi:1 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:271422497984 data:0x0000000031000002
     kworker/1:3-124     [001] ....   244.771807: rtcpu_vinotify_event: tstamp:8485172281 cch:0 vi:1 tag:FS channel:0x00 frame:1 vi_tstamp:271521418400 data:0x0000000100000012
     kworker/1:3-124     [001] ....   244.771808: rtcpu_vinotify_event: tstamp:8485172541 cch:0 vi:1 tag:ATOMP_FS channel:0x00 frame:1 vi_tstamp:271521418528 data:0x0000000800000000
     kworker/1:3-124     [001] ....   244.771808: rtcpu_vinotify_event: tstamp:8485172825 cch:0 vi:1 tag:CHANSEL_EMBED_SOF channel:0x23 frame:1 vi_tstamp:271521418976 data:0x0000000000000004
     kworker/1:3-124     [001] ....   244.771809: rtcpu_vinotify_event: tstamp:8485173069 cch:0 vi:1 tag:CHANSEL_EMBED_EOF channel:0x23 frame:1 vi_tstamp:271521470592 data:0x0000000000010008
     kworker/1:3-124     [001] ....   244.771809: rtcpu_vinotify_event: tstamp:8485173345 cch:0 vi:1 tag:ATOMP_EMB_DATA_DONE channel:0x23 frame:1 vi_tstamp:271521471776 data:0x0000000000000000
     kworker/1:3-124     [001] ....   244.771810: rtcpu_vinotify_event: tstamp:8485173588 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:271521491584 data:0x0000000003020001
     kworker/1:3-124     [001] ....   244.771810: rtcpu_vinotify_event: tstamp:8485173866 cch:0 vi:1 tag:CHANSEL_PXL_SOF channel:0x23 frame:1 vi_tstamp:271521944416 data:0x0000000000000001
     kworker/1:3-124     [001] ....   244.771810: rtcpu_vinotify_event: tstamp:8485174110 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:271521955392 data:0x0000000008020001
     kworker/1:3-124     [001] ....   244.883818: rtcpu_vinotify_event: tstamp:8487200850 cch:0 vi:1 tag:CHANSEL_PXL_EOF channel:0x23 frame:1 vi_tstamp:271590087296 data:0x000000000a1f0002
     kworker/1:3-124     [001] ....   244.883819: rtcpu_vinotify_event: tstamp:8487201115 cch:0 vi:1 tag:CHANSEL_FAULT channel:0x23 frame:1 vi_tstamp:271590088064 data:0x0000000000020800
     kworker/1:3-124     [001] ....   244.883820: rtcpu_vinotify_event: tstamp:8487201409 cch:0 vi:1 tag:VIFALC_ACTIONLST channel:0x23 frame:1 vi_tstamp:271590141632 data:0x0000000001020001
     kworker/1:3-124     [001] ....   244.883821: rtcpu_vinotify_event: tstamp:8487201658 cch:0 vi:1 tag:ATOMP_FRAME_DONE channel:0x23 frame:1 vi_tstamp:271590088544 data:0x0000000000000000
     kworker/1:3-124     [001] ....   244.883822: rtcpu_vinotify_event: tstamp:8487722322 cch:0 vi:1 tag:FE channel:0x00 frame:1 vi_tstamp:271590166208 data:0x0000000100000022
     kworker/1:3-124     [001] ....   244.883823: rtcpu_vinotify_event: tstamp:8487722584 cch:0 vi:1 tag:ATOMP_FE channel:0x00

以下のエラーがFEの直前にでています。このdataのが意味するのはEMBED_RUNAWAYであり、デバイスツリーで設定されている2lineよりも多い数の埋め込みデータラインが見つかったという意味です。

tag:CHANSEL_FAULT channel:0x23 frame:1 vi_tstamp:271590088064 data:0x0000000000020800

上の方には1lineまで埋め込みデータが見つかってこのフレームでの受信は完了したという判定になっており、CHANSEL_FAULTの前にはCHANSEL_PXL_EOFもでているので、ピクセルデータが終わった後に埋め込みデータを受信したと推測されます。
IMX708はIMX477と同じように、ピクセルデータの後に埋め込みデータを付与しているようです。

tag:CHANSEL_EMBED_EOF channel:0x23 frame:1 vi_tstamp:271521470592 data:0x0000000000010008

CHANSEL_FAULT

CHANSEL_FAULTはタグの他にdataにそのエラーやステータスの詳細を出しており、上位16bitがライン数、下位16bitがエラーコードとなっています。
この情報はJetson/l4t/Camera_BringUpにまとまっています。
Jetsonの世代よって変わる可能性もあるのでTRMやソースコードも確認するのをおすすめします。

CHANSEL_FAULT	bit	example	desc
LINE_NUMBER	16:31	0x00000001	0 lineでSoF検知
DTYPE_MISMATCH	15	0x00018000	1lineでデータタイプ不一致
EMBED_INFRINGE	14	0x00034000	3lineで埋め込みデータが予期されていないフレームで埋め込みデータを受信
EMBED_LONG_LINE	13	0x00012000	埋め込みデータラインが想定より長い
EMBED_SPURIOUS	12	0x00011000	ラインスタートなしに埋め込みデータが開始
EMBED_RUNAWAY	11	0x00010800	埋め込みデータのライン数が多い
EMBED_MISSING_LE	10	0x00010400	埋め込みデータのラインエンドが見つからない
PIXEL_SHORT_LINE	9	0x00010200	想定よりも少ないピクセル数でラインが終わった
PIXEL_LONG_LINE	8	0x00010100	ラインで想定よりも多いピクセルデータが見つかった
PIXEL_SPURIOUS	7	0x00010080	ラインスタートパケットなしにデータ開始
PIXEL_RUNAWAY	6	0x00010040	ピクセルデータが想定よりも多いライン数見つかった
PIXEL_MISSING_LE	5	0x00010020	ラインエンドが見つからない
PIXEL_LINE_TIMER	4	0x????0010	タイマー
EMBED_EOF	3	0x00000008	0 lineで埋め込みデータEoF検知
EMBED_SOF	2	0x00000004	0 lineで埋め込みデータのSoF検知
PIXEL_EOF	1	0x14600002	5216 lineでEoF検知
PIXEL_SOF	0	0x00000001	0 lineでSoF検知

レジスタ設定とデバイスツリー設定で不一致がある場合は上記のどれかに当たるエラーがでるはずです。

NVCSI

ここまではMIPI-CSIのシグナルが正常に受け取れている場合です。
もしもシグナルが正しくない場合はどうでしょうか?

NVCSIの中身を見てみますと以下のようになっています。
電気的な信号を受け取るためのPad(PHY)、CIL(Control and Interface Logic)とパケット解析をするPP(PacketParser)です。
MIPIの信号がそのものが正しくなければPad,CILからエラーが報告されます。
Padの電気的な性質は極性やレーンの入れ替えなど一部が変更可能で、CILからパラメータから渡すことで変更できます。
今回はデータレーンのPN極性反転(=Lane Polarily)の例を見てみましょう

Lane Polarily

Orin世代ではCSI-A-D1とCSI-B-D0の極性が反転している不具合が見つかっています。
HW的なもので、今後もHWでの修正予定はなく、デバイスツリーの設定で対応するのが公式の手順となっています。
以下は期待通りの反転設定をしなかった場合のトレースログです。

#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
     kworker/2:9-168     [002] ....    60.622487: rtcpu_vinotify_event: tstamp:2616133464 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:83700146304 data:0x399d580010000000
     kworker/2:9-168     [002] ....    60.622491: rtcpu_vinotify_event: tstamp:2616133606 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:83700152768 data:0x0000000031000001
     kworker/2:9-168     [002] ....    60.622491: rtcpu_vinotify_event: tstamp:2616133765 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:83700203776 data:0x399d550010000000
     kworker/2:9-168     [002] ....    60.622491: rtcpu_vinotify_event: tstamp:2616133897 cch:0 vi:0 tag:VIFALC_TDSTATE channel:0x23 frame:0 vi_tstamp:83700210368 data:0x0000000031000002
     kworker/2:9-168     [002] ....    60.678492: rtcpu_nvcsi_intr: tstamp:2619031934 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000080
     kworker/2:9-168     [002] ....    60.678493: rtcpu_nvcsi_intr: tstamp:2619032503 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000080
     kworker/2:9-168     [002] ....    60.678494: rtcpu_nvcsi_intr: tstamp:2619039320 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000080
     kworker/2:9-168     [002] ....    60.678495: rtcpu_nvcsi_intr: tstamp:2619046706 class:GLOBAL type:PHY_INTR0 phy:0 cil:0 st:0 vc:0 status:0x00000080

NOTIFYでみたrtcpu_vinotify_eventのログではなくrtcpu_nvcsi_intrのメッセージが出ています。
32bitでステータスコードのみでstatus:0x00000080はD1側のLPシーケンスが期待どおりでないことを示しています。
CSI-Aのレーンで繋いだときの結果であるため、D1でエラーになるのは予測通りの結果です。

この問題を修正するためにデバイスツリーにはlane_polarity = "6";を設定する必要があります。
lane_polarityはCSIXとX+1を1組として解釈します。
なので6 = 0b0110であるため下位ビットから以下の通り解釈して極性を入れ替えてます

CSI0-D0: 変更なし
CSI0-D1: Swap
CSI1-D0: Swap
CSI1-D1: 変更なし

4レーン単位で設定するため、CSI0とCSI1で別のセンサーを繋ぐ場合にはそれぞれに同じ値を設定する必要があります。

NVCSI_CIL_INTR0_FLAGS

CILでのエラーステータスは以下のように定義されています。
数字はデータレーンなのでD0D1どちらで起きているかがわかります。

極性判定のように信号自体は取れているがプロトコルがおかしい場合には_CTRLが、
pix_clk_hzとセンサーの出力速度の差が大きい場合は_RXFIFO_FULLが出るほか、信号品質が悪いときには_SOT_MBなどが出ることが多いようです。

既知の略称は以下の略です

ERR?_CTRL: LPシーケンスが期待どおりでない
ERR?_SOT_SB: Start of Transfer Single bit error
ERR?_SOT_MB: Start of Transfer Multi bit error

camrtc-capture.h

/**
 * @defgroup NVCSI_CIL_INTR0_FLAGS NVCSI phy/cil intr0 flags
 * @{
 */
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_ERR_CLK_LANE_CTRL	MK_BIT32(0)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_SOT_SB		MK_BIT32(1)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_SOT_MB		MK_BIT32(2)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_CTRL		MK_BIT32(3)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_RXFIFO_FULL	MK_BIT32(4)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_SOT_SB		MK_BIT32(5)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_SOT_MB		MK_BIT32(6)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_CTRL		MK_BIT32(7)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_RXFIFO_FULL	MK_BIT32(8)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_SOT_2LSB_FULL	MK_BIT32(9)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_SOT_2LSB_FULL	MK_BIT32(10)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR0_ESC_MODE_SYNC	MK_BIT32(19)
#define NVCSI_INTR_FLAG_CIL_INTR0_DATA_LANE_ERR1_ESC_MODE_SYNC	MK_BIT32(20)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_DONE_LANE0	MK_BIT32(22)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_DONE_LANE1	MK_BIT32(23)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_DONE_CTRL	MK_BIT32(24)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_ERR_LANE0	MK_BIT32(25)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_ERR_LANE1	MK_BIT32(26)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_DESKEW_CALIB_ERR_CTRL	MK_BIT32(27)
#define NVCSI_INTR_FLAG_CIL_INTR0_DPHY_LANE_ALIGN_ERR		MK_BIT32(28)
#define NVCSI_INTR_FLAG_CIL_INTR0_CPHY_CLK_CAL_DONE_TRIO0	MK_BIT32(29)
#define NVCSI_INTR_FLAG_CIL_INTR0_CPHY_CLK_CAL_DONE_TRIO1	MK_BIT32(30)
/** @} */

Lane swap

極性以外にもデータレーンが入れ替わっている可能性も考えられます。
brickでNvCsiLaneSwizzleを設定すれば実現できます。
こちらもcsi_port2セット人組で設定するため、条件分岐で0,1などを指定するのが良いです。

csi5_fops.c

    /* Brick config */
    memset(&brick_config, 0, sizeof(brick_config));
    brick_config.phy_mode = (!is_cphy) ?
        NVCSI_PHY_TYPE_DPHY : NVCSI_PHY_TYPE_CPHY;
+   if (csi_port == 0 || csi_port == 1)
+       brick_config.lane_swizzle = NVCSI_LANE_SWIZZLE_A1A0B0B1;

この場合のエラーは以下のようにSTREAM_NOVCとなります。

     kworker/3:0-2740    [003] ....  1234.287754: rtcpu_nvcsi_intr: tstamp:40086607642 class:GLOBAL type:STREAM_NOVC phy:0 cil:0 st:0 vc:0 status:0x00000001
     kworker/3:0-2740    [003] ....  1234.287764: rtcpu_nvcsi_intr: tstamp:40086607642 class:CORRECTABLE_ERR type:STREAM_NOVC phy:0 cil:0 st:0 vc:0 status:0x00000001

信号的には問題ないためPAD, CILは通過してPPに入ったものの、
パケット解析の過程でDPHY packet headerのECCが通らなかったというエラーになります。
データレーンが入れ替わっている場合、8bit単位で前後が入れ替わっているのでこのような結果になります。

NVCSI_STREAM_INTR_FLAGS

PPでのエラーはSTREAMのエラーになります。
MIPI信号として解釈は出来ても、品質が悪くてデータが書き換わっている場合や、今回の実験のようにデータレーンが入れ替わっている場合はこのエラーになるようです。
こちらはソースコードにもコメントがあり、見ての通り基本的にはECCのチェックが通らないなどパケットのデータが期待するシーケンスと異なる内容が主です。

camrtc-capture.h

/**
 * @defgroup NVCSI_STREAM_INTR_FLAGS NVCSI stream novc+vc interrupt flags
 * @{
 */
/** Multi bit error in the DPHY packet header */
#define NVCSI_INTR_FLAG_STREAM_NOVC_ERR_PH_ECC_MULTI_BIT	MK_BIT32(0)
/** Error bit indicating both of the CPHY packet header CRC check fail */
#define NVCSI_INTR_FLAG_STREAM_NOVC_ERR_PH_BOTH_CRC		MK_BIT32(1)
/** Error bit indicating VC Pixel Parser (PP) FSM timeout for a pixel line.*/
#define NVCSI_INTR_FLAG_STREAM_VC_ERR_PPFSM_TIMEOUT		MK_BIT32(2)
/** Error bit indicating VC has packet with single bit ECC error in the packet header*/
#define NVCSI_INTR_FLAG_STREAM_VC_ERR_PH_ECC_SINGLE_BIT		MK_BIT32(3)
/** Error bit indicating VC has packet payload crc check fail */
#define NVCSI_INTR_FLAG_STREAM_VC_ERR_PD_CRC			MK_BIT32(4)
/** Error bit indicating VC has packet terminate before getting the expect word count data. */
#define NVCSI_INTR_FLAG_STREAM_VC_ERR_PD_WC_SHORT		MK_BIT32(5)
/** Error bit indicating VC has one of the CPHY packet header CRC check fail. */
#define NVCSI_INTR_FLAG_STREAM_VC_ERR_PH_SINGLE_CRC		MK_BIT32(6)
/** @} */

エラーの優先順位

いくつかエラーを紹介してきましたが、実際エラーがでた後にどこから疑うのがいいでしょうか?
これまでのエラーには優先順位があります。パケット解析がエラーになるならMIPIは正常に受信出来ているはずですから、エラーはPHYに近い側から先取りです。
なのでエラーを上げてきた内容でどのあたりを調べるべきか、もしくは関連パラメータ特にデータレーンを振ったら正常に取れる場合もあります。
経験的には以下のことが言えると思うので参考にしてください。

rtcpu_nvcsi_intr
1. PHY/CILでMIPIの信号とプロトコルが正しいこと: 極性異常、データレートの不一致、信号品質
2. PPで受信したデータの並びが正しいこと: データレーンの正しさ、信号品質
rtcpu_vinotify_event
1. 解析したデータが期待通りの構造をしていること: レジスタ設定やルーティング設定

私は開発キットの2lane D-PHYの環境でしか試していないため、VCを使ったり、C-PHYの場合などのケースは実践している方が書いてくれることを期待します!

まとめ

Jetsonのカメラドライバ開発において必要になるであろうトレース機能を使ったデバッグについて紹介しました。
準備編の資料と合わせればカメラドライバ開発を専門としていなくてもそこそこ動くドライバは書けるはずです。
NVIDIAの公式のドキュメントにカメラドライバ開発の情報もかなり書かれていて本当に助かりました。

一方で実際に上手く動かない場合はどうすべきかはドキュメントにはあまりありません。
デバッグ方法に関する情報はForumのあちこちに分散している情報を寄せ集め、正常に動くセンサーにわざと不正な設定を入れて実験的に得たものです。
網羅は出来ていないものの、調査するのに取っ掛かりとなる情報はまとまっていると思います。
これからカメラドライバ開発をする、せざるを得ない開発者の参考になれば嬉しいです。