[linux-uvc-devel] Bad capture timestamp conversion

[Pavel K. <kys...@in...>]

Hi!

I use a Microsoft LifeCam Cinema camera connected to a Raspberry Pi 4B
board to capture YUV frames, and wish to have PTS timestamps in my
application, instead of system clock samples quantized at the URB
boundary (~4 ms). Enabling the hwtimestamps parameter puts into
service the sophisticated clock conversion code that resides in the
uvc_video_clock_update function, but resulting timestamps look
somewhat weird. To say the least, timestamps for successive frames are
not monotonic.

uname -a
Linux raspberrypi 5.10.63-v7l+ #1459 SMP Wed Oct 6 16:41:57 BST 2021
armv7l GNU/Linux

lsusb
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 003: ID 045e:075d Microsoft Corp. LifeCam Cinema
Bus 001 Device 002: ID 2109:3431 VIA Labs, Inc. Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
<Output of lsusb -d 045e:075d -v attached in lsusb.txt>

modinfo uvcvideo
version:        1.1.1
<full response attached in modinfo.txt>

Here is a piece of uvcvideo trace for a few seconds session (full log
attached in dmesg.txt)

[ 1490.494279] uvcvideo: Frame complete (EOF found).
[ 1490.494314] uvcvideo: frame 62 stats: 23/244/267 packets, 1/4/267
pts (early initial), 266/267 scr, last pts/stc/sof
4171438061/623018987/1826
[ 1490.494433] uvcvideo: uvc_v4l2_poll
[ 1490.494538] uvcvideo: Microsoft® LifeCam Cinema(TM):: PTS
4171438061 y 302681263.118759 SOF 36015.118759 (x1 2893195733 x2
2894125607 y1 252116992 y2 254148608 SOF offset 0)
[ 1490.494552] uvcvideo: Microsoft® LifeCam Cinema(TM):: SOF
33967.118759 y 31188972826 ts 1520632885720 buf ts 1490435939653 (x1
252313600/1802/1799 x2 254148608/1830/1830 y1 1000000000 y2
1028066803)
[ 1490.496271] uvcvideo: uvc_v4l2_poll
[ 1490.526238] uvcvideo: Frame complete (EOF found).
[ 1490.526270] uvcvideo: frame 63 stats: 23/244/267 packets, 1/4/267
pts (early initial), 266/267 scr, last pts/stc/sof
4172438005/624020101/1860
[ 1490.526477] uvcvideo: uvc_v4l2_poll
[ 1490.526536] uvcvideo: Microsoft® LifeCam Cinema(TM):: PTS
4172438005 y 302681296.454742 SOF 36048.454742 (x1 2893155659 x2
2894085533 y1 254214144 y2 256245760 SOF offset 0)
[ 1490.526550] uvcvideo: Microsoft® LifeCam Cinema(TM):: SOF
34000.454742 y 31118682782 ts 1520594607878 buf ts 1490471949068 (x1
254410752/1834/1831 x2 256245760/1862/1862 y1 1000000000 y2
1028000212)

Please note that the ts field of the last trace message for frame 63
holds 1520594607878, that is less than frame 62's ts=1520632885720.
usbmon and uvcvideo traces show that the camera uses a 30 MHz clock
for PTS/SCR samples, and I haven't noticed any anomalies in these
fields of stream headers. In the log fragment above, the difference
between PTS values equals 4172438005-4171438061=999944, that is 33.33
ms @30 MHz, matching the capturing rate of 30 FPS. Trace fields
related to dev_sof also look reliable, unlike the reconstructed values
of SOF and ts.

Raspberry Pi 4B has both the USB 2 and 3 ports, the problem holds for
both options (the log was recorded for the former).

Could you please comment on this?

Thank you so much for your great work!

P.S. I'm sorry for my fault with cluttering the mailing list with HTML
in the previous message.