Timestamp problems - QUEUED_BUFFERS 2 for low latency

jhbaek · May 31, 2021, 11:18am

I uses 6 cameras and have applied below patch for low latency.

(tx2)the camera delay N+2 frame - Jetson & Embedded Systems / Jetson TX2 - NVIDIA Developer Forums

Channel 0’s timestamp is OK but others are not fine.

stream on of 6 cameras => timestamp is OK.
stream off of 6 cameras => “ATOMP_FE syncpt timeout!” occured.
stream on of 6 camera => ch0 is ok. ch1 ~ 6’s timestamp is zero…

When I checked the timestamp at this time on kernel debug message, it was ok not zero.

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_pipe

 kworker/0:3-6620  [000] ....  1153.996809: rtcpu_vinotify_event: tstamp:36351024949 tag:ATOMP_FS channel:0x02 frame:33 vi_tstamp:36351024550 data:0x00000000
 kworker/0:3-6620  [000] ....  1153.996852: rtcpu_vinotify_event: tstamp:36351027699 tag:CHANSEL_PXL_SOF channel:0x02 frame:33 vi_tstamp:36351027312 data:0x00000001
 kworker/0:3-6620  [000] ....  1153.996855: rtcpu_vinotify_event: tstamp:36351096077 tag:CHANSEL_PXL_EOF channel:0x01 frame:33 vi_tstamp:36351095297 data:0x04370002
 kworker/0:3-6620  [000] ....  1153.996857: rtcpu_vinotify_event: tstamp:36351096270 tag:ATOMP_FE channel:0x01 frame:33 vi_tstamp:36351095403 data:0x00000000
 kworker/0:3-6620  [000] ....  1153.996860: rtcpu_vinotify_event: tstamp:36351806161 tag:ATOMP_FS channel:0x00 frame:34 vi_tstamp:36351805744 data:0x00000000
 kworker/0:3-6620  [000] ....  1153.996862: rtcpu_vinotify_event: tstamp:36351808905 tag:CHANSEL_PXL_SOF channel:0x00 frame:34 vi_tstamp:36351808506 data:0x00000001
 kworker/0:3-6620  [000] ....  1153.996868: rtcpu_vinotify_event: tstamp:36351937834 tag:ATOMP_FS channel:0x03 frame:33 vi_tstamp:36351937419 data:0x00000000
 kworker/0:3-6620  [000] ....  1153.996870: rtcpu_vinotify_event: tstamp:36351940580 tag:CHANSEL_PXL_SOF channel:0x03 frame:33 vi_tstamp:36351940181 data:0x00000001
 kworker/0:3-6620  [000] ....  1153.996873: rtcpu_vinotify_event: tstamp:36352027974 tag:CHANSEL_PXL_EOF channel:0x02 frame:33 vi_tstamp:36352027196 data:0x04370002
 kworker/0:3-6620  [000] ....  1153.996876: rtcpu_vinotify_event: tstamp:36352028165 tag:ATOMP_FE channel:0x02 frame:33 vi_tstamp:36352027304 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.053082: rtcpu_vinotify_event: tstamp:36352809178 tag:CHANSEL_PXL_EOF channel:0x00 frame:34 vi_tstamp:36352808387 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.053126: rtcpu_vinotify_event: tstamp:36352809388 tag:ATOMP_FE channel:0x00 frame:34 vi_tstamp:36352808494 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.053129: rtcpu_vinotify_event: tstamp:36352940839 tag:CHANSEL_PXL_EOF channel:0x03 frame:33 vi_tstamp:36352940060 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.053131: rtcpu_vinotify_event: tstamp:36352941031 tag:ATOMP_FE channel:0x03 frame:33 vi_tstamp:36352940169 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.053134: rtcpu_vinotify_event: tstamp:36353218095 tag:ATOMP_FS channel:0x01 frame:34 vi_tstamp:36353217685 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.053136: rtcpu_vinotify_event: tstamp:36353220880 tag:CHANSEL_PXL_SOF channel:0x01 frame:34 vi_tstamp:36353220447 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.108827: rtcpu_vinotify_event: tstamp:36354149990 tag:ATOMP_FS channel:0x02 frame:34 vi_tstamp:36354149574 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.108866: rtcpu_vinotify_event: tstamp:36354152732 tag:CHANSEL_PXL_SOF channel:0x02 frame:34 vi_tstamp:36354152336 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.108869: rtcpu_vinotify_event: tstamp:36354221121 tag:CHANSEL_PXL_EOF channel:0x01 frame:34 vi_tstamp:36354220338 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.108871: rtcpu_vinotify_event: tstamp:36354221314 tag:ATOMP_FE channel:0x01 frame:34 vi_tstamp:36354220445 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.108878: rtos_queue_peek_from_isr_failed: tstamp:36354717002 queue:0x0b4b4500
 kworker/0:3-6620  [000] ....  1154.108880: rtcpu_vinotify_event: tstamp:36354931168 tag:ATOMP_FS channel:0x00 frame:35 vi_tstamp:36354930754 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.108883: rtcpu_vinotify_event: tstamp:36354933915 tag:CHANSEL_PXL_SOF channel:0x00 frame:35 vi_tstamp:36354933516 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.108885: rtcpu_vinotify_event: tstamp:36355062842 tag:ATOMP_FS channel:0x03 frame:34 vi_tstamp:36355062429 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.108887: rtcpu_vinotify_event: tstamp:36355065591 tag:CHANSEL_PXL_SOF channel:0x03 frame:34 vi_tstamp:36355065189 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.108889: rtcpu_vinotify_event: tstamp:36355153004 tag:CHANSEL_PXL_EOF channel:0x02 frame:34 vi_tstamp:36355152221 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.108892: rtcpu_vinotify_event: tstamp:36355153196 tag:ATOMP_FE channel:0x02 frame:34 vi_tstamp:36355152327 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.164831: rtcpu_vinotify_event: tstamp:36355934190 tag:CHANSEL_PXL_EOF channel:0x00 frame:35 vi_tstamp:36355933397 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.164868: rtcpu_vinotify_event: tstamp:36355934400 tag:ATOMP_FE channel:0x00 frame:35 vi_tstamp:36355933504 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.164871: rtcpu_vinotify_event: tstamp:36356065843 tag:CHANSEL_PXL_EOF channel:0x03 frame:34 vi_tstamp:36356065071 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.164873: rtcpu_vinotify_event: tstamp:36356066034 tag:ATOMP_FE channel:0x03 frame:34 vi_tstamp:36356065179 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.164875: rtcpu_vinotify_event: tstamp:36356343143 tag:ATOMP_FS channel:0x01 frame:35 vi_tstamp:36356342728 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.164877: rtcpu_vinotify_event: tstamp:36356345892 tag:CHANSEL_PXL_SOF channel:0x01 frame:35 vi_tstamp:36356345489 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.164879: rtcpu_vinotify_event: tstamp:36357275020 tag:ATOMP_FS channel:0x02 frame:35 vi_tstamp:36357274597 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.164882: rtcpu_vinotify_event: tstamp:36357277757 tag:CHANSEL_PXL_SOF channel:0x02 frame:35 vi_tstamp:36357277359 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.164884: rtcpu_vinotify_event: tstamp:36357346164 tag:CHANSEL_PXL_EOF channel:0x01 frame:35 vi_tstamp:36357345381 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.164886: rtcpu_vinotify_event: tstamp:36357346354 tag:ATOMP_FE channel:0x01 frame:35 vi_tstamp:36357345487 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.220829: rtcpu_vinotify_event: tstamp:36358056185 tag:ATOMP_FS channel:0x00 frame:36 vi_tstamp:36358055764 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.220863: rtcpu_vinotify_event: tstamp:36358058925 tag:CHANSEL_PXL_SOF channel:0x00 frame:36 vi_tstamp:36358058526 data:0x00000001
 kworker/0:3-6620  [000] ....  1154.220865: rtcpu_vinotify_event: tstamp:36358278028 tag:CHANSEL_PXL_EOF channel:0x02 frame:35 vi_tstamp:36358277244 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.220867: rtcpu_vinotify_event: tstamp:36358278219 tag:ATOMP_FE channel:0x02 frame:35 vi_tstamp:36358277351 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.220870: rtcpu_vinotify_event: tstamp:36359059188 tag:CHANSEL_PXL_EOF channel:0x00 frame:36 vi_tstamp:36359058407 data:0x04370002
 kworker/0:3-6620  [000] ....  1154.220872: rtcpu_vinotify_event: tstamp:36359059378 tag:ATOMP_FE channel:0x00 frame:36 vi_tstamp:36359058514 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.276765: rtcpu_vinotify_event: tstamp:36359468182 tag:ATOMP_FS channel:0x01 frame:36 vi_tstamp:36359467770 data:0x00000000
 kworker/0:3-6620  [000] ....  1154.276836: rtcpu_vinotify_event: tstamp:36359470930 tag:CHANSEL_PXL_SOF channel:0x01 frame:36 vi_tstamp:36359470532 data:0x00000001

ShaneCCC · June 1, 2021, 3:25am

Did you confirm all of them without applying the patch?

jhbaek · June 1, 2021, 5:48am

Yes, without this patch, it works fine.

vi4_fops.c …
/*
* Wait for PXL_SOF syncpt
*
* Use the syncpt max value we just set as threshold
/
for (i = 0; i < chan->valid_ports; i++) {
err = nvhost_syncpt_wait_timeout_ext(chan->vi->ndev,
#if 0 **
// This is original source code. timestamp is OK.
** chan->syncpt[i][SOF_SYNCPT_IDX], thresh[i],
#else
// This is a portion of the low latency patch. timestamp is NOT OK.
** chan->syncpt[i][FE_SYNCPT_IDX], thresh[i],*
#endif
chan->timeout, NULL, NULL);
if (unlikely(err)) {
dev_err(chan->vi->dev,
“PXL_SOF syncpt timeout! err = %d\n”, err);
return false;
} else {
struct vi_capture_status status;
…

ShaneCCC · June 1, 2021, 7:10am

Remove the REG write of SW_RESET* in the csi4_phy_config() to try.

jhbaek · June 1, 2021, 7:34am

I tried that, but the result is not fine.

remove “SW_RESET*_EN” => ch0 timestamp is OK. ch1 ~ 5 timestamp failed.
remove “SW_RESET*_EN” and “NVCSI_CIL_A_SW_RESET” “NVCSI_CIL_B_SW_RESET” => ch0 ~ ch5 timestamp failed

QUESTION 1. Is this known issue?
QUESTION 2. Is there an official patch?

ShaneCCC · June 1, 2021, 8:05am

No, the patch for latency is customize patch not office release patch so it’s not know issue and didn’t have patch now.

ShaneCCC · June 1, 2021, 8:32am

Have a try this patch.

diff --git a/drivers/media/platform/tegra/camera/vi/vi4_fops.c b/drivers/media/platform/tegra/camera/vi/vi4_fops.c
index 7b19eb1..5ffe649 100644
--- a/drivers/media/platform/tegra/camera/vi/vi4_fops.c
+++ b/drivers/media/platform/tegra/camera/vi/vi4_fops.c
@@ -228,7 +233,7 @@ static bool vi_notify_wait(struct tegra_channel *chan,
                                dev_err(chan->vi->dev,
                                        "no capture status! err = %d\n", err);
                        else {
-                               *ts = ns_to_timespec((s64)status.sof_ts);
+                               *ts = ns_to_timespec((s64)status.eof_ts);

                                dev_dbg(&chan->video->dev,
                                        "%s: vi4 got SOF syncpt buf[%p]\n",