USB interrupt times

USB interrupt times

[Russell King]

I've been trying to track down where all the CPU time goes while
processing USB interrupts for HID devices.  At the moment, out of
everything on the cubox, moving the mouse or even pressing a key
on the keyboard just once is far more expensive than processing an
interrupt for the network interface or handling the SDHCI port.
Handing HID actions weigh in at around 300-400us per USB interrupt.

Around two-thirds of the time for a USB HID device interrupt is
spent in the HID layer, currently tracked down to:

	for (a = 0; a < report->maxfield; a++)
		hid_input_field(hid, report->field[a], cdata, interrupt);

in hid_report_raw_event().

However, looking at hid_input_report() and its use of down_trylock(),
I'm wondering why we're trying to run this chunk of code in IRQ
context anyway?  Why not a tasklet or workqueue?

Any suggestions on why processing a key press or mouse movement is soo
expensive?

-- 
Russell King
 Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
 maintainer of:

Re: USB interrupt times

[Jiri Kosina]

On Tue, 14 Aug 2012, Russell King wrote:

> I've been trying to track down where all the CPU time goes while
> processing USB interrupts for HID devices.  At the moment, out of
> everything on the cubox, moving the mouse or even pressing a key
> on the keyboard just once is far more expensive than processing an
> interrupt for the network interface or handling the SDHCI port.
> Handing HID actions weigh in at around 300-400us per USB interrupt.
> 
> Around two-thirds of the time for a USB HID device interrupt is
> spent in the HID layer, currently tracked down to:
> 
> 	for (a = 0; a < report->maxfield; a++)
> 		hid_input_field(hid, report->field[a], cdata, interrupt);
> 
> in hid_report_raw_event().
> 
> However, looking at hid_input_report() and its use of down_trylock(),
> I'm wondering why we're trying to run this chunk of code in IRQ
> context anyway?  Why not a tasklet or workqueue?
> 
> Any suggestions on why processing a key press or mouse movement is soo
> expensive?

Actually, Henrik (added to CC) has been doing some latency improvements 
both for input core in general, and for HID devices as well lately. I 
still have his patchset in my to-review queue, as I have just came back 
from offline vacation, but the patch below definitely can't hurt and 
should significantly lower the time spent in handling the irq for hid 
device in common situation (i.e. noone listening for debugfs events).

Could you please measure how much it helps on your system?

Offloading the processing to workqueue might actually work and make sense, 
but I will have to think a little bit more about all the consequences it'd 
have throughout the rest of the code.



From: Henrik Rydberg <rydberg@euromail.se>
Subject: HID: Only dump input if someone is listening

Going through the motions of printing the debug message information
takes a long time; using the keyboard can lead to a 160 us irqsoff
latency. This patch skips hid_dump_input() when there are no open
handles, which brings latency down to 100 us.

Signed-off-by: Henrik Rydberg <rydberg@euromail.se>
---
 drivers/hid/hid-core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/drivers/hid/hid-core.c b/drivers/hid/hid-core.c
index 60ea284..5b74e78 100644
--- a/drivers/hid/hid-core.c
+++ b/drivers/hid/hid-core.c
@@ -996,7 +996,8 @@ static void hid_process_event(struct hid_device *hid, struct hid_field *field,
 	struct hid_driver *hdrv = hid->driver;
 	int ret;
 
-	hid_dump_input(hid, usage, value);
+	if (!list_empty(&hid->debug_list))
+		hid_dump_input(hid, usage, value);
 
 	if (hdrv && hdrv->event && hid_match_usage(hid, usage)) {
 		ret = hdrv->event(hid, field, usage, value);
-- 
Jiri Kosina
SUSE Labs

Re: USB interrupt times

[Russell King]

On Tue, Aug 14, 2012 at 12:54:00PM +0200, Jiri Kosina wrote:
> Actually, Henrik (added to CC) has been doing some latency improvements 
> both for input core in general, and for HID devices as well lately. I 
> still have his patchset in my to-review queue, as I have just came back 
> from offline vacation, but the patch below definitely can't hurt and 
> should significantly lower the time spent in handling the irq for hid 
> device in common situation (i.e. noone listening for debugfs events).
> 
> Could you please measure how much it helps on your system?

Ok, it looks like it's changed the maximum USB interrupt execution
time from around 364us to 255us.

If I also do a similar trick with the debug code in hid_input_report()
then I get down to 212us - iow, something like the patch below.

Given that debugfs is fairly ubiquitous in the kernel, and that this is
fairly invasive in terms of interrupt execution impact, wouldn't having
this debug code enabled by a separate Kconfig symbol be reasonable too?

diff --git a/drivers/hid/hid-core.c b/drivers/hid/hid-core.c
index 6ac0286..8daf4d1 100644
--- a/drivers/hid/hid-core.c
+++ b/drivers/hid/hid-core.c
@@ -1220,8 +1220,6 @@ int hid_input_report(struct hid_device *hid, int type, u8 *data, int size, int i
 	struct hid_report_enum *report_enum;
 	struct hid_driver *hdrv;
 	struct hid_report *report;
-	char *buf;
-	unsigned int i;
 	int ret = 0;
 
 	if (!hid)
@@ -1243,23 +1241,27 @@ int hid_input_report(struct hid_device *hid, int type, u8 *data, int size, int i
 		goto unlock;
 	}
 
-	buf = kmalloc(sizeof(char) * HID_DEBUG_BUFSIZE, GFP_ATOMIC);
+	if (!list_empty(&hid->debug_list)) {
+		unsigned int i;
+		char *buf;
 
-	if (!buf)
-		goto nomem;
+		buf = kmalloc(sizeof(char) * HID_DEBUG_BUFSIZE, GFP_ATOMIC);
+		if (!buf)
+			goto nomem;
 
-	/* dump the report */
-	snprintf(buf, HID_DEBUG_BUFSIZE - 1,
+		/* dump the report */
+		snprintf(buf, HID_DEBUG_BUFSIZE - 1,
 			"\nreport (size %u) (%snumbered) = ", size, report_enum->numbered ? "" : "un");
-	hid_debug_event(hid, buf);
+		hid_debug_event(hid, buf);
 
-	for (i = 0; i < size; i++) {
-		snprintf(buf, HID_DEBUG_BUFSIZE - 1,
+		for (i = 0; i < size; i++) {
+			snprintf(buf, HID_DEBUG_BUFSIZE - 1,
 				" %02x", data[i]);
-		hid_debug_event(hid, buf);
+			hid_debug_event(hid, buf);
+		}
+		hid_debug_event(hid, "\n");
+		kfree(buf);
 	}
-	hid_debug_event(hid, "\n");
-	kfree(buf);
 
 nomem:
 	report = hid_get_report(report_enum, data);

-- 
Russell King
 Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
 maintainer of:
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: USB interrupt times

[Henrik Rydberg]

Hi Russell,

> On Tue, Aug 14, 2012 at 12:54:00PM +0200, Jiri Kosina wrote:
> > Actually, Henrik (added to CC) has been doing some latency improvements 
> > both for input core in general, and for HID devices as well lately. I 
> > still have his patchset in my to-review queue, as I have just came back 
> > from offline vacation, but the patch below definitely can't hurt and 
> > should significantly lower the time spent in handling the irq for hid 
> > device in common situation (i.e. noone listening for debugfs events).
> > 
> > Could you please measure how much it helps on your system?
> 
> Ok, it looks like it's changed the maximum USB interrupt execution
> time from around 364us to 255us.

With the on-review input patches on top of that, the latency should
drop further. I have measured a total of 2.5 times lower latency in
other areas, so I would expect something like 150 us in 3.7 for your
case.

> If I also do a similar trick with the debug code in hid_input_report()
> then I get down to 212us - iow, something like the patch below.

Linus' master already has a patch for that code path, actually.

> Given that debugfs is fairly ubiquitous in the kernel, and that this is
> fairly invasive in terms of interrupt execution impact, wouldn't having
> this debug code enabled by a separate Kconfig symbol be reasonable too?

I would like that, too.

Thanks,
Henrik
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: USB interrupt times

[Jiri Kosina]

On Tue, 14 Aug 2012, Russell King wrote:

> > Actually, Henrik (added to CC) has been doing some latency improvements 
> > both for input core in general, and for HID devices as well lately. I 
> > still have his patchset in my to-review queue, as I have just came back 
> > from offline vacation, but the patch below definitely can't hurt and 
> > should significantly lower the time spent in handling the irq for hid 
> > device in common situation (i.e. noone listening for debugfs events).
> > 
> > Could you please measure how much it helps on your system?
> 
> Ok, it looks like it's changed the maximum USB interrupt execution
> time from around 364us to 255us.
> 
> If I also do a similar trick with the debug code in hid_input_report()
> then I get down to 212us - iow, something like the patch below.

Are you testing with kernel that contains b94e3c94aae04 already? That 
should cover that case.

-- 
Jiri Kosina
SUSE Labs

Re: USB interrupt times

[Russell King]

On Wed, Aug 15, 2012 at 11:02:37AM +0200, Jiri Kosina wrote:
> On Tue, 14 Aug 2012, Russell King wrote:
> 
> > > Actually, Henrik (added to CC) has been doing some latency improvements 
> > > both for input core in general, and for HID devices as well lately. I 
> > > still have his patchset in my to-review queue, as I have just came back 
> > > from offline vacation, but the patch below definitely can't hurt and 
> > > should significantly lower the time spent in handling the irq for hid 
> > > device in common situation (i.e. noone listening for debugfs events).
> > > 
> > > Could you please measure how much it helps on your system?
> > 
> > Ok, it looks like it's changed the maximum USB interrupt execution
> > time from around 364us to 255us.
> > 
> > If I also do a similar trick with the debug code in hid_input_report()
> > then I get down to 212us - iow, something like the patch below.
> 
> Are you testing with kernel that contains b94e3c94aae04 already? That 
> should cover that case.

No - the kernel I'm dealing with is unfortunately based upon v3.5.0-rc5
with many other patches on top (which add support for this platform.)
However, I'll pick that commit into this tree.

-- 
Russell King
 Linux kernel    2.6 ARM Linux   - http://www.arm.linux.org.uk/
 maintainer of:

Re: USB interrupt times

[Oliver Neukum]

On Tuesday 14 August 2012 12:54:00 Jiri Kosina wrote:
> Offloading the processing to workqueue might actually work and make sense, 
> but I will have to think a little bit more about all the consequences it'd 
> have throughout the rest of the code.

How would alt-sysrq be handled?

	Reagrds
		Oliver