On 6/1/23 07:54, Dan Scally wrote:
>> With no changes, the usb_requests spend ~3ms in flight, and there
>> is one video frame dispatched every ~33ms. Unfortunately (or perhaps
>> fortunately?), it seems like the system latencies add to >8ms of per frame
>> jitter when encoding frames.
>
>
> I'm really really impressed with the thoroughness of your investigation here. Can you share how you tracked the frame times and RTTs? I have some devices with a DWC2 controller and I think a MUSB too - I'd be interested in testing those too to see how they compared.
>
Hey Dan, I appreciate the kind words! Attaching a dirty patch that I used.
Some things to note:
- It is terribly hacky, apologies in advance (didn't think anyone would
want to look at it).
- The patch will likely not apply cleanly to ToT, because I am working off an
older kernel which also had some of my own debug changes before this
patch. Hopefully it is still useful!
- It uses the time honored technique of dumping debug logs as error logs so
be prepared for a lot of log spam :P
- The metrics mess up if the stream configuration changes mid-stream. I just
restarted the gadget between tests.
- The stats at stream start and end are all over the place, but should stabilize
in a hundred frames or so.
Patch follows below
---
drivers/usb/gadget/function/uvc.h | 13 +++++
drivers/usb/gadget/function/uvc_video.c | 67 ++++++++++++++++++++++---
2 files changed, 74 insertions(+), 6 deletions(-)
diff --git a/drivers/usb/gadget/function/uvc.h b/drivers/usb/gadget/function/uvc.h
index 40226b1f7e148..2b877ab270536 100644
--- a/drivers/usb/gadget/function/uvc.h
+++ b/drivers/usb/gadget/function/uvc.h
@@ -15,6 +15,7 @@
#include <linux/usb/composite.h>
#include <linux/videodev2.h>
#include <linux/wait.h>
+#include <linux/ktime.h>
#include <media/v4l2-device.h>
#include <media/v4l2-dev.h>
@@ -81,6 +82,7 @@ struct uvc_request {
struct sg_table sgt;
u8 header[UVCG_REQUEST_HEADER_LEN];
struct uvc_buffer *last_buf;
+ ktime_t ts;
};
struct uvc_video {
@@ -104,6 +106,11 @@ struct uvc_video {
unsigned int req_size;
struct uvc_request *ureq;
struct list_head req_free;
+ ktime_t max_rtt;
+ ktime_t min_rtt;
+ ktime_t mean_rtt;
+ unsigned int num_reqs;
+ unsigned int inflight_reqs;
spinlock_t req_lock;
unsigned int req_int_count;
@@ -117,6 +124,12 @@ struct uvc_video {
struct uvc_video_queue queue;
unsigned int fid;
+
+ ktime_t frame_ts;
+ ktime_t frame_ts_min;
+ ktime_t frame_ts_max;
+ ktime_t frame_ts_mean;
+ unsigned int num_frames;
};
enum uvc_state {
diff --git a/drivers/usb/gadget/function/uvc_video.c b/drivers/usb/gadget/function/uvc_video.c
index 465dd07bf66e7..4aaa8077145d2 100644
--- a/drivers/usb/gadget/function/uvc_video.c
+++ b/drivers/usb/gadget/function/uvc_video.c
@@ -230,7 +230,8 @@ uvc_video_encode_isoc(struct usb_request *req, struct uvc_video *video,
static int uvcg_video_ep_queue(struct uvc_video *video, struct usb_request *req)
{
int ret;
-
+ struct uvc_request *ureq = req->context;
+ ureq->ts = ktime_get();
ret = usb_ep_queue(video->ep, req, GFP_ATOMIC);
if (ret < 0) {
uvcg_err(&video->uvc->func, "Failed to queue request (%d).\n",
@@ -255,6 +256,7 @@ uvc_video_complete(struct usb_ep *ep, struct usb_request *req)
struct uvc_video_queue *queue = &video->queue;
struct uvc_device *uvc = video->uvc;
unsigned long flags;
+ ktime_t rtt;
switch (req->status) {
case 0:
@@ -282,6 +284,22 @@ uvc_video_complete(struct usb_ep *ep, struct usb_request *req)
ureq->last_buf = NULL;
}
+ spin_lock_irqsave(&queue->irqlock, flags);
+ if (!req->length) {
+ video->inflight_reqs--;
+ }
+ rtt = ktime_get();
+ rtt = ktime_sub(rtt, ureq->ts);
+ video->max_rtt = max(video->max_rtt, rtt);
+ video->min_rtt = min(video->min_rtt, rtt);
+ video->num_reqs++;
+ video->mean_rtt = ((video->mean_rtt * (video->num_reqs - 1)) + rtt) / video->num_reqs;
+ printk(KERN_ERR "%s: ARLog: rtt : min/max/mean: "
+ "%lld : %lld/%lld/%lld goLRA", __FUNCTION__, rtt,
+ video->min_rtt, video->max_rtt, video->mean_rtt);
+ // printk(KERN_ERR "%s: ARLog: video->inflight_reqs = %u", __FUNCTION__, video->inflight_reqs);
+ spin_unlock_irqrestore(&queue->irqlock, flags);
+
spin_lock_irqsave(&video->req_lock, flags);
list_add_tail(&req->list, &video->req_free);
spin_unlock_irqrestore(&video->req_lock, flags);
@@ -315,6 +333,10 @@ uvc_video_free_requests(struct uvc_video *video)
}
INIT_LIST_HEAD(&video->req_free);
+ video->max_rtt = 0;
+ video->min_rtt = 2147483647;
+ video->num_reqs = 0;
+ video->inflight_reqs = 0;
video->req_size = 0;
return 0;
}
@@ -360,6 +382,10 @@ uvc_video_alloc_requests(struct uvc_video *video)
}
video->req_size = req_size;
+ video->max_rtt = 0;
+ video->min_rtt = 2147483647;
+ video->inflight_reqs = 0;
+ video->num_reqs = 0;
return 0;
@@ -389,6 +415,11 @@ static void uvcg_video_pump(struct work_struct *work)
bool buf_int;
/* video->max_payload_size is only set when using bulk transfer */
bool is_bulk = video->max_payload_size;
+ unsigned int tmp = 0;
+ unsigned int *req_ctr;
+ // unsigned int target_empty_reqs = video->uvc_num_requests + 2;
+ unsigned int num_sampled_frames;
+ ktime_t frame_ts;
while (video->ep->enabled) {
/*
@@ -416,14 +447,31 @@ static void uvcg_video_pump(struct work_struct *work)
video->encode(req, video, buf);
/* Always interrupt for the last request of a video buffer */
buf_int = buf->state == UVC_BUF_STATE_DONE;
+
+ if (buf->state == UVC_BUF_STATE_DONE) {
+ frame_ts = video->frame_ts;
+ video->frame_ts = ktime_get();
+ frame_ts = ktime_sub(video->frame_ts, frame_ts);
+ if (video->num_frames >= 100) {
+ num_sampled_frames = video->num_frames - 100;
+ video->frame_ts_min = min(video->frame_ts_min, frame_ts);
+ video->frame_ts_max = max(video->frame_ts_max, frame_ts);
+ video->frame_ts_mean = ((video->frame_ts_mean * num_sampled_frames) + frame_ts) / (num_sampled_frames + 1);
+ printk(KERN_ERR "%s: ARLog: frame encode time: curr: min/max/mean: %lld : %lld/%lld/%lld", __FUNCTION__, frame_ts, video->frame_ts_min, video->frame_ts_max, video->frame_ts_mean);
+ }
+ video->num_frames++;
+ }
+ req_ctr = &tmp;
} else if (!(queue->flags & UVC_QUEUE_DISCONNECTED) && !is_bulk) {
/*
- * No video buffer available; the queue is still connected and
- * we're traferring over ISOC. Send a 0 length request to
- * prevent missed ISOC transfers.
- */
+ * No video buffer available; the queue is still connected and
+ * we're traferring over ISOC. Send a 0 length request to
+ * prevent missed ISOC transfers.
+ */
req->length = 0;
- buf_int = false;
+ // Double the interrupt frequency for empty requests.
+ buf_int = !(video->req_int_count % DIV_ROUND_UP(video->uvc_num_requests, 8));
+ req_ctr = &video->inflight_reqs;
} else {
/*
* Either queue has been disconnected or no video buffer
@@ -449,7 +497,11 @@ static void uvcg_video_pump(struct work_struct *work)
}
/* Queue the USB request */
+
ret = uvcg_video_ep_queue(video, req);
+ if (ret == 0) {
+ (*req_ctr)++;
+ }
spin_unlock_irqrestore(&queue->irqlock, flags);
if (ret < 0) {
@@ -512,6 +564,9 @@ int uvcg_video_enable(struct uvc_video *video, int enable)
uvc_video_encode_isoc_sg : uvc_video_encode_isoc;
video->req_int_count = 0;
+ video->frame_ts_min = 9720988367;
+ video->frame_ts_max = 0;
+ video->frame_ts_mean = 0;
queue_work(video->async_wq, &video->pump);
--
