[v3] media: uvcvideo: Implement V4L2_EVENT_FRAME_SYNC

  Add support for the frame_sync event, so user-space can become aware
earlier of new frames.

Suggested-by: Esker Wong <esker@chromium.org>
Tested-by: Esker Wong <esker@chromium.org>
Signed-off-by: Ricardo Ribalda <ribalda@chromium.org>
---
We have measured a latency of around 30msecs between frame sync
and dqbuf.
---
Changes in v3:
- Sent wrong patch as v2 sorry :S
- Link to v2: https://lore.kernel.org/r/20231106-uvc-event-v2-1-7d8e36f0df16@chromium.org

Changes in v2:
- Suggested by Laurent. Split sequence++ and event init.
- Link to v1: https://lore.kernel.org/r/20231020-uvc-event-v1-1-3baa0e9f6952@chromium.org
---
 drivers/media/usb/uvc/uvc_v4l2.c  | 2 ++
 drivers/media/usb/uvc/uvc_video.c | 7 +++++++
 2 files changed, 9 insertions(+)


---
base-commit: ce55c22ec8b223a90ff3e084d842f73cfba35588
change-id: 20231020-uvc-event-d3d1bbbdcb2f

Best regards,
  

Hi Ricardo,

Sorry, I missed the whole discussion for the v2 patch. I've now read it and
will reply here.

On 11/6/23 12:00, Ricardo Ribalda wrote:
> Add support for the frame_sync event, so user-space can become aware
> earlier of new frames.

I don't think this describes why you want this. Specifically, you want to use
this to measure latency inside the driver between the arrival of the first USB
packet and the time the buffer is dequeued.

And this is presumably meant for debugging/measuring, but not for normal
capturing. Right?

Based on the discussion it looks like everyone is OK with this for the BULK
case, and V4L2_EVENT_FRAME_SYNC makes sense to me there. You want to see the
sequence number in the event, and the description of the event matches what
happens.

The problem is the ISOC case where it is debatable if this adds anything.

Perhaps in the ISOC case this event shouldn't be supported? Unless you can
show that it does provide useful information in the ISOC case. I didn't see
that in the v2 discussion, but I might have missed it.

Regards,

	Hans

> 
> Suggested-by: Esker Wong <esker@chromium.org>
> Tested-by: Esker Wong <esker@chromium.org>
> Signed-off-by: Ricardo Ribalda <ribalda@chromium.org>
> ---
> We have measured a latency of around 30msecs between frame sync
> and dqbuf.
> ---
> Changes in v3:
> - Sent wrong patch as v2 sorry :S
> - Link to v2: https://lore.kernel.org/r/20231106-uvc-event-v2-1-7d8e36f0df16@chromium.org
> 
> Changes in v2:
> - Suggested by Laurent. Split sequence++ and event init.
> - Link to v1: https://lore.kernel.org/r/20231020-uvc-event-v1-1-3baa0e9f6952@chromium.org
> ---
>  drivers/media/usb/uvc/uvc_v4l2.c  | 2 ++
>  drivers/media/usb/uvc/uvc_video.c | 7 +++++++
>  2 files changed, 9 insertions(+)
> 
> diff --git a/drivers/media/usb/uvc/uvc_v4l2.c b/drivers/media/usb/uvc/uvc_v4l2.c
> index f4988f03640a..9f3fb5fd2375 100644
> --- a/drivers/media/usb/uvc/uvc_v4l2.c
> +++ b/drivers/media/usb/uvc/uvc_v4l2.c
> @@ -1352,6 +1352,8 @@ static int uvc_ioctl_subscribe_event(struct v4l2_fh *fh,
>  	switch (sub->type) {
>  	case V4L2_EVENT_CTRL:
>  		return v4l2_event_subscribe(fh, sub, 0, &uvc_ctrl_sub_ev_ops);
> +	case V4L2_EVENT_FRAME_SYNC:
> +		return v4l2_event_subscribe(fh, sub, 0, NULL);
>  	default:
>  		return -EINVAL;
>  	}
> diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c
> index 28dde08ec6c5..6a9410133908 100644
> --- a/drivers/media/usb/uvc/uvc_video.c
> +++ b/drivers/media/usb/uvc/uvc_video.c
> @@ -1073,9 +1073,16 @@ static int uvc_video_decode_start(struct uvc_streaming *stream,
>  	 * that discontinuous sequence numbers always indicate lost frames.
>  	 */
>  	if (stream->last_fid != fid) {
> +		struct v4l2_event event = {
> +			.type = V4L2_EVENT_FRAME_SYNC,
> +		};
> +
>  		stream->sequence++;
>  		if (stream->sequence)
>  			uvc_video_stats_update(stream);
> +
> +		event.u.frame_sync.frame_sequence = stream->sequence;
> +		v4l2_event_queue(&stream->vdev, &event);
>  	}
>  
>  	uvc_video_clock_decode(stream, buf, data, len);
> 
> ---
> base-commit: ce55c22ec8b223a90ff3e084d842f73cfba35588
> change-id: 20231020-uvc-event-d3d1bbbdcb2f
> 
> Best regards,
  

Hi Hans

On Tue, 21 Nov 2023 at 11:37, Hans Verkuil <hverkuil@xs4all.nl> wrote:
>
> Hi Ricardo,
>
> Sorry, I missed the whole discussion for the v2 patch. I've now read it and
> will reply here.
>
> On 11/6/23 12:00, Ricardo Ribalda wrote:
> > Add support for the frame_sync event, so user-space can become aware
> > earlier of new frames.

Will fix the description in the next version thanks!


>
> I don't think this describes why you want this. Specifically, you want to use
> this to measure latency inside the driver between the arrival of the first USB
> packet and the time the buffer is dequeued.
>
> And this is presumably meant for debugging/measuring, but not for normal
> capturing. Right?
>
> Based on the discussion it looks like everyone is OK with this for the BULK
> case, and V4L2_EVENT_FRAME_SYNC makes sense to me there. You want to see the
> sequence number in the event, and the description of the event matches what
> happens.
>
> The problem is the ISOC case where it is debatable if this adds anything.
>
> Perhaps in the ISOC case this event shouldn't be supported? Unless you can
> show that it does provide useful information in the ISOC case. I didn't see
> that in the v2 discussion, but I might have missed it.

There are the following times
- t_exposure: Time when the exposure happens. We can get it from
v4l2_buffer.timestamp based on the hw timestamp
- t_usb_first: Time when the first usb frame arrives at the usb host.
We cannot get it (or better said.. I do not know how to get it)
- t_urb: Time when the first urb is processed by the driver.
Implemented as V4L2_EVENT_FRAME_SYNC in this driver
- t_dqbuf: Time when the buffer can be dequeded by userspace.
Implemented a timestamp in userspace when the syscall finishes.

What we would like to measure is (t_dqbuf-t_usb_first), but we cannot
obtain t_usb_first.

(t_urb-t_usb_first) is relatively small so it can be ignored: For ISO
the max we have measured is 1.8 msec vs 31 msec (t_dqbuf-t_urb)
(t_urb-t_usb_first) is also always constant. If you are measuring
trends, you do not care about an offset.

There are two proposed alternatives to this patch:
- that we use (t_dqbuf-t_exposure), but that measurement is dependent
on the exposure time, so we cannot use that measurement.
- use ftrace: but we will have to use different userspace methods for
every driver, which defeats the purpose of V4L2_EVENT_FRAME_SYNC, and
the metric will be as "bad" as the current proposal.

If you are curious you can take a look at a trace here:
https://ui.perfetto.dev/#!/?s=061a0fb7ebb0333e5dcbe35f487c18980e8e00a6e1b227c98d5e2569163924e0

Thanks!


>
> Regards,
>
>         Hans
>
> >
> > Suggested-by: Esker Wong <esker@chromium.org>
> > Tested-by: Esker Wong <esker@chromium.org>
> > Signed-off-by: Ricardo Ribalda <ribalda@chromium.org>
> > ---
> > We have measured a latency of around 30msecs between frame sync
> > and dqbuf.
> > ---
> > Changes in v3:
> > - Sent wrong patch as v2 sorry :S
> > - Link to v2: https://lore.kernel.org/r/20231106-uvc-event-v2-1-7d8e36f0df16@chromium.org
> >
> > Changes in v2:
> > - Suggested by Laurent. Split sequence++ and event init.
> > - Link to v1: https://lore.kernel.org/r/20231020-uvc-event-v1-1-3baa0e9f6952@chromium.org
> > ---
> >  drivers/media/usb/uvc/uvc_v4l2.c  | 2 ++
> >  drivers/media/usb/uvc/uvc_video.c | 7 +++++++
> >  2 files changed, 9 insertions(+)
> >
> > diff --git a/drivers/media/usb/uvc/uvc_v4l2.c b/drivers/media/usb/uvc/uvc_v4l2.c
> > index f4988f03640a..9f3fb5fd2375 100644
> > --- a/drivers/media/usb/uvc/uvc_v4l2.c
> > +++ b/drivers/media/usb/uvc/uvc_v4l2.c
> > @@ -1352,6 +1352,8 @@ static int uvc_ioctl_subscribe_event(struct v4l2_fh *fh,
> >       switch (sub->type) {
> >       case V4L2_EVENT_CTRL:
> >               return v4l2_event_subscribe(fh, sub, 0, &uvc_ctrl_sub_ev_ops);
> > +     case V4L2_EVENT_FRAME_SYNC:
> > +             return v4l2_event_subscribe(fh, sub, 0, NULL);
> >       default:
> >               return -EINVAL;
> >       }
> > diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c
> > index 28dde08ec6c5..6a9410133908 100644
> > --- a/drivers/media/usb/uvc/uvc_video.c
> > +++ b/drivers/media/usb/uvc/uvc_video.c
> > @@ -1073,9 +1073,16 @@ static int uvc_video_decode_start(struct uvc_streaming *stream,
> >        * that discontinuous sequence numbers always indicate lost frames.
> >        */
> >       if (stream->last_fid != fid) {
> > +             struct v4l2_event event = {
> > +                     .type = V4L2_EVENT_FRAME_SYNC,
> > +             };
> > +
> >               stream->sequence++;
> >               if (stream->sequence)
> >                       uvc_video_stats_update(stream);
> > +
> > +             event.u.frame_sync.frame_sequence = stream->sequence;
> > +             v4l2_event_queue(&stream->vdev, &event);
> >       }
> >
> >       uvc_video_clock_decode(stream, buf, data, len);
> >
> > ---
> > base-commit: ce55c22ec8b223a90ff3e084d842f73cfba35588
> > change-id: 20231020-uvc-event-d3d1bbbdcb2f
> >
> > Best regards,
>


--
Ricardo Ribalda