Problem with uvcvideo timestamps

* Problem with uvcvideo timestamps
@ 2016-10-31 13:42 Niels Möller
  2016-12-16 22:08 ` Guennadi Liakhovetski
  2016-12-30 13:06 ` Laurent Pinchart
  0 siblings, 2 replies; 3+ messages in thread
From: Niels Möller @ 2016-10-31 13:42 UTC (permalink / raw)
  To: linux-media

[-- Attachment #1: Type: text/plain, Size: 3403 bytes --]

Hi,

I'm tracking down a problem in Chrome, where video streams captured
from a Logitech c930e camera get bogus timestamps. Chrome started
using camera timestamps on linux a few months ago. I've noted commit

  https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=5d0fd3c806b9e932010931ae67dbb482020e0882

  "[media] uvcvideo: Disable hardware timestamps by default"

but I'm running with a kernel which doesn't have that change.

First, let me say that for our purposes, the hairy syncing to the
"SOF" clock done by uvc_video_clock_update is not that useful.
Ideally, I would prefer if the v4l2_buffer of a captured frame
included both

  * untranslated pts timestamp from the camera device (if I've
    understood this correctly, and there is a pts sent over the wire),
    and

  * the value of system monotonic clock at the point when the frame
    was received by the kernel.

Is there any reasonable way to get this information out from the
driver? We could then do estimation of the camera's epoch and clock
drift in the application. The raw pts is the most important piece of
information.

Second, I'd like to try to provide some logs to help track down the
bug. To reproduce, I'm using the example program at
https://gist.github.com/maxlapshin/1253534, modified to print out
camera timestamp and gettimeofday for each frame. Log attached as
time-2.log.

I also enabled tracing of the clock translation logic using

  echo 4096 > /sys/module/uvcvideo/parameters/trace

The corresponding kernel log messages are attached as trace-2.log.

In time-2.log (i.e., the application log), I see that camera
timestamps move backwards in time,

  TIMESTAMP_MONOTONIC
     cam: 2321521.085372
     sys: 1477913910.983620
  TIMESTAMP_MONOTONIC
     cam: 2321520.879272
     sys: 1477913911.051628

In trace-2.log (i.e., kernel log messages) I see

  uvcvideo: Logitech Webcam C930e: PTS 219483992 y 4084.798004 SOF
4084.798004 (x1 2064310082 x2 2148397132 y1 218759168 y2 268238848 SOF
offset 170)
  uvcvideo: Logitech Webcam C930e: SOF 4084.798004 y 3105900702 ts
2321520.879272 buf ts 2321521.153372 (x1 218759168/1546/1290 x2
274071552/1878/2045 y1 1000000000 y2 3380001263)
  uvcvideo: Logitech Webcam C930e: PTS 221480532 y 4156.709564 SOF
4156.709564 (x1 2079524156 x2 2148397450 y1 256376832 y2 272629760 SOF
offset 170)
  uvcvideo: Logitech Webcam C930e: SOF 4156.709564 y 2453257742 ts
2321520.378627 buf ts 2321521.217373 (x1 262275072/1698/1864 x2
278265856/1942/64 y1 1000000000 y2 3292003672)
  uvcvideo: Logitech Webcam C930e: PTS 223477044 y 4223.428085 SOF
4223.428085 (x1 2081269216 x2 2148397122 y1 264568832 y2 276955136 SOF
offset 170)
  uvcvideo: Logitech Webcam C930e: SOF 2175.428085 y 2158773894 ts
2321520.208143 buf ts 2321521.285373 (x1 136183808/1822/1989 x2
148504576/2010/130 y1 1000000000 y2 3236003012)

I don't know the details of the usb protocol, but it looks like the
"SOF" value is usually increasing. But close to the bogus output
timestamp of 2321520.879272, it goes through some kind of wraparound,
with the sequence of values

  4156.709564
  4223.428085
  2175.428085    # 2048 less than previous value
  2243.169921

I hope the attached logs provide enough information to analyze where
uvc_video_clock_update gets this wrong.

Best regards,
/Niels Möller

[-- Attachment #2: time-2.log --]
[-- Type: text/x-log, Size: 3451 bytes --]

TIMESTAMP_MONOTONIC
   cam: 2321518.773372
   sys: 1477913908.671607
TIMESTAMP_MONOTONIC
   cam: 2321518.925369
   sys: 1477913908.823594
TIMESTAMP_MONOTONIC
   cam: 2321519.049369
   sys: 1477913908.947600
TIMESTAMP_MONOTONIC
   cam: 2321519.173370
   sys: 1477913909.071610
TIMESTAMP_MONOTONIC
   cam: 2321519.297369
   sys: 1477913909.195603
TIMESTAMP_MONOTONIC
   cam: 2321519.421370
   sys: 1477913909.319607
TIMESTAMP_MONOTONIC
   cam: 2321519.489369
   sys: 1477913909.387594
TIMESTAMP_MONOTONIC
   cam: 2321519.553370
   sys: 1477913909.455586
TIMESTAMP_MONOTONIC
   cam: 2321519.621369
   sys: 1477913909.519601
TIMESTAMP_MONOTONIC
   cam: 2321519.689369
   sys: 1477913909.587594
TIMESTAMP_MONOTONIC
   cam: 2321519.753370
   sys: 1477913909.655587
TIMESTAMP_MONOTONIC
   cam: 2321519.821370
   sys: 1477913909.719600
TIMESTAMP_MONOTONIC
   cam: 2321519.889370
   sys: 1477913909.787594
TIMESTAMP_MONOTONIC
   cam: 2321519.953371
   sys: 1477913909.855585
TIMESTAMP_MONOTONIC
   cam: 2321520.021370
   sys: 1477913909.919602
TIMESTAMP_MONOTONIC
   cam: 2321520.089370
   sys: 1477913909.987594
TIMESTAMP_MONOTONIC
   cam: 2321520.153370
   sys: 1477913910.051609
TIMESTAMP_MONOTONIC
   cam: 2321520.221371
   sys: 1477913910.119597
TIMESTAMP_MONOTONIC
   cam: 2321520.289371
   sys: 1477913910.187599
TIMESTAMP_MONOTONIC
   cam: 2321520.353371
   sys: 1477913910.251609
TIMESTAMP_MONOTONIC
   cam: 2321520.421371
   sys: 1477913910.319597
TIMESTAMP_MONOTONIC
   cam: 2321520.485372
   sys: 1477913910.387588
TIMESTAMP_MONOTONIC
   cam: 2321520.553371
   sys: 1477913910.451604
TIMESTAMP_MONOTONIC
   cam: 2321520.621371
   sys: 1477913910.519595
TIMESTAMP_MONOTONIC
   cam: 2321520.685372
   sys: 1477913910.587588
TIMESTAMP_MONOTONIC
   cam: 2321520.753372
   sys: 1477913910.651603
TIMESTAMP_MONOTONIC
   cam: 2321520.821374
   sys: 1477913910.719595
TIMESTAMP_MONOTONIC
   cam: 2321520.885372
   sys: 1477913910.783609
TIMESTAMP_MONOTONIC
   cam: 2321520.953372
   sys: 1477913910.851600
TIMESTAMP_MONOTONIC
   cam: 2321521.021373
   sys: 1477913910.919602
TIMESTAMP_MONOTONIC
   cam: 2321521.085372
   sys: 1477913910.983620
TIMESTAMP_MONOTONIC
   cam: 2321520.879272
   sys: 1477913911.051628
TIMESTAMP_MONOTONIC
   cam: 2321520.378627
   sys: 1477913911.119605
TIMESTAMP_MONOTONIC
   cam: 2321520.208143
   sys: 1477913911.183618
TIMESTAMP_MONOTONIC
   cam: 2321519.853297
   sys: 1477913911.251609
TIMESTAMP_MONOTONIC
   cam: 2321518.824851
   sys: 1477913911.319600
TIMESTAMP_MONOTONIC
   cam: 2339102.290838
   sys: 1477913911.383615
TIMESTAMP_MONOTONIC
   cam: 2339102.229837
   sys: 1477913911.451608
TIMESTAMP_MONOTONIC
   cam: 2339102.551836
   sys: 1477913911.515624
TIMESTAMP_MONOTONIC
   cam: 2339102.490836
   sys: 1477913911.583612
TIMESTAMP_MONOTONIC
   cam: 2339102.300828
   sys: 1477913911.651606
TIMESTAMP_MONOTONIC
   cam: 2339102.751845
   sys: 1477913911.715622
TIMESTAMP_MONOTONIC
   cam: 2339102.561836
   sys: 1477913911.783616
TIMESTAMP_MONOTONIC
   cam: 2344963.396051
   sys: 1477913911.851603
TIMESTAMP_MONOTONIC
   cam: 2339102.822847
   sys: 1477913911.915622
TIMESTAMP_MONOTONIC
   cam: 2339102.761838
   sys: 1477913911.983610
TIMESTAMP_MONOTONIC
   cam: 2344963.424407
   sys: 1477913912.051601
TIMESTAMP_MONOTONIC
   cam: 2339103.022836
   sys: 1477913912.115625
TIMESTAMP_MONOTONIC
   cam: 2339102.961835
   sys: 1477913912.183607
TIMESTAMP_MONOTONIC
   cam: 2344963.624403
   sys: 1477913912.247627

[-- Attachment #3: trace-2.log --]
[-- Type: text/x-log, Size: 8733 bytes --]

Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.139789] uvcvideo: Logitech Webcam C930e: PTS 219483992 y 4084.798004 SOF 4084.798004 (x1 2064310082 x2 2148397132 y1 218759168 y2 268238848 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.139798] uvcvideo: Logitech Webcam C930e: SOF 4084.798004 y 3105900702 ts 2321520.879272 buf ts 2321521.153372 (x1 218759168/1546/1290 x2 274071552/1878/2045 y1 1000000000 y2 3380001263)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.207811] uvcvideo: Logitech Webcam C930e: PTS 221480532 y 4156.709564 SOF 4156.709564 (x1 2079524156 x2 2148397450 y1 256376832 y2 272629760 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.207817] uvcvideo: Logitech Webcam C930e: SOF 4156.709564 y 2453257742 ts 2321520.378627 buf ts 2321521.217373 (x1 262275072/1698/1864 x2 278265856/1942/64 y1 1000000000 y2 3292003672)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.271864] uvcvideo: Logitech Webcam C930e: PTS 223477044 y 4223.428085 SOF 4223.428085 (x1 2081269216 x2 2148397122 y1 264568832 y2 276955136 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.271869] uvcvideo: Logitech Webcam C930e: SOF 2175.428085 y 2158773894 ts 2321520.208143 buf ts 2321521.285373 (x1 136183808/1822/1989 x2 148504576/2010/130 y1 1000000000 y2 3236003012)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.339896] uvcvideo: Logitech Webcam C930e: PTS 225473576 y 2243.169921 SOF 2243.169921 (x1 2083014438 x2 2148397042 y1 138543104 y2 147128320 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.339902] uvcvideo: Logitech Webcam C930e: SOF 2243.169921 y 1679928413 ts 2321519.853297 buf ts 2321521.353373 (x1 144310272/1946/66 x2 152961024/30/197 y1 1000000000 y2 3180002937)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.407928] uvcvideo: Logitech Webcam C930e: PTS 227470098 y 2309.952255 SOF 2309.952255 (x1 2084759516 x2 2148397014 y1 146669568 y2 151453696 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.407934] uvcvideo: Logitech Webcam C930e: SOF 2309.952255 y 527482167 ts 2321518.824851 buf ts 2321521.417373 (x1 152436736/22/190 x2 157155328/94/263 y1 1000000000 y2 3120004056)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.471983] uvcvideo: Logitech Webcam C930e: PTS 229466616 y 2377.778594 SOF 2377.778594 (x1 2086504596 x2 2148397146 y1 154861568 y2 155844608 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.471989] uvcvideo: Logitech Webcam C930e: SOF 2377.778594 y 17583869468519 ts 2339102.290838 buf ts 2321521.485373 (x1 160563200/146/315 x2 161611776/162/330 y1 1000000000 y2 3064003245)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.540017] uvcvideo: Logitech Webcam C930e: PTS 231463156 y 2444.778625 SOF 2444.778625 (x1 2086504762 x2 2148397040 y1 159252480 y2 160235520 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.540023] uvcvideo: Logitech Webcam C930e: SOF 2444.778625 y 17583740468189 ts 2339102.229837 buf ts 2321521.553373 (x1 165019648/214/382 x2 166068224/230/397 y1 1000000000 y2 3064004133)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.604072] uvcvideo: Logitech Webcam C930e: PTS 233459666 y 2510.778625 SOF 2510.778625 (x1 2086504614 x2 2148397058 y1 163577856 y2 164560896 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.604078] uvcvideo: Logitech Webcam C930e: SOF 2510.778625 y 17583998467549 ts 2339102.551836 buf ts 2321521.617374 (x1 169213952/278/448 x2 170262528/294/463 y1 1000000000 y2 3064004393)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.672103] uvcvideo: Logitech Webcam C930e: PTS 235456218 y 2577.778594 SOF 2577.778594 (x1 2086504694 x2 2148397162 y1 167968768 y2 168951808 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.672109] uvcvideo: Logitech Webcam C930e: SOF 2577.778594 y 17583869467242 ts 2339102.490836 buf ts 2321521.685373 (x1 173670400/346/515 x2 174718976/362/530 y1 1000000000 y2 3064003528)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.740137] uvcvideo: Logitech Webcam C930e: PTS 237452754 y 2643.778579 SOF 2643.778579 (x1 2086504812 x2 2148397220 y1 172294144 y2 173277184 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.740144] uvcvideo: Logitech Webcam C930e: SOF 2643.778579 y 17583611459558 ts 2339102.300828 buf ts 2321521.753374 (x1 178126848/414/581 x2 179175424/430/596 y1 1000000000 y2 3064004665)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.804193] uvcvideo: Logitech Webcam C930e: PTS 239449248 y 2710.778640 SOF 2710.778640 (x1 2086504620 x2 2148397004 y1 176685056 y2 177668096 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.804199] uvcvideo: Logitech Webcam C930e: SOF 2710.778640 y 17583998475504 ts 2339102.751845 buf ts 2321521.817374 (x1 182321152/478/648 x2 183369728/494/663 y1 1000000000 y2 3064003048)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.872227] uvcvideo: Logitech Webcam C930e: PTS 241445794 y 2776.778610 SOF 2776.778610 (x1 2086504686 x2 2148397110 y1 181010432 y2 181993472 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.872234] uvcvideo: Logitech Webcam C930e: SOF 2776.778610 y 17583740467461 ts 2339102.561836 buf ts 2321521.885374 (x1 186777600/546/714 x2 187826176/562/729 y1 1000000000 y2 3064003862)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.940258] uvcvideo: Logitech Webcam C930e: PTS 243442326 y 2843.778564 SOF 2843.778564 (x1 2086504734 x2 2148397298 y1 185401344 y2 186384384 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322941.940263] uvcvideo: Logitech Webcam C930e: SOF 2843.778564 y 23444506681223 ts 2344963.396051 buf ts 2321521.949375 (x1 191234048/614/781 x2 192020480/626/796 y1 1000000000 y2 3060005103)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322942.004315] uvcvideo: Logitech Webcam C930e: PTS 245438854 y 2909.778640 SOF 2909.778640 (x1 2086504736 x2 2148396996 y1 189726720 y2 190709760 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322942.004321] uvcvideo: Logitech Webcam C930e: SOF 2909.778640 y 17583869476808 ts 2339102.822847 buf ts 2321522.017374 (x1 195428352/678/847 x2 196476928/694/862 y1 1000000000 y2 3064002717)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322942.072345] uvcvideo: Logitech Webcam C930e: PTS 247435378 y 2976.778610 SOF 2976.778610 (x1 2086505016 x2 2148397094 y1 194117632 y2 195100672 SOF offset 170)
Oct 31 12:38:31 nisse.lul.corp.google.com kernel: [2322942.072351] uvcvideo: Logitech Webcam C930e: SOF 2976.778610 y 17583740467672 ts 2339102.761838 buf ts 2321522.085374 (x1 199884800/746/914 x2 200933376/762/929 y1 1000000000 y2 3064003816)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.140377] uvcvideo: Logitech Webcam C930e: PTS 249431908 y 3042.778625 SOF 3042.778625 (x1 2086504812 x2 2148397048 y1 198443008 y2 199426048 SOF offset 170)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.140383] uvcvideo: Logitech Webcam C930e: SOF 3042.778625 y 23444335036750 ts 2344963.424407 buf ts 2321522.149374 (x1 204341248/814/980 x2 205127680/826/995 y1 1000000000 y2 3060003166)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.204440] uvcvideo: Logitech Webcam C930e: PTS 251428450 y 3109.778640 SOF 3109.778640 (x1 2086504656 x2 2148397006 y1 202833920 y2 203816960 SOF offset 170)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.204447] uvcvideo: Logitech Webcam C930e: SOF 3109.778640 y 17583869466783 ts 2339103.022836 buf ts 2321522.217375 (x1 208535552/878/1047 x2 209584128/894/1062 y1 1000000000 y2 3064004938)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.272464] uvcvideo: Logitech Webcam C930e: PTS 253424968 y 3176.778579 SOF 3176.778579 (x1 2086504684 x2 2148397222 y1 207224832 y2 208207872 SOF offset 170)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.272470] uvcvideo: Logitech Webcam C930e: SOF 3176.778579 y 17583740464609 ts 2339102.961835 buf ts 2321522.285375 (x1 212992000/946/1114 x2 214040576/962/1129 y1 1000000000 y2 3064003625)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.336522] uvcvideo: Logitech Webcam C930e: PTS 255421492 y 3242.778625 SOF 3242.778625 (x1 2086504726 x2 2148397062 y1 211550208 y2 212533248 SOF offset 170)
Oct 31 12:38:32 nisse.lul.corp.google.com kernel: [2322942.336528] uvcvideo: Logitech Webcam C930e: SOF 3242.778625 y 23444335033065 ts 2344963.624403 buf ts 2321522.349374 (x1 217448448/1014/1180 x2 218234880/1026/1195 y1 1000000000 y2 3060003754)

^ permalink raw reply	[flat|nested] 3+ messages in thread