(bisected) Logitech C920 (uvcvideo) stutters since 3.9

(bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

Hi,

There is periodic stutter (seen in vlc, for example) since 3.9 where
the stream stops for around half a second every 3-5 seconds or so.
Bisecting points to 1b18e7a0be859911b22138ce27258687efc528b8 "v4l:
Tell user space we're using monotonic timestamps". I've verified the
problem is there on stock Ubuntu 14.04 kernel, 3.16.7 from kernel.org
and when using media_build.git . The commit does not revert on newer
kernels as that code changed, but checking out a commit before the one
mentioned gives properly working kernel.

I'm using Logitech C920 which can do h264 compression and playing the
video using vlc:
cvlc v4l2:///dev/video0:chroma=h264:width=1280:height=720

-- 
Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Sakari Ailus]

Hi Grazvydas,

On Sun, Nov 02, 2014 at 04:03:55AM +0200, Grazvydas Ignotas wrote:
> There is periodic stutter (seen in vlc, for example) since 3.9 where
> the stream stops for around half a second every 3-5 seconds or so.
> Bisecting points to 1b18e7a0be859911b22138ce27258687efc528b8 "v4l:
> Tell user space we're using monotonic timestamps". I've verified the
> problem is there on stock Ubuntu 14.04 kernel, 3.16.7 from kernel.org
> and when using media_build.git . The commit does not revert on newer
> kernels as that code changed, but checking out a commit before the one
> mentioned gives properly working kernel.
> 
> I'm using Logitech C920 which can do h264 compression and playing the
> video using vlc:
> cvlc v4l2:///dev/video0:chroma=h264:width=1280:height=720

I've got Logitech C270 here but I can't reproduce the problem. The frame
rate with the above command is really low, around 5. With a smaller
resolution it works quite smoothly. The reason might be that the pixel
format is still YUYV. The other option appears to be MJPG.

My vlc is of version 2.0.3 (Debian). Which one do you have, and does it use
libv4l2?

Have you tried with a different application to see if the problem persists?
If the cause of the stutter you described is this patch, it might be how
the information the flag provides is used in the user space.

-- 
Kind regards,

Sakari Ailus
e-mail: sakari.ailus@iki.fi	XMPP: sailus@retiisi.org.uk

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

Hi,

On Mon, Nov 3, 2014 at 12:57 AM, Sakari Ailus <sakari.ailus@iki.fi> wrote:
> Hi Grazvydas,
>
> On Sun, Nov 02, 2014 at 04:03:55AM +0200, Grazvydas Ignotas wrote:
>> There is periodic stutter (seen in vlc, for example) since 3.9 where
>> the stream stops for around half a second every 3-5 seconds or so.
>> Bisecting points to 1b18e7a0be859911b22138ce27258687efc528b8 "v4l:
>> Tell user space we're using monotonic timestamps". I've verified the
>> problem is there on stock Ubuntu 14.04 kernel, 3.16.7 from kernel.org
>> and when using media_build.git . The commit does not revert on newer
>> kernels as that code changed, but checking out a commit before the one
>> mentioned gives properly working kernel.
>>
>> I'm using Logitech C920 which can do h264 compression and playing the
>> video using vlc:
>> cvlc v4l2:///dev/video0:chroma=h264:width=1280:height=720
>
> I've got Logitech C270 here but I can't reproduce the problem. The frame
> rate with the above command is really low, around 5. With a smaller
> resolution it works quite smoothly. The reason might be that the pixel
> format is still YUYV. The other option appears to be MJPG.

I've tried lower resolution and YUYV with MJPG too, this has the same problem:
cvlc v4l2:///dev/video0:chroma=h264:width=320:height=240
cvlc v4l2:///dev/video0:chroma=yuyv:width=320:height=240

>
> My vlc is of version 2.0.3 (Debian). Which one do you have, and does it use
> libv4l2?

Mine is 2.1.4, my distro is Ubuntu 14.04. I can see libv4l2.so.0.0.0
in maps, but I have no idea what it's used for..

> Have you tried with a different application to see if the problem persists?

Tried mplayer and cheese now, and it seems they are not affected, so
it's an issue with vlc. I wonder why it doesn't like newer flags..

Ohwell, sorry for the noise.

-- 
Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Sakari Ailus]

Hi Grazvydas,

On Tue, Nov 04, 2014 at 01:16:03AM +0200, Grazvydas Ignotas wrote:
> Hi,
> 
> On Mon, Nov 3, 2014 at 12:57 AM, Sakari Ailus <sakari.ailus@iki.fi> wrote:
> > Hi Grazvydas,
> >
> > On Sun, Nov 02, 2014 at 04:03:55AM +0200, Grazvydas Ignotas wrote:
> >> There is periodic stutter (seen in vlc, for example) since 3.9 where
> >> the stream stops for around half a second every 3-5 seconds or so.
> >> Bisecting points to 1b18e7a0be859911b22138ce27258687efc528b8 "v4l:
> >> Tell user space we're using monotonic timestamps". I've verified the
> >> problem is there on stock Ubuntu 14.04 kernel, 3.16.7 from kernel.org
> >> and when using media_build.git . The commit does not revert on newer
> >> kernels as that code changed, but checking out a commit before the one
> >> mentioned gives properly working kernel.
> >>
> >> I'm using Logitech C920 which can do h264 compression and playing the
> >> video using vlc:
> >> cvlc v4l2:///dev/video0:chroma=h264:width=1280:height=720
> >
> > I've got Logitech C270 here but I can't reproduce the problem. The frame
> > rate with the above command is really low, around 5. With a smaller
> > resolution it works quite smoothly. The reason might be that the pixel
> > format is still YUYV. The other option appears to be MJPG.
> 
> I've tried lower resolution and YUYV with MJPG too, this has the same problem:
> cvlc v4l2:///dev/video0:chroma=h264:width=320:height=240
> cvlc v4l2:///dev/video0:chroma=yuyv:width=320:height=240
> 
> >
> > My vlc is of version 2.0.3 (Debian). Which one do you have, and does it use
> > libv4l2?
> 
> Mine is 2.1.4, my distro is Ubuntu 14.04. I can see libv4l2.so.0.0.0
> in maps, but I have no idea what it's used for..
> 
> > Have you tried with a different application to see if the problem persists?
> 
> Tried mplayer and cheese now, and it seems they are not affected, so
> it's an issue with vlc. I wonder why it doesn't like newer flags..
> 
> Ohwell, sorry for the noise.

I guess the newer VLC could indeed pay attention to the monotonic timestamp
flag. Remi, any idea?

-- 
Cheers,

Sakari Ailus
e-mail: sakari.ailus@iki.fi	XMPP: sailus@retiisi.org.uk

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Rémi Denis-Courmont]

Le 2014-11-04 14:58, Sakari Ailus a écrit :
>> > Have you tried with a different application to see if the problem 
>> persists?
>>
>> Tried mplayer and cheese now, and it seems they are not affected, so
>> it's an issue with vlc. I wonder why it doesn't like newer flags..
>>
>> Ohwell, sorry for the noise.
>
> I guess the newer VLC could indeed pay attention to the monotonic 
> timestamp
> flag. Remi, any idea?

VLC takes the kernel timestamp, if monotonic, since version 2.1. 
Otherwise, it generates its own inaccurate timestamp. So either that 
code is wrong, or the kernel timestamps are.

-- 
Rémi Denis-Courmont

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Paulo Assis]

I've add to change guvcview so that it now generates it's own
monotonic timestamps, kernel timestamps (uvcvideo at least), caused a
similar problem, e.g:
I would get a couple of frames with correct timestamps, then I would
get at least one with a value lower than the rest, this caused
playback to stutter.
I didn't had time to check the cause, but it has been like this for
quite some time now.

Regards,
Paulo

2014-11-04 12:42 GMT+00:00 Rémi Denis-Courmont <remi@remlab.net>:
> Le 2014-11-04 14:58, Sakari Ailus a écrit :
>>>
>>> > Have you tried with a different application to see if the problem
>>> > persists?
>>>
>>> Tried mplayer and cheese now, and it seems they are not affected, so
>>> it's an issue with vlc. I wonder why it doesn't like newer flags..
>>>
>>> Ohwell, sorry for the noise.
>>
>>
>> I guess the newer VLC could indeed pay attention to the monotonic
>> timestamp
>> flag. Remi, any idea?
>
>
> VLC takes the kernel timestamp, if monotonic, since version 2.1. Otherwise,
> it generates its own inaccurate timestamp. So either that code is wrong, or
> the kernel timestamps are.
>
> --
> Rémi Denis-Courmont
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-media" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Sakari Ailus]

Hi,

On Tue, Nov 04, 2014 at 03:02:58PM +0000, Paulo Assis wrote:
> I've add to change guvcview so that it now generates it's own
> monotonic timestamps, kernel timestamps (uvcvideo at least), caused a
> similar problem, e.g:
> I would get a couple of frames with correct timestamps, then I would
> get at least one with a value lower than the rest, this caused
> playback to stutter.
> I didn't had time to check the cause, but it has been like this for
> quite some time now.

Have you looked what kind of timestamps the device gives you? The uvc
devices provide their own hardware timestamps which the UVC driver uses. If
the device provides bad timestamps to the driver, the buffer timestamps
could end up being very wrong. I don't know if the driver tries to cope with
that. One thing to try would be to capture images with a program which
prints the buffer timestamps.

yavta does, for example, print both the monotonic timestamp from the buffer
and the time when the buffer has been dequeued:

<URL:http://git.ideasonboard.org/yavta.git>

	$ yavta -c /dev/video0

should do it. The first timestamp is the buffer timestamp, and the latter is
the one is taken when the buffer is dequeued (by yavta).

-- 
Kind regards,

Sakari Ailus
e-mail: sakari.ailus@iki.fi	XMPP: sailus@retiisi.org.uk

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Sakari Ailus]

Sakari Ailus wrote:
> yavta does, for example, print both the monotonic timestamp from the buffer
> and the time when the buffer has been dequeued:
> 
> <URL:http://git.ideasonboard.org/yavta.git>
> 
> 	$ yavta -c /dev/video0
> 
> should do it. The first timestamp is the buffer timestamp, and the latter is
> the one is taken when the buffer is dequeued (by yavta).

Removing the uvcvideo module and loading it again with trace=4096 before
capturing, and then kernel log would provide more useful information.

-- 
Sakari Ailus
sakari.ailus@iki.fi

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Paulo Assis]

Hi,

2014-11-04 23:32 GMT+00:00 Sakari Ailus <sakari.ailus@iki.fi>:
> Sakari Ailus wrote:
>> yavta does, for example, print both the monotonic timestamp from the buffer
>> and the time when the buffer has been dequeued:
>>
>> <URL:http://git.ideasonboard.org/yavta.git>
>>
>>       $ yavta -c /dev/video0
>>
>> should do it. The first timestamp is the buffer timestamp, and the latter is
>> the one is taken when the buffer is dequeued (by yavta).

I've done exaclty this with guvcview, and uvcvideo timestamps are
completly unreliable, in some devices they may have just a bit of
jitter, but in others, values go back and forth in time, making them
totally unusable.
Honestly I wouldn't trust device firmware to provide correct
timestamps, or at least I would have the driver perform a couple of
tests to make sure these are at least reasonable: within an expected
interval (maybe comparing it to a reference monotonic clock) or at the
very least making sure the current frame timestamp is not lower than
the previous one.

Regards,
Paulo

>
> Removing the uvcvideo module and loading it again with trace=4096 before
> capturing, and then kernel log would provide more useful information.
>
> --
> Sakari Ailus
> sakari.ailus@iki.fi

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Laurent Pinchart]

Hi Paulo,

On Wednesday 05 November 2014 10:13:45 Paulo Assis wrote:
> 2014-11-04 23:32 GMT+00:00 Sakari Ailus <sakari.ailus@iki.fi>:
> > Sakari Ailus wrote:
> >> yavta does, for example, print both the monotonic timestamp from the
> >> buffer and the time when the buffer has been dequeued:
> >> 
> >> <URL:http://git.ideasonboard.org/yavta.git>
> >> 
> >>       $ yavta -c /dev/video0
> >> 
> >> should do it. The first timestamp is the buffer timestamp, and the latter
> >> is the one is taken when the buffer is dequeued (by yavta).
> 
> I've done exaclty this with guvcview, and uvcvideo timestamps are completly
> unreliable, in some devices they may have just a bit of jitter, but in
> others, values go back and forth in time, making them totally unusable.
>
> Honestly I wouldn't trust device firmware to provide correct timestamps, or
> at least I would have the driver perform a couple of tests to make sure
> these are at least reasonable: within an expected interval (maybe comparing
> it to a reference monotonic clock) or at the very least making sure the
> current frame timestamp is not lower than the previous one.

I can add that to the uvcvideo driver, but I'd first like to find out whether 
the device timestamps are really unreliable, or if the problem comes from a 
bug in the driver's timestamp conversion code. Could you capture images using 
yavta with an unreliable device, with the uvcvideo trace parameter set to 
4096, and send me both the yavta log and the kernel log ? Let's start with a 
capture sequence of 50 to 100 images.

> > Removing the uvcvideo module and loading it again with trace=4096 before
> > capturing, and then kernel log would provide more useful information.

-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Paulo Assis]

Laurent,
see below yavta output and matching syslog

./yavta -c -s 800x600 -t 1/30 -f mjpeg /dev/video0
Device /dev/video0 opened.
Device `Logitech Webcam C930e' on `usb-0000:00:1a.7-1' is a video
output (without mplanes) device.
Video format set: MJPEG (47504a4d) 800x600 (stride 0) field none
buffer size 960000
Video format: MJPEG (47504a4d) 800x600 (stride 0) field none buffer size 960000
Current frame rate: 1/30
Setting frame rate to: 1/30
Frame rate set: 1/30
8 buffers requested.
length: 960000 offset: 0 timestamp type/source: mono/SoE
Buffer 0/0 mapped at address 0x7fa53d2a9000.
length: 960000 offset: 962560 timestamp type/source: mono/SoE
Buffer 1/0 mapped at address 0x7fa53c8d6000.
length: 960000 offset: 1925120 timestamp type/source: mono/SoE
Buffer 2/0 mapped at address 0x7fa53c7eb000.
length: 960000 offset: 2887680 timestamp type/source: mono/SoE
Buffer 3/0 mapped at address 0x7fa53c700000.
length: 960000 offset: 3850240 timestamp type/source: mono/SoE
Buffer 4/0 mapped at address 0x7fa53c615000.
length: 960000 offset: 4812800 timestamp type/source: mono/SoE
Buffer 5/0 mapped at address 0x7fa53c52a000.
length: 960000 offset: 5775360 timestamp type/source: mono/SoE
Buffer 6/0 mapped at address 0x7fa53c43f000.
length: 960000 offset: 6737920 timestamp type/source: mono/SoE
Buffer 7/0 mapped at address 0x7fa53c354000.
0 (0) [-] any 0 78126 B 1967.041984 1967.046007 199.243 fps ts mono/SoE
1 (1) [-] any 1 83867 B 1967.065982 1967.074017 41.670 fps ts mono/SoE
2 (2) [-] any 2 83019 B 1967.157974 1967.166002 10.871 fps ts mono/SoE
3 (3) [-] any 3 83772 B 1967.249978 1967.258003 10.869 fps ts mono/SoE
4 (4) [-] any 4 83973 B 1967.341976 1967.350002 10.870 fps ts mono/SoE
5 (5) [-] any 5 81903 B 1967.433974 1967.441996 10.870 fps ts mono/SoE
6 (6) [-] any 6 83112 B 1967.497976 1967.506003 15.625 fps ts mono/SoE
7 (7) [-] any 7 80714 B 1967.565975 1967.573998 14.706 fps ts mono/SoE
8 (0) [-] any 8 81568 B 1967.633973 1967.641990 14.706 fps ts mono/SoE
9 (1) [-] any 9 80797 B 1967.697971 1967.705999 15.625 fps ts mono/SoE
10 (2) [-] any 10 81242 B 1967.765972 1967.773996 14.706 fps ts mono/SoE
11 (3) [-] any 11 79881 B 1967.833971 1967.841984 14.706 fps ts mono/SoE
12 (4) [-] any 12 77947 B 1967.897969 1967.905998 15.625 fps ts mono/SoE
13 (5) [-] any 13 75779 B 1967.965969 1967.973987 14.706 fps ts mono/SoE
14 (6) [-] any 14 73720 B 1968.029969 1968.038008 15.625 fps ts mono/SoE
15 (7) [-] any 15 73671 B 1968.097969 1968.105995 14.706 fps ts mono/SoE
16 (0) [-] any 16 80507 B 1968.165969 1968.173989 14.706 fps ts mono/SoE
17 (1) [-] any 17 82505 B 1968.229969 1968.237999 15.625 fps ts mono/SoE
18 (2) [-] any 18 82640 B 1968.297966 1968.305990 14.707 fps ts mono/SoE
19 (3) [-] any 19 82676 B 1968.365969 1968.373987 14.705 fps ts mono/SoE
20 (4) [-] any 20 82802 B 1968.429967 1968.437996 15.625 fps ts mono/SoE
21 (5) [-] any 21 83523 B 1968.497967 1968.505992 14.706 fps ts mono/SoE
22 (6) [-] any 22 83774 B 1968.565964 1968.573980 14.707 fps ts mono/SoE
23 (7) [-] any 23 83678 B 1968.629966 1968.637992 15.625 fps ts mono/SoE
24 (0) [-] any 24 83627 B 1968.697964 1968.705985 14.706 fps ts mono/SoE
25 (1) [-] any 25 83675 B 1968.761965 1968.773978 15.625 fps ts mono/SoE
26 (2) [-] any 26 84022 B 1968.829965 1968.837991 14.706 fps ts mono/SoE
27 (3) [-] any 27 83861 B 1968.897963 1968.905984 14.706 fps ts mono/SoE
28 (4) [-] any 28 83859 B 1968.961962 1968.969995 15.625 fps ts mono/SoE
29 (5) [-] any 29 84127 B 1969.029964 1969.037988 14.705 fps ts mono/SoE
30 (6) [-] any 30 83975 B 1969.097963 1969.105980 14.706 fps ts mono/SoE
31 (7) [-] any 31 83942 B 1968.705930 1969.170007 -2.551 fps ts mono/SoE
32 (0) [-] any 32 84151 B 1966.942496 1969.238004 -0.567 fps ts mono/SoE
33 (1) [-] any 33 84063 B 1966.407386 1969.305995 -1.869 fps ts mono/SoE
34 (2) [-] any 34 83821 B 6363.417588 1969.370002 0.000 fps ts mono/SoE
35 (3) [-] any 35 83856 B 8999.957765 1969.437996 0.000 fps ts mono/SoE
36 (4) [-] any 36 83654 B 25405.275813 1969.505986 0.000 fps ts mono/SoE
37 (5) [-] any 37 83619 B 19546.239569 1969.570001 -0.000 fps ts mono/SoE
38 (6) [-] any 38 83257 B 19546.049575 1969.637995 -5.263 fps ts mono/SoE
39 (7) [-] any 39 83211 B 25405.475806 1969.702002 0.000 fps ts mono/SoE
40 (0) [-] any 40 83231 B 19546.310550 1969.769993 -0.000 fps ts mono/SoE
41 (1) [-] any 41 83172 B 19546.249539 1969.837989 -16.390 fps ts mono/SoE
42 (2) [-] any 42 83177 B 25405.504127 1969.901997 0.000 fps ts mono/SoE
43 (3) [-] any 43 83055 B 19546.510529 1969.969995 -0.000 fps ts mono/SoE
44 (4) [-] any 44 82520 B 19546.320540 1970.037985 -5.263 fps ts mono/SoE
45 (5) [-] any 45 80593 B 19546.771538 1970.101999 2.217 fps ts mono/SoE
46 (6) [-] any 46 77431 B 19546.710555 1970.169986 -16.398 fps ts mono/SoE
47 (7) [-] any 47 75963 B 25406.007835 1970.233994 0.000 fps ts mono/SoE
48 (0) [-] any 48 74591 B 19546.971544 1970.301993 -0.000 fps ts mono/SoE
49 (1) [-] any 49 74606 B 19546.781526 1970.369988 -5.263 fps ts mono/SoE
50 (2) [-] any 50 73896 B 25406.207845 1970.433995 0.000 fps ts mono/SoE
51 (3) [-] any 51 74192 B 19547.042536 1970.501990 -0.000 fps ts mono/SoE
52 (4) [-] any 52 75659 B 19546.981566 1970.569978 -16.402 fps ts mono/SoE
53 (5) [-] any 53 76690 B 25406.236134 1970.633989 0.000 fps ts mono/SoE
54 (6) [-] any 54 77414 B 19547.242545 1970.701984 -0.000 fps ts mono/SoE
55 (7) [-] any 55 78730 B 19547.181540 1970.769977 -16.392 fps ts mono/SoE
56 (0) [-] any 56 78034 B 19547.503556 1970.833988 3.105 fps ts mono/SoE
57 (1) [-] any 57 79526 B 19547.442546 1970.901984 -16.391 fps ts mono/SoE
58 (2) [-] any 58 79702 B 25406.739800 1970.965992 0.000 fps ts mono/SoE
59 (3) [-] any 59 79123 B 19547.703559 1971.033986 -0.000 fps ts mono/SoE
60 (4) [-] any 60 79122 B 19547.513551 1971.101980 -5.263 fps ts mono/SoE
61 (5) [-] any 61 80463 B 25406.939786 1971.165993 0.000 fps ts mono/SoE
62 (6) [-] any 62 81427 B 19547.774542 1971.233983 -0.000 fps ts mono/SoE


---//----
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.169995] uvcvideo:
Logitech Webcam C930e: PTS 2762404994 y 4519.375137 SOF 4519.375137
(x1 2073036234 x2 2148397214 y1 266141696 y2 296550400 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.170002] uvcvideo:
Logitech Webcam C930e: SOF 4519.375137 y 2663946718 ts 1968.705930 buf
ts 1969.161961 (x1 266141696/221/2013 x2 304414720/293/429 y1
1000000000 y2 3119977295)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.237992] uvcvideo:
Logitech Webcam C930e: PTS 2764401500 y 2542.380523 SOF 2542.380523
(x1 2083514520 x2 2148397346 y1 159186944 y2 166723584 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.237998] uvcvideo:
Logitech Webcam C930e: SOF 2542.380523 y 876513667 ts 1966.942496 buf
ts 1969.229962 (x1 167051264/245/381 x2 174653440/361/496 y1
1000000000 y2 3163980033)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.305981] uvcvideo:
Logitech Webcam C930e: PTS 2766398050 y 2608.731536 SOF 2608.731536
(x1 2084261310 x2 2148397740 y1 165216256 y2 171048960 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.305987] uvcvideo:
Logitech Webcam C930e: SOF 2608.731536 y 249412201 ts 1966.407386 buf
ts 1969.297961 (x1 173080576/337/473 x2 179109888/429/562 y1
1000000000 y2 3139986562)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.369989] uvcvideo:
Logitech Webcam C930e: PTS 2768394588 y 2676.063140 SOF 2676.063140
(x1 2085009256 x2 2148397262 y1 171180032 y2 175439872 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.369995] uvcvideo:
Logitech Webcam C930e: SOF 2676.063140 y 4397167610356 ts 6363.417588
buf ts 1969.361960 (x1 179109888/429/564 x2 183304192/493/629 y1
1000000000 y2 3111982460)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.437982] uvcvideo:
Logitech Webcam C930e: PTS 2770391078 y 2743.416503 SOF 2743.416503
(x1 2085757052 x2 2148397390 y1 177209344 y2 179830784 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.437989] uvcvideo:
Logitech Webcam C930e: SOF 2743.416503 y 7033615790108 ts 8999.957765
buf ts 1969.429961 (x1 185139200/521/656 x2 187760640/561/696 y1
1000000000 y2 3087984880)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.505973] uvcvideo:
Logitech Webcam C930e: PTS 2772387614 y 2809.778488 SOF 2809.778488
(x1 2086504990 x2 2148397582 y1 183173120 y2 184156160 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.505979] uvcvideo:
Logitech Webcam C930e: SOF 2809.778488 y 23438841839398 ts
25405.275813 buf ts 1969.493958 (x1 191168512/613/747 x2
191954944/625/762 y1 1000000000 y2 3059984364)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.569988] uvcvideo:
Logitech Webcam C930e: PTS 2774384164 y 2876.778503 SOF 2876.778503
(x1 2086505172 x2 2148397550 y1 187564032 y2 188547072 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.569994] uvcvideo:
Logitech Webcam C930e: SOF 2876.778503 y 17579741593849 ts
19546.239569 buf ts 1969.561957 (x1 195362816/677/814 x2
196411392/693/829 y1 1000000000 y2 3063981195)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.637982] uvcvideo:
Logitech Webcam C930e: PTS 2776380650 y 2942.778549 SOF 2942.778549
(x1 2086504900 x2 2148397350 y1 191889408 y2 192872448 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.637988] uvcvideo:
Logitech Webcam C930e: SOF 2942.778549 y 17579483600299 ts
19546.049575 buf ts 1969.629957 (x1 199819264/745/880 x2
200867840/761/895 y1 1000000000 y2 3063981467)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.701989] uvcvideo:
Logitech Webcam C930e: PTS 2778377196 y 3009.778503 SOF 3009.778503
(x1 2086504892 x2 2148397554 y1 196280320 y2 197263360 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.701995] uvcvideo:
Logitech Webcam C930e: SOF 3009.778503 y 23438841832859 ts
25405.475806 buf ts 1969.693958 (x1 204275712/813/947 x2
205062144/825/962 y1 1000000000 y2 3059985389)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.769980] uvcvideo:
Logitech Webcam C930e: PTS 2780373752 y 3075.778549 SOF 3075.778549
(x1 2086505152 x2 2148397324 y1 200605696 y2 201588736 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.769986] uvcvideo:
Logitech Webcam C930e: SOF 3075.778549 y 17579612579208 ts
19546.310550 buf ts 1969.761955 (x1 208470016/877/1013 x2
209518592/893/1028 y1 1000000000 y2 3063984498)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.837976] uvcvideo:
Logitech Webcam C930e: PTS 2782370262 y 3142.778564 SOF 3142.778564
(x1 2086504996 x2 2148397304 y1 204996608 y2 205979648 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.837982] uvcvideo:
Logitech Webcam C930e: SOF 3142.778564 y 17579483566644 ts
19546.249539 buf ts 1969.829959 (x1 212926464/945/1080 x2
213975040/961/1095 y1 1000000000 y2 3063986833)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.901984] uvcvideo:
Logitech Webcam C930e: PTS 2784366776 y 3208.778396 SOF 3208.778396
(x1 2086505046 x2 2148397978 y1 209321984 y2 210305024 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.901990] uvcvideo:
Logitech Webcam C930e: SOF 3208.778396 y 23438670155531 ts
25405.504127 buf ts 1969.893956 (x1 217382912/1013/1146 x2
218169344/1/1161 y1 1000000000 y2 3059984673)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.969981] uvcvideo:
Logitech Webcam C930e: PTS 2786363306 y 3275.778518 SOF 3275.778518
(x1 2086505170 x2 2148397476 y1 213712896 y2 214695936 SOF offset 138)
Nov  5 22:07:38 Cobra-desktop kernel: [ 1969.969987] uvcvideo:
Logitech Webcam C930e: SOF 3275.778518 y 17579612560054 ts
19546.510529 buf ts 1969.961956 (x1 221577216/53/1213 x2
222625792/69/1228 y1 1000000000 y2 3063986812)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.037972] uvcvideo:
Logitech Webcam C930e: PTS 2788359850 y 3341.778533 SOF 3341.778533
(x1 2086505350 x2 2148397414 y1 218038272 y2 219021312 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.037979] uvcvideo:
Logitech Webcam C930e: SOF 3341.778533 y 17579354571096 ts
19546.320540 buf ts 1970.029955 (x1 226033664/121/1279 x2
227082240/137/1294 y1 1000000000 y2 3063985704)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.101986] uvcvideo:
Logitech Webcam C930e: PTS 2790356358 y 3408.778518 SOF 3408.778518
(x1 2086504950 x2 2148397496 y1 222429184 y2 223412224 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.101992] uvcvideo:
Logitech Webcam C930e: SOF 3408.778518 y 17579741569189 ts
19546.771538 buf ts 1970.093954 (x1 230227968/185/1346 x2
231276544/201/1361 y1 1000000000 y2 3063985283)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.169973] uvcvideo:
Logitech Webcam C930e: PTS 2792352904 y 3475.778533 SOF 3475.778533
(x1 2086505102 x2 2148397408 y1 226820096 y2 227803136 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.169980] uvcvideo:
Logitech Webcam C930e: SOF 3475.778533 y 17579612586322 ts
19546.710555 buf ts 1970.161952 (x1 234684416/253/1413 x2
235732992/269/1428 y1 1000000000 y2 3063983117)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.233981] uvcvideo:
Logitech Webcam C930e: PTS 2794349426 y 3541.778564 SOF 3541.778564
(x1 2086505038 x2 2148397280 y1 231145472 y2 232128512 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.233987] uvcvideo:
Logitech Webcam C930e: SOF 3541.778564 y 23438841865772 ts
25406.007835 buf ts 1970.225952 (x1 239140864/321/1479 x2
239927296/333/1494 y1 1000000000 y2 3059982878)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.301979] uvcvideo:
Logitech Webcam C930e: PTS 2796345944 y 3608.778533 SOF 3608.778533
(x1 2086504980 x2 2148397402 y1 235536384 y2 236519424 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.301986] uvcvideo:
Logitech Webcam C930e: SOF 3608.778533 y 17579741575092 ts
19546.971544 buf ts 1970.293954 (x1 243335168/385/1546 x2
244383744/401/1561 y1 1000000000 y2 3063984679)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.369975] uvcvideo:
Logitech Webcam C930e: PTS 2798342492 y 3674.778518 SOF 3674.778518
(x1 2086505052 x2 2148397480 y1 239861760 y2 240844800 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.369981] uvcvideo:
Logitech Webcam C930e: SOF 3674.778518 y 17579483560493 ts
19546.781526 buf ts 1970.361953 (x1 247791616/453/1612 x2
248840192/469/1627 y1 1000000000 y2 3063986870)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.433983] uvcvideo:
Logitech Webcam C930e: PTS 2800339000 y 3741.778564 SOF 3741.778564
(x1 2086505020 x2 2148397320 y1 244252672 y2 245235712 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.433989] uvcvideo:
Logitech Webcam C930e: SOF 3741.778564 y 23438841876629 ts
25406.207845 buf ts 1970.425951 (x1 252248064/521/1679 x2
253034496/533/1694 y1 1000000000 y2 3059981663)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.501978] uvcvideo:
Logitech Webcam C930e: PTS 2802335514 y 3807.778503 SOF 3807.778503
(x1 2086504998 x2 2148397556 y1 248578048 y2 249561088 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.501984] uvcvideo:
Logitech Webcam C930e: SOF 3807.778503 y 17579612569758 ts
19547.042536 buf ts 1970.493952 (x1 256442368/585/1745 x2
257490944/601/1760 y1 1000000000 y2 3063985037)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.569965] uvcvideo:
Logitech Webcam C930e: PTS 2804332058 y 3874.778533 SOF 3874.778533
(x1 2086505178 x2 2148397390 y1 252968960 y2 253952000 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.569972] uvcvideo:
Logitech Webcam C930e: SOF 3874.778533 y 17579483599493 ts
19546.981566 buf ts 1970.561949 (x1 260898816/653/1812 x2
261947392/669/1827 y1 1000000000 y2 3063981292)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.633976] uvcvideo:
Logitech Webcam C930e: PTS 2806328600 y 3940.778472 SOF 3940.778472
(x1 2086505510 x2 2148397640 y1 257294336 y2 258277376 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.633983] uvcvideo:
Logitech Webcam C930e: SOF 3940.778472 y 23438670170143 ts
25406.236134 buf ts 1970.625949 (x1 265355264/721/1878 x2
266141696/733/1893 y1 1000000000 y2 3059984505)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.701972] uvcvideo:
Logitech Webcam C930e: PTS 2808325118 y 4007.778503 SOF 4007.778503
(x1 2086504962 x2 2148397538 y1 261685248 y2 262668288 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.701979] uvcvideo:
Logitech Webcam C930e: SOF 1959.778503 y 17579612579235 ts
19547.242545 buf ts 1970.693950 (x1 135331840/785/1945 x2
136380416/801/1960 y1 1000000000 y2 3063983596)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.769964] uvcvideo:
Logitech Webcam C930e: PTS 2810321650 y 4074.778533 SOF 4074.778533
(x1 2086505356 x2 2148397434 y1 266076160 y2 267059200 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.769970] uvcvideo:
Logitech Webcam C930e: SOF 2026.778533 y 17579483577113 ts
19547.181540 buf ts 1970.761948 (x1 139788288/853/2012 x2
140836864/869/2027 y1 1000000000 y2 3063984663)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.833975] uvcvideo:
Logitech Webcam C930e: PTS 2812318162 y 2092.778579 SOF 2092.778579
(x1 2086504992 x2 2148397224 y1 136183808 y2 137166848 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.833981] uvcvideo:
Logitech Webcam C930e: SOF 2092.778579 y 17579741591308 ts
19547.503556 buf ts 1970.825948 (x1 143982592/917/30 x2
145031168/933/45 y1 1000000000 y2 3063983096)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.901972] uvcvideo:
Logitech Webcam C930e: PTS 2814314688 y 2159.778503 SOF 2159.778503
(x1 2086504946 x2 2148397560 y1 140574720 y2 141557760 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.901978] uvcvideo:
Logitech Webcam C930e: SOF 2159.778503 y 17579612581944 ts
19547.442546 buf ts 1970.893948 (x1 148439040/985/97 x2
149487616/1001/112 y1 1000000000 y2 3063983184)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.965979] uvcvideo:
Logitech Webcam C930e: PTS 2816311230 y 2225.778564 SOF 2225.778564
(x1 2086505120 x2 2148397300 y1 144900096 y2 145883136 SOF offset 138)
Nov  5 22:07:39 Cobra-desktop kernel: [ 1970.965986] uvcvideo:
Logitech Webcam C930e: SOF 2225.778564 y 23438841837341 ts
25406.739800 buf ts 1970.957949 (x1 152895488/29/163 x2
153681920/41/178 y1 1000000000 y2 3059986060)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.033973] uvcvideo:
Logitech Webcam C930e: PTS 2818307742 y 2292.778579 SOF 2292.778579
(x1 2086505052 x2 2148397240 y1 149291008 y2 150274048 SOF offset 138)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.033980] uvcvideo:
Logitech Webcam C930e: SOF 2292.778579 y 17579741596923 ts
19547.703559 buf ts 1971.025944 (x1 157089792/93/230 x2
158138368/109/245 y1 1000000000 y2 3063982234)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.101967] uvcvideo:
Logitech Webcam C930e: PTS 2820304272 y 2358.778503 SOF 2358.778503
(x1 2086505024 x2 2148397552 y1 153616384 y2 154599424 SOF offset 138)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.101973] uvcvideo:
Logitech Webcam C930e: SOF 2358.778503 y 17579483587576 ts
19547.513551 buf ts 1971.093946 (x1 161546240/161/296 x2
162594816/177/311 y1 1000000000 y2 3063982494)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.165980] uvcvideo:
Logitech Webcam C930e: PTS 2822300816 y 2425.778549 SOF 2425.778549
(x1 2086505156 x2 2148397368 y1 158007296 y2 158990336 SOF offset 138)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.165986] uvcvideo:
Logitech Webcam C930e: SOF 2425.778549 y 23438841823651 ts
25406.939786 buf ts 1971.157950 (x1 166002688/229/363 x2
166789120/241/378 y1 1000000000 y2 3059987299)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.233970] uvcvideo:
Logitech Webcam C930e: PTS 2824297352 y 2491.778472 SOF 2491.778472
(x1 2086504856 x2 2148397660 y1 162332672 y2 163315712 SOF offset 138)
Nov  5 22:07:40 Cobra-desktop kernel: [ 1971.233976] uvcvideo:
Logitech Webcam C930e: SOF 2491.778472 y 17579612581033 ts
19547.774542 buf ts 1971.225944 (x1 170196992/293/429 x2
171245568/309/444 y1 1000000000 y2 3063982724)

--/--

As you can see from the yavta output timestamps are completly messed up.
I hope these logs are enough, I don't think I'll have time to test
anything else for the next coule of days.

Regards,
Paulo

2014-11-05 14:05 GMT+00:00 Laurent Pinchart <laurent.pinchart@ideasonboard.com>:
> Hi Paulo,
>
> On Wednesday 05 November 2014 10:13:45 Paulo Assis wrote:
>> 2014-11-04 23:32 GMT+00:00 Sakari Ailus <sakari.ailus@iki.fi>:
>> > Sakari Ailus wrote:
>> >> yavta does, for example, print both the monotonic timestamp from the
>> >> buffer and the time when the buffer has been dequeued:
>> >>
>> >> <URL:http://git.ideasonboard.org/yavta.git>
>> >>
>> >>       $ yavta -c /dev/video0
>> >>
>> >> should do it. The first timestamp is the buffer timestamp, and the latter
>> >> is the one is taken when the buffer is dequeued (by yavta).
>>
>> I've done exaclty this with guvcview, and uvcvideo timestamps are completly
>> unreliable, in some devices they may have just a bit of jitter, but in
>> others, values go back and forth in time, making them totally unusable.
>>
>> Honestly I wouldn't trust device firmware to provide correct timestamps, or
>> at least I would have the driver perform a couple of tests to make sure
>> these are at least reasonable: within an expected interval (maybe comparing
>> it to a reference monotonic clock) or at the very least making sure the
>> current frame timestamp is not lower than the previous one.
>
> I can add that to the uvcvideo driver, but I'd first like to find out whether
> the device timestamps are really unreliable, or if the problem comes from a
> bug in the driver's timestamp conversion code. Could you capture images using
> yavta with an unreliable device, with the uvcvideo trace parameter set to
> 4096, and send me both the yavta log and the kernel log ? Let's start with a
> capture sequence of 50 to 100 images.
>
>> > Removing the uvcvideo module and loading it again with trace=4096 before
>> > capturing, and then kernel log would provide more useful information.
>
> --
> Regards,
>
> Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Sakari Ailus]

Hi Paolo,

On Wed, Nov 05, 2014 at 10:13:45AM +0000, Paulo Assis wrote:
> Hi,
> 
> 2014-11-04 23:32 GMT+00:00 Sakari Ailus <sakari.ailus@iki.fi>:
> > Sakari Ailus wrote:
> >> yavta does, for example, print both the monotonic timestamp from the buffer
> >> and the time when the buffer has been dequeued:
> >>
> >> <URL:http://git.ideasonboard.org/yavta.git>
> >>
> >>       $ yavta -c /dev/video0
> >>
> >> should do it. The first timestamp is the buffer timestamp, and the latter is
> >> the one is taken when the buffer is dequeued (by yavta).
> 
> I've done exaclty this with guvcview, and uvcvideo timestamps are
> completly unreliable, in some devices they may have just a bit of
> jitter, but in others, values go back and forth in time, making them
> totally unusable.
> Honestly I wouldn't trust device firmware to provide correct
> timestamps, or at least I would have the driver perform a couple of
> tests to make sure these are at least reasonable: within an expected
> interval (maybe comparing it to a reference monotonic clock) or at the
> very least making sure the current frame timestamp is not lower than
> the previous one.

Using the hardware timestamps provides much better accuracy than the
software ones --- the real time capabilities of the USB aren't exactly the
same as on some other busses.

Freel free to try the follow-up patches; I've only compile tested them so
far.

It might be possible to add some heuristics to detect bad implementations
but perhaps we could simply flag them for now. If heuristics would be used,
then one would likely have a few bad timestamps every time the device is
accessed the first time anyway. Besides, the timestamp type changes as a
result.

I wonder what Laurent thinks. :-)

-- 
Kind regards,

Sakari Ailus
e-mail: sakari.ailus@iki.fi	XMPP: sailus@retiisi.org.uk

[RFC 1/2] uvc: Add a quirk flag for cameras that do not produce correct timestamps

[Sakari Ailus]

The UVC devices do produce hardware timestamps according to the spec, but
not all cameras implement it or implement it correctly. Add a quirk flag for
such devices, and use monotonic timestamp from the end of the frame instead.

Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
---
 drivers/media/usb/uvc/uvc_queue.c |  6 ++++--
 drivers/media/usb/uvc/uvc_video.c | 14 +++++++++++++-
 drivers/media/usb/uvc/uvcvideo.h  |  4 +++-
 3 files changed, 20 insertions(+), 4 deletions(-)

diff --git a/drivers/media/usb/uvc/uvc_queue.c b/drivers/media/usb/uvc/uvc_queue.c
index 6e92d20..3f6432f 100644
--- a/drivers/media/usb/uvc/uvc_queue.c
+++ b/drivers/media/usb/uvc/uvc_queue.c
@@ -141,7 +141,7 @@ static struct vb2_ops uvc_queue_qops = {
 };
 
 int uvc_queue_init(struct uvc_video_queue *queue, enum v4l2_buf_type type,
-		    int drop_corrupted)
+		   bool drop_corrupted, bool tstamp_eof)
 {
 	int ret;
 
@@ -152,7 +152,9 @@ int uvc_queue_init(struct uvc_video_queue *queue, enum v4l2_buf_type type,
 	queue->queue.ops = &uvc_queue_qops;
 	queue->queue.mem_ops = &vb2_vmalloc_memops;
 	queue->queue.timestamp_flags = V4L2_BUF_FLAG_TIMESTAMP_MONOTONIC
-		| V4L2_BUF_FLAG_TSTAMP_SRC_SOE;
+		| (tstamp_eof ? V4L2_BUF_FLAG_TSTAMP_SRC_EOF
+		   : V4L2_BUF_FLAG_TSTAMP_SRC_SOE);
+
 	ret = vb2_queue_init(&queue->queue);
 	if (ret)
 		return ret;
diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c
index df81b9c..f599112 100644
--- a/drivers/media/usb/uvc/uvc_video.c
+++ b/drivers/media/usb/uvc/uvc_video.c
@@ -382,6 +382,9 @@ uvc_video_clock_decode(struct uvc_streaming *stream, struct uvc_buffer *buf,
 	u16 host_sof;
 	u16 dev_sof;
 
+	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP)
+		return;
+
 	switch (data[1] & (UVC_STREAM_PTS | UVC_STREAM_SCR)) {
 	case UVC_STREAM_PTS | UVC_STREAM_SCR:
 		header_size = 12;
@@ -490,6 +493,9 @@ static int uvc_video_clock_init(struct uvc_streaming *stream)
 {
 	struct uvc_clock *clock = &stream->clock;
 
+	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP)
+		return 0;
+
 	spin_lock_init(&clock->lock);
 	clock->size = 32;
 
@@ -615,6 +621,11 @@ void uvc_video_clock_update(struct uvc_streaming *stream,
 	u32 rem;
 	u64 y;
 
+	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP) {
+		v4l2_get_timestamp(&v4l2_buf->timestamp);
+		return;
+	}
+
 	spin_lock_irqsave(&clock->lock, flags);
 
 	if (clock->count < clock->size)
@@ -1779,7 +1790,8 @@ int uvc_video_init(struct uvc_streaming *stream)
 	atomic_set(&stream->active, 0);
 
 	/* Initialize the video buffers queue. */
-	ret = uvc_queue_init(&stream->queue, stream->type, !uvc_no_drop_param);
+	ret = uvc_queue_init(&stream->queue, stream->type, !uvc_no_drop_param,
+			     stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP);
 	if (ret)
 		return ret;
 
diff --git a/drivers/media/usb/uvc/uvcvideo.h b/drivers/media/usb/uvc/uvcvideo.h
index 864ada7..89a638c 100644
--- a/drivers/media/usb/uvc/uvcvideo.h
+++ b/drivers/media/usb/uvc/uvcvideo.h
@@ -148,6 +148,7 @@
 #define UVC_QUIRK_PROBE_DEF		0x00000100
 #define UVC_QUIRK_RESTRICT_FRAME_RATE	0x00000200
 #define UVC_QUIRK_RESTORE_CTRLS_ON_INIT	0x00000400
+#define UVC_QUIRK_BAD_TIMESTAMP		0x00000800
 
 /* Format flags */
 #define UVC_FMT_FLAG_COMPRESSED		0x00000001
@@ -622,7 +623,8 @@ extern struct uvc_entity *uvc_entity_by_id(struct uvc_device *dev, int id);
 
 /* Video buffers queue management. */
 extern int uvc_queue_init(struct uvc_video_queue *queue,
-		enum v4l2_buf_type type, int drop_corrupted);
+		enum v4l2_buf_type type, bool drop_corrupted,
+		bool tstamp_eof);
 extern int uvc_alloc_buffers(struct uvc_video_queue *queue,
 		struct v4l2_requestbuffers *rb);
 extern void uvc_free_buffers(struct uvc_video_queue *queue);
-- 
2.1.0.231.g7484e3b

[RFC 2/2] uvc: Use UVC_QUIRK_BAD_TIMESTAMP quirk flag for Logitech C920

[Sakari Ailus]

Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>
---
 drivers/media/usb/uvc/uvc_driver.c | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/drivers/media/usb/uvc/uvc_driver.c b/drivers/media/usb/uvc/uvc_driver.c
index 7c8322d..3908e2f 100644
--- a/drivers/media/usb/uvc/uvc_driver.c
+++ b/drivers/media/usb/uvc/uvc_driver.c
@@ -2183,7 +2183,9 @@ static struct usb_device_id uvc_ids[] = {
 	  .bInterfaceClass	= USB_CLASS_VIDEO,
 	  .bInterfaceSubClass	= 1,
 	  .bInterfaceProtocol	= 0,
-	  .driver_info		= UVC_QUIRK_RESTORE_CTRLS_ON_INIT },
+	  .driver_info		= UVC_QUIRK_RESTORE_CTRLS_ON_INIT
+				| UVC_QUIRK_BAD_TIMESTAMP
+	},
 	/* Chicony CNF7129 (Asus EEE 100HE) */
 	{ .match_flags		= USB_DEVICE_ID_MATCH_DEVICE
 				| USB_DEVICE_ID_MATCH_INT_INFO,
-- 
2.1.0.231.g7484e3b

Re: [RFC 1/2] uvc: Add a quirk flag for cameras that do not produce correct timestamps

[Laurent Pinchart]

Hi Sakari,

On Wednesday 05 November 2014 18:12:33 Sakari Ailus wrote:
> The UVC devices do produce hardware timestamps according to the spec, but
> not all cameras implement it or implement it correctly. Add a quirk flag for
> such devices, and use monotonic timestamp from the end of the frame
> instead.
> 
> Signed-off-by: Sakari Ailus <sakari.ailus@linux.intel.com>

I don't think this is the right fix, as the problem seems to come from the 
driver, not from the camera. I've disabled hardware timestamps by default for 
now which should work around the problem until I find time to conduct a full 
investigation and fix it.

> ---
>  drivers/media/usb/uvc/uvc_queue.c |  6 ++++--
>  drivers/media/usb/uvc/uvc_video.c | 14 +++++++++++++-
>  drivers/media/usb/uvc/uvcvideo.h  |  4 +++-
>  3 files changed, 20 insertions(+), 4 deletions(-)
> 
> diff --git a/drivers/media/usb/uvc/uvc_queue.c
> b/drivers/media/usb/uvc/uvc_queue.c index 6e92d20..3f6432f 100644
> --- a/drivers/media/usb/uvc/uvc_queue.c
> +++ b/drivers/media/usb/uvc/uvc_queue.c
> @@ -141,7 +141,7 @@ static struct vb2_ops uvc_queue_qops = {
>  };
> 
>  int uvc_queue_init(struct uvc_video_queue *queue, enum v4l2_buf_type type,
> -		    int drop_corrupted)
> +		   bool drop_corrupted, bool tstamp_eof)
>  {
>  	int ret;
> 
> @@ -152,7 +152,9 @@ int uvc_queue_init(struct uvc_video_queue *queue, enum
> v4l2_buf_type type, queue->queue.ops = &uvc_queue_qops;
>  	queue->queue.mem_ops = &vb2_vmalloc_memops;
>  	queue->queue.timestamp_flags = V4L2_BUF_FLAG_TIMESTAMP_MONOTONIC
> -		| V4L2_BUF_FLAG_TSTAMP_SRC_SOE;
> +		| (tstamp_eof ? V4L2_BUF_FLAG_TSTAMP_SRC_EOF
> +		   : V4L2_BUF_FLAG_TSTAMP_SRC_SOE);
> +
>  	ret = vb2_queue_init(&queue->queue);
>  	if (ret)
>  		return ret;
> diff --git a/drivers/media/usb/uvc/uvc_video.c
> b/drivers/media/usb/uvc/uvc_video.c index df81b9c..f599112 100644
> --- a/drivers/media/usb/uvc/uvc_video.c
> +++ b/drivers/media/usb/uvc/uvc_video.c
> @@ -382,6 +382,9 @@ uvc_video_clock_decode(struct uvc_streaming *stream,
> struct uvc_buffer *buf, u16 host_sof;
>  	u16 dev_sof;
> 
> +	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP)
> +		return;
> +
>  	switch (data[1] & (UVC_STREAM_PTS | UVC_STREAM_SCR)) {
>  	case UVC_STREAM_PTS | UVC_STREAM_SCR:
>  		header_size = 12;
> @@ -490,6 +493,9 @@ static int uvc_video_clock_init(struct uvc_streaming
> *stream) {
>  	struct uvc_clock *clock = &stream->clock;
> 
> +	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP)
> +		return 0;
> +
>  	spin_lock_init(&clock->lock);
>  	clock->size = 32;
> 
> @@ -615,6 +621,11 @@ void uvc_video_clock_update(struct uvc_streaming
> *stream, u32 rem;
>  	u64 y;
> 
> +	if (stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP) {
> +		v4l2_get_timestamp(&v4l2_buf->timestamp);
> +		return;
> +	}
> +
>  	spin_lock_irqsave(&clock->lock, flags);
> 
>  	if (clock->count < clock->size)
> @@ -1779,7 +1790,8 @@ int uvc_video_init(struct uvc_streaming *stream)
>  	atomic_set(&stream->active, 0);
> 
>  	/* Initialize the video buffers queue. */
> -	ret = uvc_queue_init(&stream->queue, stream->type, !uvc_no_drop_param);
> +	ret = uvc_queue_init(&stream->queue, stream->type, !uvc_no_drop_param,
> +			     stream->dev->quirks & UVC_QUIRK_BAD_TIMESTAMP);
>  	if (ret)
>  		return ret;
> 
> diff --git a/drivers/media/usb/uvc/uvcvideo.h
> b/drivers/media/usb/uvc/uvcvideo.h index 864ada7..89a638c 100644
> --- a/drivers/media/usb/uvc/uvcvideo.h
> +++ b/drivers/media/usb/uvc/uvcvideo.h
> @@ -148,6 +148,7 @@
>  #define UVC_QUIRK_PROBE_DEF		0x00000100
>  #define UVC_QUIRK_RESTRICT_FRAME_RATE	0x00000200
>  #define UVC_QUIRK_RESTORE_CTRLS_ON_INIT	0x00000400
> +#define UVC_QUIRK_BAD_TIMESTAMP		0x00000800
> 
>  /* Format flags */
>  #define UVC_FMT_FLAG_COMPRESSED		0x00000001
> @@ -622,7 +623,8 @@ extern struct uvc_entity *uvc_entity_by_id(struct
> uvc_device *dev, int id);
> 
>  /* Video buffers queue management. */
>  extern int uvc_queue_init(struct uvc_video_queue *queue,
> -		enum v4l2_buf_type type, int drop_corrupted);
> +		enum v4l2_buf_type type, bool drop_corrupted,
> +		bool tstamp_eof);
>  extern int uvc_alloc_buffers(struct uvc_video_queue *queue,
>  		struct v4l2_requestbuffers *rb);
>  extern void uvc_free_buffers(struct uvc_video_queue *queue);

-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Laurent Pinchart]

Hi Sakari,

On Wednesday 05 November 2014 18:11:47 Sakari Ailus wrote:
> On Wed, Nov 05, 2014 at 10:13:45AM +0000, Paulo Assis wrote:
> > 2014-11-04 23:32 GMT+00:00 Sakari Ailus <sakari.ailus@iki.fi>:
> >> Sakari Ailus wrote:
> >>> yavta does, for example, print both the monotonic timestamp from the
> >>> buffer and the time when the buffer has been dequeued:
> >>> 
> >>> <URL:http://git.ideasonboard.org/yavta.git>
> >>> 
> >>>       $ yavta -c /dev/video0
> >>> 
> >>> should do it. The first timestamp is the buffer timestamp, and the
> >>> latter is the one is taken when the buffer is dequeued (by yavta).
> > 
> > I've done exaclty this with guvcview, and uvcvideo timestamps are
> > completly unreliable, in some devices they may have just a bit of
> > jitter, but in others, values go back and forth in time, making them
> > totally unusable.
> > Honestly I wouldn't trust device firmware to provide correct
> > timestamps, or at least I would have the driver perform a couple of
> > tests to make sure these are at least reasonable: within an expected
> > interval (maybe comparing it to a reference monotonic clock) or at the
> > very least making sure the current frame timestamp is not lower than
> > the previous one.
> 
> Using the hardware timestamps provides much better accuracy than the
> software ones --- the real time capabilities of the USB aren't exactly the
> same as on some other busses.
> 
> Freel free to try the follow-up patches; I've only compile tested them so
> far.
> 
> It might be possible to add some heuristics to detect bad implementations
> but perhaps we could simply flag them for now. If heuristics would be used,
> then one would likely have a few bad timestamps every time the device is
> accessed the first time anyway. Besides, the timestamp type changes as a
> result.
> 
> I wonder what Laurent thinks. :-)

I've been toying with the idea of a heuristic, but decided to delay the 
implementation until needed. I'd like to find the root cause of the issue 
first before deciding how to fix it.

-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Rémi Denis-Courmont]

Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
> Le 2014-11-04 14:58, Sakari Ailus a écrit :
> >> > Have you tried with a different application to see if the problem
> >> 
> >> persists?
> >> 
> >> Tried mplayer and cheese now, and it seems they are not affected, so
> >> it's an issue with vlc. I wonder why it doesn't like newer flags..
> >> 
> >> Ohwell, sorry for the noise.
> > 
> > I guess the newer VLC could indeed pay attention to the monotonic
> > timestamp
> > flag. Remi, any idea?
> 
> VLC takes the kernel timestamp, if monotonic, since version 2.1.
> Otherwise, it generates its own inaccurate timestamp. So either that
> code is wrong, or the kernel timestamps are.

>From a quick check with C920, the timestamps from the kernel are quite 
jittery, and but seem to follow a pattern. When requesting a 10 Hz frame rate, 
I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to 1/3 every 
approximately 2 seconds.

>From my user-space point of view, this is a kernel issue. The problem probably 
just manifests when both VLC and Linux versions support monotonic timestamps.

Whether the root cause is in the kernel, the device driver or the firmware, I 
can´t say.

-- 
Rémi Denis-Courmont
http://www.remlab.net/

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Laurent Pinchart]

Hi Rémi,

On Tuesday 04 November 2014 22:41:44 Rémi Denis-Courmont wrote:
> Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
> > Le 2014-11-04 14:58, Sakari Ailus a écrit :
> > >> > Have you tried with a different application to see if the problem
> > >> > persists?
> > >> 
> > >> Tried mplayer and cheese now, and it seems they are not affected, so
> > >> it's an issue with vlc. I wonder why it doesn't like newer flags..
> > >> 
> > >> Ohwell, sorry for the noise.
> > > 
> > > I guess the newer VLC could indeed pay attention to the monotonic
> > > timestamp flag. Remi, any idea?
> > 
> > VLC takes the kernel timestamp, if monotonic, since version 2.1.
> > Otherwise, it generates its own inaccurate timestamp. So either that
> > code is wrong, or the kernel timestamps are.
> 
> From a quick check with C920, the timestamps from the kernel are quite
> jittery, and but seem to follow a pattern. When requesting a 10 Hz frame
> rate, I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to
> 1/3 every approximately 2 seconds.
> 
> From my user-space point of view, this is a kernel issue. The problem
> probably just manifests when both VLC and Linux versions support monotonic
> timestamps.
> 
> Whether the root cause is in the kernel, the device driver or the firmware,
> I can´t say.

Would you be able to capture images from the C920 using yavta, with the 
uvcvideo trace parameter set to 4096, and send me both the yavta log and the 
kernel log ? Let's start with a capture sequence of 50 to 100 images.

-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart
<laurent.pinchart@ideasonboard.com> wrote:
> Hi Rémi,
>
> On Tuesday 04 November 2014 22:41:44 Rémi Denis-Courmont wrote:
>> Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
>> > Le 2014-11-04 14:58, Sakari Ailus a écrit :
>> > >> > Have you tried with a different application to see if the problem
>> > >> > persists?
>> > >>
>> > >> Tried mplayer and cheese now, and it seems they are not affected, so
>> > >> it's an issue with vlc. I wonder why it doesn't like newer flags..
>> > >>
>> > >> Ohwell, sorry for the noise.
>> > >
>> > > I guess the newer VLC could indeed pay attention to the monotonic
>> > > timestamp flag. Remi, any idea?
>> >
>> > VLC takes the kernel timestamp, if monotonic, since version 2.1.
>> > Otherwise, it generates its own inaccurate timestamp. So either that
>> > code is wrong, or the kernel timestamps are.
>>
>> From a quick check with C920, the timestamps from the kernel are quite
>> jittery, and but seem to follow a pattern. When requesting a 10 Hz frame
>> rate, I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to
>> 1/3 every approximately 2 seconds.
>>
>> From my user-space point of view, this is a kernel issue. The problem
>> probably just manifests when both VLC and Linux versions support monotonic
>> timestamps.
>>
>> Whether the root cause is in the kernel, the device driver or the firmware,
>> I can´t say.
>
> Would you be able to capture images from the C920 using yavta, with the
> uvcvideo trace parameter set to 4096, and send me both the yavta log and the
> kernel log ? Let's start with a capture sequence of 50 to 100 images.

I've done 2 captures, if that helps:
http://notaz.gp2x.de/tmp/c920_yavta/

The second one was done using low exposure setting, which allows
camera to achieve higher frame rate.

-- 
Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

On Thu, Nov 6, 2014 at 12:29 AM, Grazvydas Ignotas <notasas@gmail.com> wrote:
> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart
> <laurent.pinchart@ideasonboard.com> wrote:
>> Hi Rémi,
>>
>> On Tuesday 04 November 2014 22:41:44 Rémi Denis-Courmont wrote:
>>> Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
>>> > Le 2014-11-04 14:58, Sakari Ailus a écrit :
>>> > >> > Have you tried with a different application to see if the problem
>>> > >> > persists?
>>> > >>
>>> > >> Tried mplayer and cheese now, and it seems they are not affected, so
>>> > >> it's an issue with vlc. I wonder why it doesn't like newer flags..
>>> > >>
>>> > >> Ohwell, sorry for the noise.
>>> > >
>>> > > I guess the newer VLC could indeed pay attention to the monotonic
>>> > > timestamp flag. Remi, any idea?
>>> >
>>> > VLC takes the kernel timestamp, if monotonic, since version 2.1.
>>> > Otherwise, it generates its own inaccurate timestamp. So either that
>>> > code is wrong, or the kernel timestamps are.
>>>
>>> From a quick check with C920, the timestamps from the kernel are quite
>>> jittery, and but seem to follow a pattern. When requesting a 10 Hz frame
>>> rate, I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to
>>> 1/3 every approximately 2 seconds.
>>>
>>> From my user-space point of view, this is a kernel issue. The problem
>>> probably just manifests when both VLC and Linux versions support monotonic
>>> timestamps.
>>>
>>> Whether the root cause is in the kernel, the device driver or the firmware,
>>> I can´t say.
>>
>> Would you be able to capture images from the C920 using yavta, with the
>> uvcvideo trace parameter set to 4096, and send me both the yavta log and the
>> kernel log ? Let's start with a capture sequence of 50 to 100 images.
>
> I've done 2 captures, if that helps:
> http://notaz.gp2x.de/tmp/c920_yavta/
>
> The second one was done using low exposure setting, which allows
> camera to achieve higher frame rate.

So, has anyone had time to look at these?

Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Hans Verkuil]

On 11/17/14 16:36, Grazvydas Ignotas wrote:
> On Thu, Nov 6, 2014 at 12:29 AM, Grazvydas Ignotas <notasas@gmail.com> wrote:
>> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart
>> <laurent.pinchart@ideasonboard.com> wrote:
>>> Hi Rémi,
>>>
>>> On Tuesday 04 November 2014 22:41:44 Rémi Denis-Courmont wrote:
>>>> Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
>>>>> Le 2014-11-04 14:58, Sakari Ailus a écrit :
>>>>>>>> Have you tried with a different application to see if the problem
>>>>>>>> persists?
>>>>>>>
>>>>>>> Tried mplayer and cheese now, and it seems they are not affected, so
>>>>>>> it's an issue with vlc. I wonder why it doesn't like newer flags..
>>>>>>>
>>>>>>> Ohwell, sorry for the noise.
>>>>>>
>>>>>> I guess the newer VLC could indeed pay attention to the monotonic
>>>>>> timestamp flag. Remi, any idea?
>>>>>
>>>>> VLC takes the kernel timestamp, if monotonic, since version 2.1.
>>>>> Otherwise, it generates its own inaccurate timestamp. So either that
>>>>> code is wrong, or the kernel timestamps are.
>>>>
>>>> From a quick check with C920, the timestamps from the kernel are quite
>>>> jittery, and but seem to follow a pattern. When requesting a 10 Hz frame
>>>> rate, I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to
>>>> 1/3 every approximately 2 seconds.
>>>>
>>>> From my user-space point of view, this is a kernel issue. The problem
>>>> probably just manifests when both VLC and Linux versions support monotonic
>>>> timestamps.
>>>>
>>>> Whether the root cause is in the kernel, the device driver or the firmware,
>>>> I can´t say.
>>>
>>> Would you be able to capture images from the C920 using yavta, with the
>>> uvcvideo trace parameter set to 4096, and send me both the yavta log and the
>>> kernel log ? Let's start with a capture sequence of 50 to 100 images.
>>
>> I've done 2 captures, if that helps:
>> http://notaz.gp2x.de/tmp/c920_yavta/
>>
>> The second one was done using low exposure setting, which allows
>> camera to achieve higher frame rate.
> 
> So, has anyone had time to look at these?

Laurent is on vacation for one more week. So you'll have to wait until
he's back and has time to process his no doubt considerable pile of email.

If you haven't heard anything from him by the end of next week, then try
another ping just in case this got buried.

Regards,

	Hans

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Laurent Pinchart]

Hi Grazvydas,

On Thursday 06 November 2014 00:29:53 Grazvydas Ignotas wrote:
> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart wrote:
> > On Tuesday 04 November 2014 22:41:44 Rémi Denis-Courmont wrote:
> >> Le mardi 04 novembre 2014, 15:42:37 Rémi Denis-Courmont a écrit :
> >> > Le 2014-11-04 14:58, Sakari Ailus a écrit :
> >> > >> > Have you tried with a different application to see if the problem
> >> > >> > persists?
> >> > >> 
> >> > >> Tried mplayer and cheese now, and it seems they are not affected, so
> >> > >> it's an issue with vlc. I wonder why it doesn't like newer flags..
> >> > >> 
> >> > >> Ohwell, sorry for the noise.
> >> > > 
> >> > > I guess the newer VLC could indeed pay attention to the monotonic
> >> > > timestamp flag. Remi, any idea?
> >> > 
> >> > VLC takes the kernel timestamp, if monotonic, since version 2.1.
> >> > Otherwise, it generates its own inaccurate timestamp. So either that
> >> > code is wrong, or the kernel timestamps are.
> >> 
> >> From a quick check with C920, the timestamps from the kernel are quite
> >> jittery, and but seem to follow a pattern. When requesting a 10 Hz frame
> >> rate, I actually get a frame interval of about 8/9 (i.e. 89ms) jumping to
> >> 1/3 every approximately 2 seconds.
> >> 
> >> From my user-space point of view, this is a kernel issue. The problem
> >> probably just manifests when both VLC and Linux versions support
> >> monotonic timestamps.
> >> 
> >> Whether the root cause is in the kernel, the device driver or the
> >> firmware,
> >> I can´t say.
> > 
> > Would you be able to capture images from the C920 using yavta, with the
> > uvcvideo trace parameter set to 4096, and send me both the yavta log and
> > the kernel log ? Let's start with a capture sequence of 50 to 100 images.
>
> I've done 2 captures, if that helps:
> http://notaz.gp2x.de/tmp/c920_yavta/
> 
> The second one was done using low exposure setting, which allows
> camera to achieve higher frame rate.

Thank you for the log, they were very helpful. They revealed that the USB SOF 
(Start Of Frame) counter values on the device and host side are not in sync. 
The counters get incremented are very different rates. What USB controller are 
you using ?

-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

Hi,

On Fri, Dec 5, 2014 at 1:46 PM, Laurent Pinchart
<laurent.pinchart@ideasonboard.com> wrote:
> Hi Grazvydas,
>
> On Thursday 06 November 2014 00:29:53 Grazvydas Ignotas wrote:
>> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart wrote:
>> > Would you be able to capture images from the C920 using yavta, with the
>> > uvcvideo trace parameter set to 4096, and send me both the yavta log and
>> > the kernel log ? Let's start with a capture sequence of 50 to 100 images.
>>
>> I've done 2 captures, if that helps:
>> http://notaz.gp2x.de/tmp/c920_yavta/
>>
>> The second one was done using low exposure setting, which allows
>> camera to achieve higher frame rate.
>
> Thank you for the log, they were very helpful. They revealed that the USB SOF
> (Start Of Frame) counter values on the device and host side are not in sync.
> The counters get incremented are very different rates. What USB controller are
> you using ?

00:1d.7 USB controller: Intel Corporation NM10/ICH7 Family USB2 EHCI
Controller (rev 01) (prog-if 20 [EHCI])
        Subsystem: Micro-Star International Co., Ltd. [MSI] Device 7592
        Flags: bus master, medium devsel, latency 0, IRQ 23
        Memory at fe9fbc00 (32-bit, non-prefetchable) [size=1K]
        Capabilities: [50] Power Management version 2
        Capabilities: [58] Debug port: BAR=1 offset=00a0
        Kernel driver in use: ehci-pci

If it helps, I could try on an ARM board, currently don't have any
other x86 hardware around.

--
Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Laurent Pinchart]

Hi Grazvydas,

(CC'ing Paulo Assis)

On Saturday 06 December 2014 02:25:25 Grazvydas Ignotas wrote:
> On Fri, Dec 5, 2014 at 1:46 PM, Laurent Pinchart wrote:
> > On Thursday 06 November 2014 00:29:53 Grazvydas Ignotas wrote:
> >> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart wrote:
> >> > Would you be able to capture images from the C920 using yavta, with the
> >> > uvcvideo trace parameter set to 4096, and send me both the yavta log
> >> > and the kernel log ? Let's start with a capture sequence of 50 to 100
> >> > images.
> >> 
> >> I've done 2 captures, if that helps:
> >> http://notaz.gp2x.de/tmp/c920_yavta/
> >> 
> >> The second one was done using low exposure setting, which allows
> >> camera to achieve higher frame rate.
> > 
> > Thank you for the log, they were very helpful. They revealed that the USB
> > SOF (Start Of Frame) counter values on the device and host side are not
> > in sync. The counters get incremented are very different rates. What USB
> > controller are you using ?
> 
> 00:1d.7 USB controller: Intel Corporation NM10/ICH7 Family USB2 EHCI
> Controller (rev 01) (prog-if 20 [EHCI])
>         Subsystem: Micro-Star International Co., Ltd. [MSI] Device 7592
>         Flags: bus master, medium devsel, latency 0, IRQ 23
>         Memory at fe9fbc00 (32-bit, non-prefetchable) [size=1K]
>         Capabilities: [50] Power Management version 2
>         Capabilities: [58] Debug port: BAR=1 offset=00a0
>         Kernel driver in use: ehci-pci
> 
> If it helps, I could try on an ARM board, currently don't have any
> other x86 hardware around.

Actually the frequencies I've computed from the log are correct on the host
side but quite off on the device side. I'm puzzled.

The following patch allows accessing the contents of the clock data buffer
through debugfs. Would you be able to apply it and execute the following
steps ?

1. Load the uvcvideo module with the clock trace flag (0x1000) set.

2. Start capturing clock data.

while true; do
	cat /sys/kernel/debug/usb/uvcvideo/2-6/clocks ;
done > ~/samples.log

3. Capture 100 frames.

yavta -c100 > yavta.log

4. Stop the "while true" with ctrl-C.

5. Capture the uvcvideo stats.

cat /sys/kernel/debug/usb/uvcvideo/2-6/stats > stats.log

6. Capture the kernel log.

dmesg > dmesg.log

7. Send me all the log files.

>From 801372be5eeac86326bc7eb230783a4d2a491c2e Mon Sep 17 00:00:00 2001
From: Laurent Pinchart <laurent.pinchart@ideasonboard.com>
Date: Sun, 7 Dec 2014 17:02:05 +0200
Subject: [PATCH] uvcvideo: Expose clock samples through debugfs

Signed-off-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com>
---
 drivers/media/usb/uvc/uvc_debugfs.c | 71 ++++++++++++++++++++++++++++---------
 drivers/media/usb/uvc/uvc_video.c   | 44 +++++++++++++++++++++++
 drivers/media/usb/uvc/uvcvideo.h    |  5 +++
 3 files changed, 104 insertions(+), 16 deletions(-)

diff --git a/drivers/media/usb/uvc/uvc_debugfs.c b/drivers/media/usb/uvc/uvc_debugfs.c
index 14561a5..4013dc5 100644
--- a/drivers/media/usb/uvc/uvc_debugfs.c
+++ b/drivers/media/usb/uvc/uvc_debugfs.c
@@ -19,16 +19,37 @@
 #include "uvcvideo.h"
 
 /* -----------------------------------------------------------------------------
- * Statistics
+ * Common Helpers
  */
 
-#define UVC_DEBUGFS_BUF_SIZE	1024
+#define UVC_DEBUGFS_BUF_SIZE	2048
 
 struct uvc_debugfs_buffer {
 	size_t count;
 	char data[UVC_DEBUGFS_BUF_SIZE];
 };
 
+static ssize_t uvc_debugfs_read(struct file *file, char __user *user_buf,
+				size_t nbytes, loff_t *ppos)
+{
+	struct uvc_debugfs_buffer *buf = file->private_data;
+
+	return simple_read_from_buffer(user_buf, nbytes, ppos, buf->data,
+				       buf->count);
+}
+
+static int uvc_debugfs_release(struct inode *inode, struct file *file)
+{
+	kfree(file->private_data);
+	file->private_data = NULL;
+
+	return 0;
+}
+
+/* -----------------------------------------------------------------------------
+ * Statistics
+ */
+
 static int uvc_debugfs_stats_open(struct inode *inode, struct file *file)
 {
 	struct uvc_streaming *stream = inode->i_private;
@@ -44,29 +65,39 @@ static int uvc_debugfs_stats_open(struct inode *inode, struct file *file)
 	return 0;
 }
 
-static ssize_t uvc_debugfs_stats_read(struct file *file, char __user *user_buf,
-				      size_t nbytes, loff_t *ppos)
-{
-	struct uvc_debugfs_buffer *buf = file->private_data;
+static const struct file_operations uvc_debugfs_stats_fops = {
+	.owner = THIS_MODULE,
+	.open = uvc_debugfs_stats_open,
+	.llseek = no_llseek,
+	.read = uvc_debugfs_read,
+	.release = uvc_debugfs_release,
+};
 
-	return simple_read_from_buffer(user_buf, nbytes, ppos, buf->data,
-				       buf->count);
-}
+/* -----------------------------------------------------------------------------
+ * Clocks
+ */
 
-static int uvc_debugfs_stats_release(struct inode *inode, struct file *file)
+static int uvc_debugfs_clocks_open(struct inode *inode, struct file *file)
 {
-	kfree(file->private_data);
-	file->private_data = NULL;
+	struct uvc_streaming *stream = inode->i_private;
+	struct uvc_debugfs_buffer *buf;
+
+	buf = kmalloc(sizeof(*buf), GFP_KERNEL);
+	if (buf == NULL)
+		return -ENOMEM;
 
+	buf->count = uvc_video_clocks_dump(stream, buf->data, sizeof(buf->data));
+
+	file->private_data = buf;
 	return 0;
 }
 
-static const struct file_operations uvc_debugfs_stats_fops = {
+static const struct file_operations uvc_debugfs_clocks_fops = {
 	.owner = THIS_MODULE,
-	.open = uvc_debugfs_stats_open,
+	.open = uvc_debugfs_clocks_open,
 	.llseek = no_llseek,
-	.read = uvc_debugfs_stats_read,
-	.release = uvc_debugfs_stats_release,
+	.read = uvc_debugfs_read,
+	.release = uvc_debugfs_release,
 };
 
 /* -----------------------------------------------------------------------------
@@ -95,6 +126,14 @@ int uvc_debugfs_init_stream(struct uvc_streaming *stream)
 
 	stream->debugfs_dir = dent;
 
+	dent = debugfs_create_file("clocks", 0444, stream->debugfs_dir,
+				   stream, &uvc_debugfs_clocks_fops);
+	if (IS_ERR_OR_NULL(dent)) {
+		uvc_printk(KERN_INFO, "Unable to create debugfs clocks file.\n");
+		uvc_debugfs_cleanup_stream(stream);
+		return -ENODEV;
+	}
+
 	dent = debugfs_create_file("stats", 0444, stream->debugfs_dir,
 				   stream, &uvc_debugfs_stats_fops);
 	if (IS_ERR_OR_NULL(dent)) {
diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c
index 9637e8b..831f6ea 100644
--- a/drivers/media/usb/uvc/uvc_video.c
+++ b/drivers/media/usb/uvc/uvc_video.c
@@ -466,12 +466,15 @@ uvc_video_clock_decode(struct uvc_streaming *stream, struct uvc_buffer *buf,
 	sample->dev_sof = dev_sof;
 	sample->host_sof = host_sof;
 	sample->host_ts = ts;
+	sample->index = stream->clock.index++;
 
 	/* Update the sliding window head and count. */
 	stream->clock.head = (stream->clock.head + 1) % stream->clock.size;
 
 	if (stream->clock.count < stream->clock.size)
 		stream->clock.count++;
+	if (stream->clock.print < stream->clock.size)
+		stream->clock.print++;
 
 	spin_unlock_irqrestore(&stream->clock.lock, flags);
 }
@@ -480,10 +483,51 @@ static void uvc_video_clock_reset(struct uvc_streaming *stream)
 {
 	struct uvc_clock *clock = &stream->clock;
 
+	spin_lock_irq(&clock->lock);
+
 	clock->head = 0;
 	clock->count = 0;
+	clock->print = 0;
+	clock->index = 0;
 	clock->last_sof = -1;
 	clock->sof_offset = -1;
+
+	spin_unlock_irq(&clock->lock);
+}
+
+size_t uvc_video_clocks_dump(struct uvc_streaming *stream, char *buf,
+			     size_t size)
+{
+	struct uvc_clock *clock = &stream->clock;
+	unsigned int pos;
+	size_t count = 0;
+
+	mutex_lock(&stream->mutex);
+
+	if (!clock->samples)
+		goto done;
+
+	spin_lock_irq(&clock->lock);
+
+	pos = (clock->head - clock->print) % clock->size;
+
+	for (; clock->print; clock->print--) {
+		struct uvc_clock_sample *sample = &clock->samples[pos];
+
+		count += scnprintf(buf + count, size - count,
+				   "%04x %08x %04x %04x %08lx %08lx\n",
+				   sample->index, sample->dev_stc, sample->dev_sof,
+				   sample->host_sof, sample->host_ts.tv_sec,
+				   sample->host_ts.tv_nsec);
+		pos = (pos + 1) % clock->size;
+	}
+
+	spin_unlock_irq(&clock->lock);
+
+done:
+	mutex_unlock(&stream->mutex);
+
+	return count;
 }
 
 static int uvc_video_clock_init(struct uvc_streaming *stream)
diff --git a/drivers/media/usb/uvc/uvcvideo.h b/drivers/media/usb/uvc/uvcvideo.h
index f0a04b5..e0950b4 100644
--- a/drivers/media/usb/uvc/uvcvideo.h
+++ b/drivers/media/usb/uvc/uvcvideo.h
@@ -501,11 +501,14 @@ struct uvc_streaming {
 			u16 dev_sof;
 			struct timespec host_ts;
 			u16 host_sof;
+			u16 index;
 		} *samples;
 
 		unsigned int head;
 		unsigned int count;
 		unsigned int size;
+		unsigned int print;
+		u16 index;
 
 		u16 last_sof;
 		u16 sof_offset;
@@ -737,6 +740,8 @@ void uvc_debugfs_cleanup(void);
 int uvc_debugfs_init_stream(struct uvc_streaming *stream);
 void uvc_debugfs_cleanup_stream(struct uvc_streaming *stream);
 
+size_t uvc_video_clocks_dump(struct uvc_streaming *stream, char *buf,
+			     size_t size);
 size_t uvc_video_stats_dump(struct uvc_streaming *stream, char *buf,
 			    size_t size);
 
-- 
Regards,

Laurent Pinchart

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Grazvydas Ignotas]

Hi,

On Sun, Dec 7, 2014 at 9:23 PM, Laurent Pinchart
<laurent.pinchart@ideasonboard.com> wrote:
> Hi Grazvydas,
>
> (CC'ing Paulo Assis)
>
> On Saturday 06 December 2014 02:25:25 Grazvydas Ignotas wrote:
>> On Fri, Dec 5, 2014 at 1:46 PM, Laurent Pinchart wrote:
>> > On Thursday 06 November 2014 00:29:53 Grazvydas Ignotas wrote:
>> >> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart wrote:
>> >> > Would you be able to capture images from the C920 using yavta, with the
>> >> > uvcvideo trace parameter set to 4096, and send me both the yavta log
>> >> > and the kernel log ? Let's start with a capture sequence of 50 to 100
>> >> > images.
>> >>
>> >> I've done 2 captures, if that helps:
>> >> http://notaz.gp2x.de/tmp/c920_yavta/
>> >>
>> >> The second one was done using low exposure setting, which allows
>> >> camera to achieve higher frame rate.
>> >
>> > Thank you for the log, they were very helpful. They revealed that the USB
>> > SOF (Start Of Frame) counter values on the device and host side are not
>> > in sync. The counters get incremented are very different rates. What USB
>> > controller are you using ?
>>
>> 00:1d.7 USB controller: Intel Corporation NM10/ICH7 Family USB2 EHCI
>> Controller (rev 01) (prog-if 20 [EHCI])
>>         Subsystem: Micro-Star International Co., Ltd. [MSI] Device 7592
>>         Flags: bus master, medium devsel, latency 0, IRQ 23
>>         Memory at fe9fbc00 (32-bit, non-prefetchable) [size=1K]
>>         Capabilities: [50] Power Management version 2
>>         Capabilities: [58] Debug port: BAR=1 offset=00a0
>>         Kernel driver in use: ehci-pci
>>
>> If it helps, I could try on an ARM board, currently don't have any
>> other x86 hardware around.
>
> Actually the frequencies I've computed from the log are correct on the host
> side but quite off on the device side. I'm puzzled.
>
> The following patch allows accessing the contents of the clock data buffer
> through debugfs. Would you be able to apply it and execute the following
> steps ?
>
> 1. Load the uvcvideo module with the clock trace flag (0x1000) set.
>
> 2. Start capturing clock data.
>
> while true; do
>         cat /sys/kernel/debug/usb/uvcvideo/2-6/clocks ;
> done > ~/samples.log
>
> 3. Capture 100 frames.
>
> yavta -c100 > yavta.log
>
> 4. Stop the "while true" with ctrl-C.
>
> 5. Capture the uvcvideo stats.
>
> cat /sys/kernel/debug/usb/uvcvideo/2-6/stats > stats.log
>
> 6. Capture the kernel log.
>
> dmesg > dmesg.log
>
> 7. Send me all the log files.

Done:
http://notaz.gp2x.de/tmp/c920_yavta/3/

--
Gražvydas

Re: (bisected) Logitech C920 (uvcvideo) stutters since 3.9

[Milos Ivanovic]

On 8/12/2014 10:23 am, Grazvydas Ignotas wrote:
> Hi,
>
> On Sun, Dec 7, 2014 at 9:23 PM, Laurent Pinchart
> <laurent.pinchart@ideasonboard.com> wrote:
>> Hi Grazvydas,
>>
>> (CC'ing Paulo Assis)
>>
>> On Saturday 06 December 2014 02:25:25 Grazvydas Ignotas wrote:
>>> On Fri, Dec 5, 2014 at 1:46 PM, Laurent Pinchart wrote:
>>>> On Thursday 06 November 2014 00:29:53 Grazvydas Ignotas wrote:
>>>>> On Wed, Nov 5, 2014 at 4:05 PM, Laurent Pinchart wrote:
>>>>>> Would you be able to capture images from the C920 using yavta, with the
>>>>>> uvcvideo trace parameter set to 4096, and send me both the yavta log
>>>>>> and the kernel log ? Let's start with a capture sequence of 50 to 100
>>>>>> images.
>>>>>
>>>>> I've done 2 captures, if that helps:
>>>>> http://notaz.gp2x.de/tmp/c920_yavta/
>>>>>
>>>>> The second one was done using low exposure setting, which allows
>>>>> camera to achieve higher frame rate.
>>>>
>>>> Thank you for the log, they were very helpful. They revealed that the USB
>>>> SOF (Start Of Frame) counter values on the device and host side are not
>>>> in sync. The counters get incremented are very different rates. What USB
>>>> controller are you using ?
>>>
>>> 00:1d.7 USB controller: Intel Corporation NM10/ICH7 Family USB2 EHCI
>>> Controller (rev 01) (prog-if 20 [EHCI])
>>>          Subsystem: Micro-Star International Co., Ltd. [MSI] Device 7592
>>>          Flags: bus master, medium devsel, latency 0, IRQ 23
>>>          Memory at fe9fbc00 (32-bit, non-prefetchable) [size=1K]
>>>          Capabilities: [50] Power Management version 2
>>>          Capabilities: [58] Debug port: BAR=1 offset=00a0
>>>          Kernel driver in use: ehci-pci
>>>
>>> If it helps, I could try on an ARM board, currently don't have any
>>> other x86 hardware around.
>>
>> Actually the frequencies I've computed from the log are correct on the host
>> side but quite off on the device side. I'm puzzled.
>>
>> The following patch allows accessing the contents of the clock data buffer
>> through debugfs. Would you be able to apply it and execute the following
>> steps ?
>>
>> 1. Load the uvcvideo module with the clock trace flag (0x1000) set.
>>
>> 2. Start capturing clock data.
>>
>> while true; do
>>          cat /sys/kernel/debug/usb/uvcvideo/2-6/clocks ;
>> done > ~/samples.log
>>
>> 3. Capture 100 frames.
>>
>> yavta -c100 > yavta.log
>>
>> 4. Stop the "while true" with ctrl-C.
>>
>> 5. Capture the uvcvideo stats.
>>
>> cat /sys/kernel/debug/usb/uvcvideo/2-6/stats > stats.log
>>
>> 6. Capture the kernel log.
>>
>> dmesg > dmesg.log
>>
>> 7. Send me all the log files.
>
> Done:
> http://notaz.gp2x.de/tmp/c920_yavta/3/
>
> --
> Gražvydas
>

Hello,

I've reproduced this issue on a Logitech C920 in the following environments:

1. x86_64 Linux 3.19.3 (Gentoo, custom kernel)
2. x86_64 Linux 3.13.0-46-generic (Ubuntu)
3. armv7a Linux 3.19.3 (Arch Linux, custom kernel)

I can confirm that the issue is not present in Linux 3.8.y.

I'm not sure if there have been any developments in regards to this in 
recent months, but I'm happy to help out in any way possible. If someone 
is in need of new debug logs, I can follow the steps above and provide them.

--
Milos