Re: [RFC PATCH v1] media: uvcvideo: Cache URB header data before processing

[Kieran Bingham <kieran.bingham@ideasonboard.com>]

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

I'm attaching my debug patch in case it's useful to anyone measuring
performances.

(Recently with an extra metric added thanks to Keiichi)

Also available at:
git://git.kernel.org/pub/scm/linux/kernel/git/kbingham/rcar.git uvc/async-ml

Regards
--
Kieran

On 30/07/18 17:00, Laurent Pinchart wrote:
> Hi Keiichi,
> 
> (CC'ing Alan, Ezequiel and Matwey)
> 
> Thank you for the patch.
> 
> On Wednesday, 27 June 2018 13:34:08 EEST Keiichi Watanabe wrote:
>> On some platforms with non-coherent DMA (e.g. ARM), USB drivers use
>> uncached memory allocation methods. In such situations, it sometimes
>> takes a long time to access URB buffers.  This can be a cause of video
>> flickering problems if a resolution is high and a USB controller has
>> a very tight time limit. (e.g. dwc2) To avoid this problem, we copy
>> header data from (uncached) URB buffer into (cached) local buffer.
>>
>> This change should make the elapsed time of the interrupt handler
>> shorter on platforms with non-coherent DMA. We measured the elapsed
>> time of each callback of uvc_video_complete without/with this patch
>> while capturing Full HD video in
>> https://webrtc.github.io/samples/src/content/getusermedia/resolution/.
>> I tested it on the top of Kieran Bingham's Asynchronous UVC series
>> https://www.mail-archive.com/linux-media@vger.kernel.org/msg128359.html.
>> The test device was Jerry Chromebook (RK3288) with Logitech Brio 4K.
>> I collected data for 5 seconds. (There were around 480 callbacks in
>> this case.) The following result shows that this patch makes
>> uvc_video_complete about 2x faster.
>>
>>            | average | median  | min     | max     | standard deviation
>>
>> w/o caching| 45319ns | 40250ns | 33834ns | 142625ns| 16611ns
>> w/  caching| 20620ns | 19250ns | 12250ns | 56583ns | 6285ns
>>
>> In addition, we confirmed that this patch doesn't make it worse on
>> coherent DMA architecture by performing the same measurements on a
>> Broadwell Chromebox with the same camera.
>>
>>            | average | median  | min     | max     | standard deviation
>>
>> w/o caching| 21026ns | 21424ns | 12263ns | 23956ns | 1932ns
>> w/  caching| 20728ns | 20398ns |  8922ns | 45120ns | 3368ns
> 
> This is very interesting, and it seems related to https://
> patchwork.kernel.org/patch/10468937/. You might have seen that discussion as 
> you got CC'ed at some point.
> 
> I wonder whether performances couldn't be further improved by allocating the 
> URB buffers cached, as that would speed up the memcpy() as well. Have you 
> tested that by any chance ?
> 
>> Signed-off-by: Keiichi Watanabe <keiichiw@chromium.org>
>> ---
>>
>> After applying 6 patches in
>> https://www.mail-archive.com/linux-media@vger.kernel.org/msg128359.html,
>> I measured elapsed time by adding the following code to
>> /drivers/media/usb/uvc/uvc_video.c
>>
>> @@ -XXXX,6 +XXXX,9 @@ static void uvc_video_complete(struct urb *urb)
>>         struct uvc_video_queue *queue = &stream->queue;
>>  	struct uvc_buffer *buf = NULL;
>>  	int ret;
>> +	ktime_t start, end;
>> +	int elapsed_time;
>> +	start = ktime_get();
>>  	switch (urb->status) {
>>  	case 0:
>>
>> @@ -XXXX,6 +XXXX,10 @@ static void uvc_video_complete(struct urb *urb)
>>
>>  	INIT_WORK(&uvc_urb->work, uvc_video_copy_data_work);
>>  	queue_work(stream->async_wq, &uvc_urb->work);
>> +
>> +	end = ktime_get();
>> +	elapsed_time = ktime_to_ns(ktime_sub(end, start));
>> +	pr_err("elapsed time: %d ns", elapsed_time);
>>  }
>>
>>  /*
>>
>>
>>  drivers/media/usb/uvc/uvc_video.c | 92 +++++++++++++++----------------
>>  1 file changed, 43 insertions(+), 49 deletions(-)
>> diff --git a/drivers/media/usb/uvc/uvc_video.c
>> b/drivers/media/usb/uvc/uvc_video.c index a88b2e51a666..ff2eddc55530 100644
>> --- a/drivers/media/usb/uvc/uvc_video.c
>> +++ b/drivers/media/usb/uvc/uvc_video.c
>> @@ -391,36 +391,15 @@ static inline ktime_t uvc_video_get_time(void)
>>
>>  static void
>>  uvc_video_clock_decode(struct uvc_streaming *stream, struct uvc_buffer
>> *buf, -		       const u8 *data, int len)
>> +		       const u8 *data, int len, unsigned int header_size,
>> +		       bool has_pts, bool has_scr)
>>  {
>>  	struct uvc_clock_sample *sample;
>> -	unsigned int header_size;
>> -	bool has_pts = false;
>> -	bool has_scr = false;
>>  	unsigned long flags;
>>  	ktime_t time;
>>  	u16 host_sof;
>>  	u16 dev_sof;
>>
>> -	switch (data[1] & (UVC_STREAM_PTS | UVC_STREAM_SCR)) {
>> -	case UVC_STREAM_PTS | UVC_STREAM_SCR:
>> -		header_size = 12;
>> -		has_pts = true;
>> -		has_scr = true;
>> -		break;
>> -	case UVC_STREAM_PTS:
>> -		header_size = 6;
>> -		has_pts = true;
>> -		break;
>> -	case UVC_STREAM_SCR:
>> -		header_size = 8;
>> -		has_scr = true;
>> -		break;
>> -	default:
>> -		header_size = 2;
>> -		break;
>> -	}
>> -
>>  	/* Check for invalid headers. */
>>  	if (len < header_size)
>>  		return;
>> @@ -717,11 +696,10 @@ void uvc_video_clock_update(struct uvc_streaming
>> *stream, */
>>
>>  static void uvc_video_stats_decode(struct uvc_streaming *stream,
>> -		const u8 *data, int len)
>> +				   const u8 *data, int len,
>> +				   unsigned int header_size, bool has_pts,
>> +				   bool has_scr)
>>  {
>> -	unsigned int header_size;
>> -	bool has_pts = false;
>> -	bool has_scr = false;
>>  	u16 uninitialized_var(scr_sof);
>>  	u32 uninitialized_var(scr_stc);
>>  	u32 uninitialized_var(pts);
>> @@ -730,25 +708,6 @@ static void uvc_video_stats_decode(struct uvc_streaming
>> *stream, stream->stats.frame.nb_packets == 0)
>>  		stream->stats.stream.start_ts = ktime_get();
>>
>> -	switch (data[1] & (UVC_STREAM_PTS | UVC_STREAM_SCR)) {
>> -	case UVC_STREAM_PTS | UVC_STREAM_SCR:
>> -		header_size = 12;
>> -		has_pts = true;
>> -		has_scr = true;
>> -		break;
>> -	case UVC_STREAM_PTS:
>> -		header_size = 6;
>> -		has_pts = true;
>> -		break;
>> -	case UVC_STREAM_SCR:
>> -		header_size = 8;
>> -		has_scr = true;
>> -		break;
>> -	default:
>> -		header_size = 2;
>> -		break;
>> -	}
>> -
>>  	/* Check for invalid headers. */
>>  	if (len < header_size || data[0] < header_size) {
>>  		stream->stats.frame.nb_invalid++;
>> @@ -957,10 +916,41 @@ static void uvc_video_stats_stop(struct uvc_streaming
>> *stream) * to be called with a NULL buf parameter. uvc_video_decode_data
>> and * uvc_video_decode_end will never be called with a NULL buffer.
>>   */
>> +static void uvc_video_decode_header_size(const u8 *data, int *header_size,
>> +					 bool *has_pts, bool *has_scr)
>> +{
>> +	switch (data[1] & (UVC_STREAM_PTS | UVC_STREAM_SCR)) {
>> +	case UVC_STREAM_PTS | UVC_STREAM_SCR:
>> +		*header_size = 12;
>> +		*has_pts = true;
>> +		*has_scr = true;
>> +		break;
>> +	case UVC_STREAM_PTS:
>> +		*header_size = 6;
>> +		*has_pts = true;
>> +		break;
>> +	case UVC_STREAM_SCR:
>> +		*header_size = 8;
>> +		*has_scr = true;
>> +		break;
>> +	default:
>> +		*header_size = 2;
>> +	}
>> +}
>> +
>>  static int uvc_video_decode_start(struct uvc_streaming *stream,
>> -		struct uvc_buffer *buf, const u8 *data, int len)
>> +				  struct uvc_buffer *buf, const u8 *urb_data,
>> +				  int len)
>>  {
>>  	u8 fid;
>> +	u8 data[12];
>> +	unsigned int header_size;
>> +	bool has_pts = false, has_scr = false;
>> +
>> +	/* Cache the header since urb_data is uncached memory. The size of
>> +	 * header is at most 12 bytes.
>> +	 */
>> +	memcpy(data, urb_data, min(len, 12));
>>
>>  	/* Sanity checks:
>>  	 * - packet must be at least 2 bytes long
>> @@ -983,8 +973,12 @@ static int uvc_video_decode_start(struct uvc_streaming
>> *stream, uvc_video_stats_update(stream);
>>  	}
>>
>> -	uvc_video_clock_decode(stream, buf, data, len);
>> -	uvc_video_stats_decode(stream, data, len);
>> +	uvc_video_decode_header_size(data, &header_size, &has_pts, &has_scr);
>> +
>> +	uvc_video_clock_decode(stream, buf, data, len, header_size, has_pts,
>> +			       has_scr);
>> +	uvc_video_stats_decode(stream, data, len, header_size, has_pts,
>> +			       has_scr);
>>
>>  	/* Store the payload FID bit and return immediately when the buffer is
>>  	 * NULL.
>> --
>> 2.18.0.rc2.346.g013aa6912e-goog
> 
> 

-- 
Regards
--
Kieran

[-- Attachment #2: 0001-uvcvideo-debug-Add-statistics-for-measuring-performa.patch --]
[-- Type: text/x-patch, Size: 10707 bytes --]

From cebbd1b629bbe5f856ec5dc7591478c003f5a944 Mon Sep 17 00:00:00 2001
From: Kieran Bingham <kieran.bingham@ideasonboard.com>
Date: Wed, 22 Mar 2017 09:54:11 +0000
Subject: [PATCH] uvcvideo: debug: Add statistics for measuring performance

Measuring the performance of the uvcvideo driver requires introspection
into the internal state.

Extend the information provided at:
 /sys/kernel/debug/usb/uvcvideo/${bus}-${dev}/stats

to track the overall data throughput as well as URB usage and processing
speeds.

This patch is not intended for integration into any release tree, but is
provided as-is to assist in measuring the performance while fine tuning
specific use-cases of the driver.

Signed-off-by: Kieran Bingham <kieran.bingham@ideasonboard.com>
---

 v2:
   - uvcvideo: debug: Convert to using ktime_t
   - uvcvideo: debug: Track header processing time
     (H/T Keiichi Watanabe <keiichiw@chromium.org>

Signed-off-by: Kieran Bingham <kieran@bingham.xyz>
---
 drivers/media/usb/uvc/uvc_video.c | 153 +++++++++++++++++++++++++++++-
 drivers/media/usb/uvc/uvcvideo.h  |  20 ++++
 2 files changed, 171 insertions(+), 2 deletions(-)

diff --git a/drivers/media/usb/uvc/uvc_video.c b/drivers/media/usb/uvc/uvc_video.c
index a4222d8d09a5..40943890668b 100644
--- a/drivers/media/usb/uvc/uvc_video.c
+++ b/drivers/media/usb/uvc/uvc_video.c
@@ -863,12 +863,56 @@ static void uvc_video_stats_update(struct uvc_streaming *stream)
 	memset(&stream->stats.frame, 0, sizeof(stream->stats.frame));
 }
 
+size_t uvc_video_dump_time_stats(char *buf, size_t size,
+				 struct uvc_stats_time *stat, const char *pfx)
+{
+	unsigned int avg = 0;
+
+	if (stat->qty)
+		avg = stat->duration / stat->qty;
+
+	/* Stat durations are in nanoseconds, we present in micro-seconds */
+	return scnprintf(buf, size,
+			 "%s: %llu/%u uS/qty: %u.%03u avg %u.%03u min %u.%03u max (uS)\n",
+			 pfx, stat->duration / 1000, stat->qty,
+			  avg / 1000, avg % 1000,
+			  stat->min / 1000, stat->min % 1000,
+			  stat->max / 1000, stat->max % 1000);
+}
+
+size_t uvc_video_dump_speed(char *buf, size_t size, const char *pfx,
+			    u64 bytes, u64 milliseconds)
+{
+	unsigned int rate = 0;
+	bool gbit = false;
+
+	if (milliseconds)
+		rate = bytes * 8 / milliseconds;
+
+	if (rate >= 1000000) {
+		gbit = true;
+		rate /= 1000;
+	}
+
+	/*
+	* bits/milliseconds == kilobits/seconds,
+	* presented here as Mbits/s (or Gbit/s) with 3 decimal places
+	*/
+	return scnprintf(buf, size, "%s: %d.%03d %sbits/s\n",
+			 pfx, rate / 1000, rate % 1000,
+			 gbit ? "G" : "M");
+}
+
 size_t uvc_video_stats_dump(struct uvc_streaming *stream, char *buf,
 			    size_t size)
 {
+	u64 bytes = stream->stats.stream.bytes; /* Single sample */
+	unsigned int empty_ratio = 0;
 	unsigned int scr_sof_freq;
 	unsigned int duration;
+	unsigned int fps = 0;
 	size_t count = 0;
+	u64 cpu = 0;
 
 	/* Compute the SCR.SOF frequency estimate. At the nominal 1kHz SOF
 	 * frequency this will not overflow before more than 1h.
@@ -881,12 +925,20 @@ size_t uvc_video_stats_dump(struct uvc_streaming *stream, char *buf,
 	else
 		scr_sof_freq = 0;
 
+	if (stream->stats.stream.nb_packets)
+		empty_ratio = stream->stats.stream.nb_empty * 100 /
+			stream->stats.stream.nb_packets;
+
 	count += scnprintf(buf + count, size - count,
-			   "frames:  %u\npackets: %u\nempty:   %u\n"
-			   "errors:  %u\ninvalid: %u\n",
+			   "frames:  %u\n"
+			   "packets: %u\n"
+			   "empty:   %u (%u %%)\n"
+			   "errors:  %u\n"
+			   "invalid: %u\n",
 			   stream->stats.stream.nb_frames,
 			   stream->stats.stream.nb_packets,
 			   stream->stats.stream.nb_empty,
+			   empty_ratio,
 			   stream->stats.stream.nb_errors,
 			   stream->stats.stream.nb_invalid);
 	count += scnprintf(buf + count, size - count,
@@ -903,6 +955,53 @@ size_t uvc_video_stats_dump(struct uvc_streaming *stream, char *buf,
 			   stream->stats.stream.min_sof,
 			   stream->stats.stream.max_sof,
 			   scr_sof_freq / 1000, scr_sof_freq % 1000);
+	count += scnprintf(buf + count, size - count,
+			   "bytes %lld : duration %d\n",
+			   bytes, duration);
+
+	if (duration != 0) {
+		/* Duration is in milliseconds, * 100 to gain 2 dp precision */
+		fps = stream->stats.stream.nb_frames * 1000 * 100 / duration;
+		/* CPU usage as a % with 6 decimal places */
+		cpu = stream->stats.urbstat.decode.duration / duration * 100;
+	}
+
+	count += scnprintf(buf + count, size - count,
+			   "FPS: %u.%02u\n", fps / 100, fps % 100);
+
+	/* Processing Times */
+
+	count += uvc_video_dump_time_stats(buf + count, size - count,
+			   &stream->stats.urbstat.urb, "URB");
+	count += uvc_video_dump_time_stats(buf + count, size - count,
+			   &stream->stats.urbstat.header, "header");
+	count += uvc_video_dump_time_stats(buf + count, size - count,
+			   &stream->stats.urbstat.latency, "latency");
+	count += uvc_video_dump_time_stats(buf + count, size - count,
+			   &stream->stats.urbstat.decode, "decode");
+
+	/* Processing Speeds */
+
+	/* This should be representative of the memory bus / cpu speed */
+	count += uvc_video_dump_speed(buf + count, size - count,
+			   "raw decode speed",
+			   bytes,
+			   stream->stats.urbstat.decode.duration / 1000000);
+
+	/* Raw bus speed - scheduling latencies */
+	count += uvc_video_dump_speed(buf + count, size - count,
+			   "raw URB handling speed",
+			   bytes,
+			   stream->stats.urbstat.urb.duration / 1000000);
+
+	/* Throughput against wall clock time, stream duration is in millis*/
+	count += uvc_video_dump_speed(buf + count, size - count,
+			   "throughput", bytes, duration);
+
+	/* Determine the 'CPU Usage' of our URB processing */
+	count += scnprintf(buf + count, size - count,
+			   "URB decode CPU usage %llu.%06llu %%\n",
+			   cpu / 1000000, cpu % 1000000);
 
 	return count;
 }
@@ -911,6 +1010,10 @@ static void uvc_video_stats_start(struct uvc_streaming *stream)
 {
 	memset(&stream->stats, 0, sizeof(stream->stats));
 	stream->stats.stream.min_sof = 2048;
+
+	stream->stats.urbstat.urb.min = -1;
+	stream->stats.urbstat.latency.min = -1;
+	stream->stats.urbstat.decode.min = -1;
 }
 
 static void uvc_video_stats_stop(struct uvc_streaming *stream)
@@ -918,6 +1021,27 @@ static void uvc_video_stats_stop(struct uvc_streaming *stream)
 	stream->stats.stream.stop_ts = ktime_get();
 }
 
+static s64 uvc_stats_add(struct uvc_stats_time *s,
+			 const ktime_t a, const ktime_t b)
+{
+	ktime_t delta;
+	u64 duration;
+
+	delta = ktime_sub(b, a);
+	duration = ktime_to_ns(delta);
+
+	s->qty++;
+	s->duration += duration;
+
+	if (duration < s->min)
+		s->min = duration;
+
+	if (duration > s->max)
+		s->max = duration;
+
+	return duration;
+}
+
 /* ------------------------------------------------------------------------
  * Video codecs
  */
@@ -981,6 +1105,9 @@ static int uvc_video_decode_start(struct uvc_streaming *stream,
 		stream->sequence++;
 		if (stream->sequence)
 			uvc_video_stats_update(stream);
+
+		/* Update the stream timer each frame */
+		stream->stats.stream.stop_ts = ktime_get();
 	}
 
 	uvc_video_clock_decode(stream, buf, data, len);
@@ -1063,18 +1190,34 @@ static int uvc_video_decode_start(struct uvc_streaming *stream,
 static void uvc_video_copy_data_work(struct work_struct *work)
 {
 	struct uvc_urb *uvc_urb = container_of(work, struct uvc_urb, work);
+	ktime_t now;
 	unsigned int i;
 	int ret;
 
+	/* Measure decode performance */
+	uvc_urb->decode_start = ktime_get();
+	/* Measure scheduling latency */
+	uvc_stats_add(&uvc_urb->stream->stats.urbstat.latency,
+		      uvc_urb->received, uvc_urb->decode_start);
+
 	for (i = 0; i < uvc_urb->async_operations; i++) {
 		struct uvc_copy_op *op = &uvc_urb->copy_operations[i];
 
 		memcpy(op->dst, op->src, op->len);
+		uvc_urb->stream->stats.stream.bytes += op->len;
 
 		/* Release reference taken on this buffer */
 		uvc_queue_buffer_release(op->buf);
 	}
 
+	now = ktime_get();
+	/* measure 'memcpy time' */
+	uvc_stats_add(&uvc_urb->stream->stats.urbstat.decode,
+		      uvc_urb->decode_start, now);
+	/* measure 'full urb processing time' */
+	uvc_stats_add(&uvc_urb->stream->stats.urbstat.urb,
+		      uvc_urb->received, now);
+
 	ret = usb_submit_urb(uvc_urb->urb, GFP_ATOMIC);
 	if (ret < 0)
 		uvc_printk(KERN_ERR, "Failed to resubmit video URB (%d).\n",
@@ -1461,6 +1604,9 @@ static void uvc_video_complete(struct urb *urb)
 	unsigned long flags;
 	int ret;
 
+	/* Track URB processing performance */
+	uvc_urb->received = ktime_get();
+
 	switch (urb->status) {
 	case 0:
 		break;
@@ -1512,6 +1658,9 @@ static void uvc_video_complete(struct urb *urb)
 
 	INIT_WORK(&uvc_urb->work, uvc_video_copy_data_work);
 	queue_work(stream->async_wq, &uvc_urb->work);
+
+	uvc_stats_add(&uvc_urb->stream->stats.urbstat.header,
+		      uvc_urb->received, ktime_get());
 }
 
 /*
diff --git a/drivers/media/usb/uvc/uvcvideo.h b/drivers/media/usb/uvc/uvcvideo.h
index 7ebeb680710b..efaa55a24a68 100644
--- a/drivers/media/usb/uvc/uvcvideo.h
+++ b/drivers/media/usb/uvc/uvcvideo.h
@@ -462,6 +462,13 @@ struct uvc_stats_frame {
 	u32 scr_stc;			/* SCR.STC of the last packet */
 };
 
+struct uvc_stats_time {
+	u64 duration;			/* Cumulative total duration between two events */
+	unsigned int qty;		/* Number of events represented in the total */
+	unsigned int min;		/* Shortest duration */
+	unsigned int max;		/* Longest duration */
+};
+
 struct uvc_stats_stream {
 	ktime_t start_ts;		/* Stream start timestamp */
 	ktime_t stop_ts;		/* Stream stop timestamp */
@@ -483,6 +490,8 @@ struct uvc_stats_stream {
 	unsigned int scr_sof;		/* STC.SOF of the last packet */
 	unsigned int min_sof;		/* Minimum STC.SOF value */
 	unsigned int max_sof;		/* Maximum STC.SOF value */
+
+	unsigned long bytes;		/* Successfully transferred bytes */
 };
 
 #define UVC_METATADA_BUF_SIZE 1024
@@ -512,6 +521,8 @@ struct uvc_copy_op {
  * @async_operations: counter to indicate the number of copy operations
  * @copy_operations: work descriptors for asynchronous copy operations
  * @work: work queue entry for asynchronous decode
+ * @received: URB interrupt time stamp
+ * @decode_start: URB processing start time stamp
  */
 struct uvc_urb {
 	struct urb *urb;
@@ -523,6 +534,9 @@ struct uvc_urb {
 	unsigned int async_operations;
 	struct uvc_copy_op copy_operations[UVC_MAX_PACKETS];
 	struct work_struct work;
+
+	ktime_t received;
+	ktime_t decode_start;
 };
 
 struct uvc_streaming {
@@ -585,6 +599,12 @@ struct uvc_streaming {
 	struct {
 		struct uvc_stats_frame frame;
 		struct uvc_stats_stream stream;
+		struct uvc_stats_urb {
+			struct uvc_stats_time header;
+			struct uvc_stats_time latency;
+			struct uvc_stats_time decode;
+			struct uvc_stats_time urb;
+		} urbstat;
 	} stats;
 
 	/* Timestamps support. */
-- 
2.17.1