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
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
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)
