Optimising cdc-acm throughput (problems interpreting usbmon output)

Discussion:

Richard Ash

2011-04-15 14:05:52 UTC

I have a custom board with an STM32 (arm-based) microcontroller with
built-in USB peripheral, running a modified version of ST's USB Serial
device code which makes it appear as a CDC-ACM class device. It's a
Full Speed (12Mbit) device, not High Speed. As a result, the bulk
in/out endpoints are limited in max packet size to 64 bytes, which
shows up in the lsusb -v output as expected.

This works great with the Linux CDC-ACM class driver at speeds below ~
3 Mbit/second. Above that, the data rate fails to rise as more data is
offered, I think sections of data are being lost. It's also very
sensitive to how fast the application reads the data off the serial
device in user space - my impression is that if there is a gap of any
length between read() calls, then it slows down disproportionately.

These issues are showing up with both Windows and Linux to some
extent, so I suspect a problem on the ARM, however I'm struggling to
make sense of usbmon to tell me what that problem is.

On the host side I'm currently testing using Greg's usb-2.6 GIT tree
(2.6.39rc2, pulled on Wednesday as git through corporate LAN doesn't
work) with Johan Hovold's patch set (as sent to this list, with 16v2)
applied. This seems to be the quickest of all the kernels I've tried,
which is good. It's running on an Atom motherboard, so UHCI
controllers. Board is plugged directly into the motherboard USB
socket.

On the device side the ARM is being fed data as fast as it can take it
(I believe), and should be driving the USB peripheral continuously in
double-buffered mode, allowing continuous sending of data up the USB
link.

Once it's got going, the usbmon trace looks like this:

f5146880 554152969 C Bi:4:002:1 0 128 = e6232508 0020e72e 3afcf03a
03933424 250800b0 e72e3afc f03a030e 83242508
f5146880 554152997 S Bi:4:002:1 -115 128 <
f5146500 554153005 C Bi:4:002:1 0 128 = 260800f0 e72e3afc f03a0326
cf4e2608 00d0e72e 3afcf03a 03a21d4f 260800e0
f5146500 554153009 S Bi:4:002:1 -115 128 <
f5146000 554153014 C Bi:4:002:1 0 128 = 3afcf03a 034a1b79 270800d0
e72e3afc f03a03c5 69792708 0060e72e 3afcf03a
f5146000 554153019 S Bi:4:002:1 -115 128 <
f5146980 554153024 C Bi:4:002:1 0 128 = f03a03e4 b5a32808 0060e72e
3afcf03a 036004a4 280800b0 e72e3afc f03a03dc
f5146980 554153028 S Bi:4:002:1 -115 128 <
f5146780 554153033 C Bi:4:002:1 0 128 = 03a150ce 290800e0 e72e3afc
f03a031d 9fce2908 00b0e52e 3afcf03a 0398edce
f5146780 554153038 S Bi:4:002:1 -115 128 <
f52b4600 554153043 C Bi:4:002:1 0 128 = ebf82a08 00b0e72e 3afcf03a
03cb39f9 2a0800d0 e72e3afc f03a0346 88f92a08
f52b4600 554153046 S Bi:4:002:1 -115 128 <
f52b4c80 554153051 C Bi:4:002:1 0 128 = 2c0800b0 e72e3afc f03a0357
d4232c08 00b0e62e 3afcf03a 03d22224 2c0800d0
f52b4c80 554153055 S Bi:4:002:1 -115 128 <
f52b4800 554153061 C Bi:4:002:1 0 128 = 3afcf03a 0385204e 2d0800b0
e72e3afc f03a0301 6f4e2d08 0040e82e 3afcf03a
f52b4800 554153065 S Bi:4:002:1 -115 128 <
f52b4980 554153962 C Bi:4:002:1 0 128 = f03a031f bb782e08 0070e72e
3afcf03a 039b0979 2e0800f0 e62e3afc f03a0316
f52b4980 554153980 S Bi:4:002:1 -115 128 <
f52b4780 554153988 C Bi:4:002:1 0 128 = 030c0566 2f0800b0 e72e3afc
f03a0388 53662f08 0020e72e 3afcf03a 0303a266
f52b4780 554153992 S Bi:4:002:1 -115 128 <
f52b4580 554153997 C Bi:4:002:1 0 128 = 64692f08 00b0e72e 3afcf03a
03d9b269 2f080050 e72e3afc f03a03d0 4f6a2f08
f52b4580 554154001 S Bi:4:002:1 -115 128 <
f52b4900 554154006 C Bi:4:002:1 0 128 = 2f0800b0 e92e3afc f03a0311
e96e2f08 0090e72e 3afcf03a 038d376f 2f0800e0
f52b4900 554154010 S Bi:4:002:1 -115 128 <
f52b4000 554154015 C Bi:4:002:1 0 128 = 0060e72e 3afcf03a 03d63373
2f0800f0 e72e3afc f03a0351 82732f08 0060e72e
f52b4000 554154019 S Bi:4:002:1 -115 128 <
f52b4280 554154026 C Bi:4:002:1 0 58 = e72e3afc f03a0397 7e772f08
00d0e72e 3afcf03a 038e1b78 2f080060 e72e3afc
f52b4280 554154030 S Bi:4:002:1 -115 128 <
f581ad80 554154969 C Bi:4:002:1 0 19 = 3afcf03a 03faa379 2f080060
e72e3afc f03a03
f581ad80 554154988 S Bi:4:002:1 -115 128 <
f581ad00 554154997 C Bi:4:002:1 0 23 = 6e8f7a2f 0800a0e7 2e3afcf0
3a03eadd 7a2f0800 90e72e
f581ad00 554155001 S Bi:4:002:1 -115 128

This is where I get confused - my device is apparently being asked for
128 bytes of data, and replying with 128 bytes, but only 32 bytes end
up in the output. This is for a 64 byte endpoint ...

The last two replies (with reported lengths of 19 and 23 bytes) do
have 19 and 23 bytes of output data respectively.

Can anyone explain when a length in usbmon output is not a length, and
separately why a device with 64byte max packet size is doing 128 byte
reads?

Thanks,

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

Alan Stern

2011-04-15 14:17:21 UTC

Permalink

Post by Richard Ash
I have a custom board with an STM32 (arm-based) microcontroller with
built-in USB peripheral, running a modified version of ST's USB Serial
device code which makes it appear as a CDC-ACM class device. It's a
Full Speed (12Mbit) device, not High Speed. As a result, the bulk
in/out endpoints are limited in max packet size to 64 bytes, which
shows up in the lsusb -v output as expected.
This works great with the Linux CDC-ACM class driver at speeds below ~
3 Mbit/second. Above that, the data rate fails to rise as more data is
offered, I think sections of data are being lost. It's also very
sensitive to how fast the application reads the data off the serial
device in user space - my impression is that if there is a gap of any
length between read() calls, then it slows down disproportionately.
These issues are showing up with both Windows and Linux to some
extent, so I suspect a problem on the ARM, however I'm struggling to
make sense of usbmon to tell me what that problem is.
On the host side I'm currently testing using Greg's usb-2.6 GIT tree
(2.6.39rc2, pulled on Wednesday as git through corporate LAN doesn't
work) with Johan Hovold's patch set (as sent to this list, with 16v2)
applied. This seems to be the quickest of all the kernels I've tried,
which is good. It's running on an Atom motherboard, so UHCI
controllers. Board is plugged directly into the motherboard USB
socket.
On the device side the ARM is being fed data as fast as it can take it
(I believe), and should be driving the USB peripheral continuously in
double-buffered mode, allowing continuous sending of data up the USB
link.
f5146880 554152969 C Bi:4:002:1 0 128 = e6232508 0020e72e 3afcf03a
03933424 250800b0 e72e3afc f03a030e 83242508
f5146880 554152997 S Bi:4:002:1 -115 128 <
f5146500 554153005 C Bi:4:002:1 0 128 = 260800f0 e72e3afc f03a0326
cf4e2608 00d0e72e 3afcf03a 03a21d4f 260800e0

...

Post by Richard Ash
This is where I get confused - my device is apparently being asked for
128 bytes of data, and replying with 128 bytes, but only 32 bytes end
up in the output. This is for a 64 byte endpoint ...
The last two replies (with reported lengths of 19 and 23 bytes) do
have 19 and 23 bytes of output data respectively.
Can anyone explain when a length in usbmon output is not a length, and
separately why a device with 64byte max packet size is doing 128 byte
reads?

Read the Documentation/usb/usbmon.txt file. Briefly, usbmon's text
interface displays only the first 32 bytes of each transfer. If you
want to see the complete data for each transfer, you need to use the
binary interface. The easiest way to do that is to run Wireshark,
although Pete Zaitcev has written a command-line program to do the same
thing:

http://people.redhat.com/zaitcev/linux/usbmon-5.4.tar.gz

Alan Stern

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

Richard Ash

2011-04-15 15:30:30 UTC

Permalink

Add to the usbmon documentation to clarify how much of the packet text-=
mode
users can expect to see. This is useful if packet lengths are not what =
they
were expected to be.

Signed-off-by: Richard Ash <richard-***@public.gmane.org>
---

[...]
f5146880 554152969 C Bi:4:002:1 0 128 =3D e6232508 0020e72e 3afcf03a
03933424 250800b0 e72e3afc f03a030e 83242508
f5146880 554152997 S Bi:4:002:1 -115 128 <
f5146500 554153005 C Bi:4:002:1 0 128 =3D 260800f0 e72e3afc f03a0326
cf4e2608 00d0e72e 3afcf03a 03a21d4f 260800e0

...

This is where I get confused - my device is apparently being asked f=

128 bytes of data, and replying with 128 bytes, but only 32 bytes en=

up in the output. This is for a 64 byte endpoint ...
The last two replies (with reported lengths of 19 and 23 bytes) do
have 19 and 23 bytes of output data respectively.
Can anyone explain when a length in usbmon output is not a length, a=

separately why a device with 64byte max packet size is doing 128 byt=

reads?

Read the Documentation/usb/usbmon.txt file. =A0Briefly, usbmon's text
interface displays only the first 32 bytes of each transfer. =A0If yo=

want to see the complete data for each transfer, you need to use the
binary interface. =A0The easiest way to do that is to run Wireshark,
although Pete Zaitcev has written a command-line program to do the sa=

=A0 =A0 =A0 =A0http://people.redhat.com/zaitcev/linux/usbmon-5.4.tar.=

gz

I did read that file, but because it didn't say how much of the data yo=
u might
get, missed the existence of the limit (and anyway, was concerned that
64 / 2 =3D 32).

diff -u usb-2.6-vanilla/Documentation/usb/usbmon.txt
usb-2.6-patched/Documentation/usb/usbmon.txt
--- usb-2.6-vanilla/Documentation/usb/usbmon.txt 2011-04-13
20:17:14.000000000 +0100
+++ usb-2.6-patched/Documentation/usb/usbmon.txt 2011-04-15
16:18:30.016288637 +0100
@@ -165,12 +165,12 @@
- Data words follow, in big endian hexadecimal format. Notice that the=
y are
not machine words, but really just a byte stream split into words to=
make
it easier to read. Thus, the last word may contain from one to four =
bytes.
- The length of collected data is limited and can be less than the dat=
a length
- reported in the Data Length word. In the case of an Isochronous inpu=
t (Zi)
- completion where the received data is sparse in the buffer, the leng=
th of
- the collected data can be greater than the Data Length value (becaus=
e Data
- Length counts only the bytes that were received whereas the Data wor=
ds
- contain the entire transfer buffer).
+ The length of collected data is limited to 32 bytes and can be less =
than
+ the data length reported in the Data Length word.
+ In the case of an Isochronous input (Zi) completion where the receiv=
ed data
+ is sparse in the buffer, the length of the collected data can be gre=
ater than
+ the Data Length value (because Data Length counts only the bytes tha=
t were
+ received whereas the Data words contain the entire transfer buffer).

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

Alan Stern

2011-04-15 21:07:00 UTC

Permalink

Add to the usbmon documentation to clarify how much of the packet text-mode
users can expect to see. This is useful if packet lengths are not what they
were expected to be.

The patch is fine with me (all it does is change "limited" to "limited
to 32 bytes"), but I'm not the maintainer for usbmon. That would be
Pete Zaitcev (listed in MAINTAINERS, although not for usbmon). You
should CC: your patch to him, and also to the overall USB maintainer
(Greg KH).

Also, change the email Subject: line to something more appropriate.

Alan Stern

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

Richard Ash

2011-04-15 15:38:44 UTC

Permalink

f5146880 554152969 C Bi:4:002:1 0 128 =3D e6232508 0020e72e 3afcf03a
03933424 250800b0 e72e3afc f03a030e 83242508
f5146880 554152997 S Bi:4:002:1 -115 128 <
f5146500 554153005 C Bi:4:002:1 0 128 =3D 260800f0 e72e3afc f03a0326
cf4e2608 00d0e72e 3afcf03a 03a21d4f 260800e0

...

This is where I get confused - my device is apparently being asked f=

128 bytes of data, and replying with 128 bytes, but only 32 bytes en=

separately why a device with 64byte max packet size is doing 128 byt=

reads?

Read the Documentation/usb/usbmon.txt file. =A0Briefly, usbmon's text
interface displays only the first 32 bytes of each transfer. =A0If yo=

want to see the complete data for each transfer, you need to use the
binary interface.

Thanks for the clarification, wireshark is installing.

=46or the moment I don't need to see packet contents, only the packet
lengths to work out the bit rate. Am I worrying needlessly that a devic=
e with
wMaxPacketSize 0x0040 1x 64 bytes
is doing 128 byte reads most of the time?

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

Alan Stern

2011-04-15 15:58:13 UTC

Permalink

Post by Richard Ash

Can anyone explain when a length in usbmon output is not a length,=

and

Post by Richard Ash

separately why a device with 64byte max packet size is doing 128 b=

yte

Post by Richard Ash

reads?

Read the Documentation/usb/usbmon.txt file. =A0Briefly, usbmon's te=

Post by Richard Ash

interface displays only the first 32 bytes of each transfer. =A0If =

you

Post by Richard Ash

want to see the complete data for each transfer, you need to use th=

Post by Richard Ash

binary interface.

=20
Thanks for the clarification, wireshark is installing.
=20
For the moment I don't need to see packet contents, only the packet
lengths to work out the bit rate. Am I worrying needlessly that a dev=

ice with

Post by Richard Ash
wMaxPacketSize 0x0040 1x 64 bytes
is doing 128 byte reads most of the time?

There's no direct relation between the length of a transfer and the=20
maxpacket size of the endpoint. A single transfer can comprise a=20
partial data packet or multiple data packets.

Transfer lengths are determined more by the size of the available=20
buffers, the expected transfer rate, the acceptable latency, and so on.

Alan Stern

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

Marius Kotsbak

2011-04-15 14:35:48 UTC

Permalink

I measured 14 Mbits using the CDC-ACM driver with my HSPA+ 3G modem, so
it is seems it is performing quite well, although it would possible
perform better using the CDC-NCM module (not tested yet).

--
Marius Kotsbak

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

Steve Calfee

2011-04-15 19:05:57 UTC

Permalink

Post by Marius Kotsbak

Hi Marius,

That is a very impressive rate considering you are on a 12Mhz bus!
Usually a FS max transfer rate tops out around 1Mbyte per second. Is
your data being sent compressed?

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

Marius Kotsbak

2011-04-15 19:19:43 UTC

Permalink

Post by Steve Calfee

Post by Marius Kotsbak
I measured 14 Mbits using the CDC-ACM driver with my HSPA+ 3G modem, so
it is seems it is performing quite well, although it would possible
perform better using the CDC-NCM module (not tested yet).
--
Marius Kotsbak

Hi Marius,
That is a very impressive rate considering you are on a 12Mhz bus!
Usually a FS max transfer rate tops out around 1Mbyte per second. Is
your data being sent compressed?

Well, it is USB 2.0, which seems to support 480 Mbits/s.

--
Marius

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