Bug 202022 - slow (780KB/s) USB2.0 + VT82xxxx + yenta (cardbus pcmcia)
slow (780KB/s) USB2.0 + VT82xxxx + yenta (cardbus pcmcia)
Status: CLOSED WONTFIX
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
10
i386 Linux
medium Severity medium
: ---
: ---
Assigned To: Pete Zaitcev
Brian Brock
bzcl34nup
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2006-08-10 09:23 EDT by John Reiser
Modified: 2009-12-18 00:53 EST (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-12-18 00:53:04 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
output from lsmod (list of loaded kernel modules) (2.40 KB, text/plain)
2006-08-10 09:25 EDT, John Reiser
no flags Details
lspci; lspci -n; lspci -v (6.77 KB, text/plain)
2006-08-10 09:26 EDT, John Reiser
no flags Details
output from /proc/interrupts (585 bytes, text/plain)
2006-08-10 09:29 EDT, John Reiser
no flags Details
output from /proc/bus/usb/devices (2.30 KB, text/plain)
2006-08-10 09:32 EDT, John Reiser
no flags Details
/var/log/messages: device configuration (boot + USB2.0) (20.53 KB, text/plain)
2006-08-10 09:35 EDT, John Reiser
no flags Details
IRQ 11 disable (7.87 KB, text/plain)
2008-01-25 14:42 EST, Rudolf Ulc
no flags Details
usbmon/1u at 120==max_sectors_kb (5.22 KB, application/octet-stream)
2008-04-05 13:47 EDT, John Reiser
no flags Details
usbmon/1u at 64==max_sectors_kb (4.97 KB, application/octet-stream)
2008-04-05 13:47 EDT, John Reiser
no flags Details
usbmon/1u at 32==max_sectors_kb (6.64 KB, application/octet-stream)
2008-04-05 13:48 EDT, John Reiser
no flags Details
usbmon/1u at 16==max_sectors_kb (10.30 KB, application/octet-stream)
2008-04-05 13:49 EDT, John Reiser
no flags Details
usbmon/1u at 8==max_sectors_kb (15.52 KB, application/octet-stream)
2008-04-05 13:49 EDT, John Reiser
no flags Details
usbmon/1u at 4==max_sectors_kb (29.12 KB, application/octet-stream)
2008-04-05 13:50 EDT, John Reiser
no flags Details
lspci output for new PCcard (IOgear brand) (6.50 KB, text/plain)
2008-04-22 14:05 EDT, John Reiser
no flags Details

  None (edit)
Description John Reiser 2006-08-10 09:23:12 EDT
Description of problem: Reading a USB2.0 flash drive gives only 780KB/s
throughput when connected via cardbus that uses VT82xxxx.  The same hardware
gives 4.9MB/s under cygwin on Microsoft Windows ME.


Version-Release number of selected component (if applicable):
kernel-2.6.17-1.2139_FC5

How reproducible:
always

Steps to Reproduce:
1. create file of 196,608,000 bytes on USB2.0 flash storage (dd if=/dev/zero
of=flash bs=32k count=6000)
2. reboot (to be sure no caching)
3. time dd if=flash of=/dev/null bs=32k
  
Actual results:
492 seconds (780KB/s)

Expected results:
40.1 seconds (4.9MB/s) achieved under cygwin on WinME.

Additional info:  /proc/bus/usb/devices shows that the flash drive was connected
to the USB2.0 side (speed=480); /var/log/messages also says so.  I will attach
output from lspci, /proc/interrupts, lsmod, /proc/usb/devices,
/var/log/messages.  Write speed under cygwin was 6.7MB/s (196MB in 29.7
seconds).  Note that the cardbus buffer is only 2x256 bytes for USB2.0, plus two
256-byte buffers for USB1.0.  The same device also has ieee1394 with a 2KB
buffer, and transfers 17MB/s from an external harddrive.  The system can
transfer 21MB/s from its own internal harddrive.
Comment 1 John Reiser 2006-08-10 09:25:28 EDT
Created attachment 133941 [details]
output from lsmod (list of loaded kernel modules)
Comment 2 John Reiser 2006-08-10 09:26:37 EDT
Created attachment 133942 [details]
lspci; lspci -n; lspci -v
Comment 3 John Reiser 2006-08-10 09:29:05 EDT
Created attachment 133943 [details]
output from /proc/interrupts
Comment 4 John Reiser 2006-08-10 09:32:50 EDT
Created attachment 133944 [details]
output from /proc/bus/usb/devices
Comment 5 John Reiser 2006-08-10 09:35:55 EDT
Created attachment 133945 [details]
/var/log/messages: device configuration (boot + USB2.0)
Comment 6 Dave Jones 2006-10-16 16:39:37 EDT
A new kernel update has been released (Version: 2.6.18-1.2200.fc5)
based upon a new upstream kernel release.

Please retest against this new kernel, as a large number of patches
go into each upstream release, possibly including changes that
may address this problem.

This bug has been placed in NEEDINFO state.
Due to the large volume of inactive bugs in bugzilla, if this bug is
still in this state in two weeks time, it will be closed.

Should this bug still be relevant after this period, the reporter
can reopen the bug at any time. Any other users on the Cc: list
of this bug can request that the bug be reopened by adding a
comment to the bug.

In the last few updates, some users upgrading from FC4->FC5
have reported that installing a kernel update has left their
systems unbootable. If you have been affected by this problem
please check you only have one version of device-mapper & lvm2
installed.  See bug 207474 for further details.

If this bug is a problem preventing you from installing the
release this version is filed against, please see bug 169613.

If this bug has been fixed, but you are now experiencing a different
problem, please file a separate bug for the new problem.

Thank you.
Comment 7 John Reiser 2006-10-17 12:28:35 EDT
The problem persists in kernel-2.6.18-1.2200.fc5.  For a file of 196,608,000
bytes on USB2.0 flash storage, "dd if=flash of=/dev/null bs=32k" took 368.4
seconds (534KB/s) under FC5, but only 34.9 seconds (5.6MB/s) under cygwin-WinME
on the same physical equipment.  The FC5 measurements were within a second or
two regardless of booting with kernel commandline option "irqpoll" or not.  FC5
also hung a few times (console freeze [no blinking X11 gnome-terminal cursor]
and no messages in /var/log/messages; power cycle reboot was required to
recover) while trying to make the measurements.  There was no hang under
cygwin-WinME.
Comment 8 Rudolf Ulc 2008-01-25 14:41:07 EST
The problem persist in Fedora 8, kernel kernel-2.6.23.9-85.fc8. Hardware is 
PCMCIA USB 2.0 Kouwell KW-2002-2, notebook IBM Thinkpad T23, and flash storage 
speed only 700 KB/s. After copy 1 GB from flash storage, IRQ 11 disable. 
Comment 9 Rudolf Ulc 2008-01-25 14:42:02 EST
Created attachment 292976 [details]
IRQ 11 disable
Comment 10 Bug Zapper 2008-04-03 23:30:26 EDT
Fedora apologizes that these issues have not been resolved yet. We're
sorry it's taken so long for your bug to be properly triaged and acted
on. We appreciate the time you took to report this issue and want to
make sure no important bugs slip through the cracks.

If you're currently running a version of Fedora Core between 1 and 6,
please note that Fedora no longer maintains these releases. We strongly
encourage you to upgrade to a current Fedora release. In order to
refocus our efforts as a project we are flagging all of the open bugs
for releases which are no longer maintained and closing them.
http://fedoraproject.org/wiki/LifeCycle/EOL

If this bug is still open against Fedora Core 1 through 6, thirty days
from now, it will be closed 'WONTFIX'. If you can reporduce this bug in
the latest Fedora version, please change to the respective version. If
you are unable to do this, please add a comment to this bug requesting
the change.

Thanks for your help, and we apologize again that we haven't handled
these issues to this point.

The process we are following is outlined here:
http://fedoraproject.org/wiki/BugZappers/F9CleanUp

We will be following the process here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping to ensure this
doesn't happen again.

And if you'd like to join the bug triage team to help make things
better, check out http://fedoraproject.org/wiki/BugZappers
Comment 11 John Reiser 2008-04-04 19:55:42 EDT
Please change 'Version' to 8; bugzilla won't let me.

The problem persists in Fedora 8 kernel-2.6.24.4-64.fc8.  A USB 2.0 flash device
reads only 641KB/s (327680000 bytes in 511.488 seconds; "time dd if=320MiB_file
bs=32k of=/dev/null")  The same hardware running with Cygwin on WindowsME reads
7.5MB/s (327680000 bytes in 45.248 seconds) which is more than ten times as
fast.  The device can accept write data at 3.3 MB/s under Fedora.  The device
definitely is a USB 2.0 device, at least /proc/bus/usb/devices has "Spd=480". 
Remember it is attached to a PCMCIA CardBus adapter that has 2x 256-bytes buffer
for USB2.0, and two USB1.1 controllers, each with one 256-byte buffer.  The
CardBus adapter also has a firewire (IEEE1354) device with a 2KB buffer. 
Speculation: somehow the driver is treating it as a USB1.1 device (limited to
12Mbit/s), or the 2 hardware buffers are not being used as a double buffer for
the purpose of sustaining continuous data transfer.
Comment 12 Dave Jones 2008-04-04 20:31:21 EDT
I wonder if this another manifestation of 438599
Comment 13 Pete Zaitcev 2008-04-04 21:02:22 EDT
I really don't know how to help this. I can only say that whatever
buffers are on the Cardbus card is not very relevant to us. Even if
they exist, they are either not visible to software, or useless.

This can be caused by any number of reasons:
 - device not liking the block size we request and boggling down
 - PCI master parameters not optimal for the HC
 - MTRR not set right (although that would probably slow whole box)
 - other?
Comment 14 John Reiser 2008-04-05 00:53:01 EDT
What stands in the way of finding a more explicit cause for the slowness?  Does
changing the blocksize in the user application-level 'dd' command cause a change
in the blocksize that the driver requests from the device?  Is there any other
way I can test changing the blocksize that the driver requests?  How can I find
out the actual blocksize used by the driver<->device interface?  How can I
determine whether automatic buffered readahead is taking place?  Can I learn
useful information by poking around in the Device Manager of ControlPanel on
Windows?

The same slowness occurs with USB2.0 flash memory devices from four different
brands (PNY, SanDisk, Kingston, HP.)  
Comment 15 Pete Zaitcev 2008-04-05 01:58:02 EDT
No, in Linux block devices are always buffered. Application block size
is irrelevant. The size the block layer uses is set with sysfs. Try
to poke around these:
 /sys/block/sda/queue/max_hw_sectors_kb
 /sys/block/sda/queue/max_sectors_kb
Windows always uses a small block size when talking to USB devices, not
more than 32KB.

While doing that, the best would be to tap into the traffic with usbmon.
It provides good timestamps, so you'd see the finer grained picture.
You'd know if reducing block size makes device to respond faster. See:
/usr/share/doc/kernel-doc-2.6.24/Documentation/usb/usbmon.txt
Comment 16 Pete Zaitcev 2008-04-05 02:02:53 EDT
BTW, I'm afraid it's not the device which is at fault. Something is up
with the controller on that CardBus thing. For that, usbmon is not
good enough, it does not show us all the little descriptors that the
controller uses. Knowing what happens to controller schedules requires
special instrumentation (e.g. someone has to write that for this bug).

It's still worth to vary the block size and attach a couple of usbmon
traces to the bug. Maybe something obvious pops up when I see them.
Comment 17 John Reiser 2008-04-05 13:43:08 EDT
(In reply to comment #16)

> Knowing what happens to controller schedules requires
> special instrumentation (e.g. someone has to write that for this bug).

Where should I start (which particular source files), and what is the name of
the timestamp variable or subroutine?

> It's still worth to vary the block size and attach a couple of usbmon
> traces to the bug. Maybe something obvious pops up when I see them.

max_hw_sectors_kb was 120 (not 128) and was read-only.
max_sectors_kb was 120 and could be written.  So I experimented using
"echo 64 > max_sectors_kb" etc.  I'll attach compressed usbmon traces shortly.
In general the speed increased to a maximum of 1.1MB/s at 8==max_sectors_kb, and
could not be set below 4==max_sectors_kb.
-----
$ dd if=320mb bs=32k count=100 of=/dev/null
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 5.32992 s, 615 kB/s   ## 120==max_sectors_kb

$ dd if=320mb bs=32k count=100 of=/dev/null skip=100
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 4.76116 s, 688 kB/s   ## 64==max_sectors_kb

$ dd if=320mb bs=32k count=100 of=/dev/null skip=200
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 4.32364 s, 758 kB/s   ## 32==max_sectors_kb

$ dd if=320mb bs=32k count=100 of=/dev/null skip=30
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 3.5734 s, 917 kB/s   ## 16==max_sectors_kb

$ dd if=320mb bs=32k count=100 of=/dev/null skip=400
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 2.99369 s, 1.1 MB/s   ## 8==max_sectors_kb

$ dd if=320mb bs=32k count=100 of=/dev/null skip=500
100+0 records in
100+0 records out
3276800 bytes (3.3 MB) copied, 3.20851 s, 1.0 MB/s   ## 4==max_sectors_kb
$ 
-----

The mount of debugfs succeeded, but the modprobe of usbmon failed for
2.6.24.4-64.fc8.  There was no 'usbmon' neither in the output of lsmod, nor any
'usbmon*' driver below /lib/modules/2.6.24.4-64.fc8.  However, the "ls
/sys/kernel/debug/usbmon" gave the list "0s 0t 0u 1s ...", so I'll assume that
is OK.

The /proc/bus/usb/devices entry is:
-----
T:  Bus=01 Lev=01 Prnt=01 Port=01 Cnt=01 Dev#=  2 Spd=480 MxCh= 0
D:  Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS=64 #Cfgs=  1
P:  Vendor=03f0 ProdID=2107 Rev= 1.00
S:  Manufacturer=HP v120w
S:  Product=HP v120w
S:  SerialNumber=73b4fa94d7b174
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr= 80mA
I:* If#= 0 Alt= 0 #EPs= 3 Cls=08(stor.) Sub=06 Prot=50 Driver=usb-storage
E:  Ad=01(O) Atr=02(Bulk) MxPS= 512 Ivl=125us
E:  Ad=82(I) Atr=02(Bulk) MxPS= 512 Ivl=0ms
E:  Ad=83(I) Atr=03(Int.) MxPS=  64 Ivl=16ms
-----
Comment 18 John Reiser 2008-04-05 13:47:06 EDT
Created attachment 301380 [details]
usbmon/1u at 120==max_sectors_kb

gzipped
Comment 19 John Reiser 2008-04-05 13:47:49 EDT
Created attachment 301381 [details]
usbmon/1u at 64==max_sectors_kb

gzipped
Comment 20 John Reiser 2008-04-05 13:48:26 EDT
Created attachment 301382 [details]
usbmon/1u at 32==max_sectors_kb

gzipped
Comment 21 John Reiser 2008-04-05 13:49:06 EDT
Created attachment 301383 [details]
usbmon/1u at 16==max_sectors_kb

gzipped
Comment 22 John Reiser 2008-04-05 13:49:41 EDT
Created attachment 301384 [details]
usbmon/1u at 8==max_sectors_kb

gzipped
Comment 23 John Reiser 2008-04-05 13:50:17 EDT
Created attachment 301385 [details]
usbmon/1u at 4==max_sectors_kb

gzipped
Comment 24 Pete Zaitcev 2008-04-06 21:16:44 EDT
Let's look at this (in the first trace):

d2ffd680 2715166762 S Bi:1:002:2 -115 8192 <
d2ffd700 2715166775 S Bi:1:002:2 -115 16384 <
d2ffd780 2715166780 S Bi:1:002:2 -115 16384 <
d2ffd800 2715166785 S Bi:1:002:2 -115 16384 <
d2ffd880 2715166789 S Bi:1:002:2 -115 16384 <
d2ffd900 2715166795 S Bi:1:002:2 -115 16384 <
d2ffd980 2715166799 S Bi:1:002:2 -115 16384 <
d2ffda00 2715166804 S Bi:1:002:2 -115 16384 <
d2ffd680 2715175971 C Bi:1:002:2 0 8192 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd700 2715275971 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd780 2715275980 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd800 2715275985 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd880 2715373227 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd900 2715373236 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffd980 2715373242 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d2ffda00 2715373246 C Bi:1:002:2 0 16384 = 00000000 00000000 00000000 00000000
00000000 00000000 00000000 00000000
d3183680 2715373287 S Bi:1:002:2 -115 13 <

It's clear as day that callbacks for big reads arrive in clumps
of about 3 at 100ms intervals, which is the value of TIMER_IO_WATCHDOG.

So, the system loses interrupts. Why? Beats me. I suspect that the
specific EHCI silicon doesn't like something that we do, but I don't
know what that might be. I haven't seen anything like this before.
Comment 25 John Reiser 2008-04-22 14:05:34 EDT
Created attachment 303348 [details]
lspci output for new PCcard (IOgear brand)

This PCcard works (made by IOgear with NEC USB2.0 chip, instead of Zonet with
VIA chip): 10.1 MB/s reading, which is faster than the 9.2 MB/s on the same
hardware in cygwin on WindowsME.  So the problem lies in the linux kernel
driver for the VIA hardware.
Comment 26 Bug Zapper 2008-11-26 02:00:45 EST
This message is a reminder that Fedora 8 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 8.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '8'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 8's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 8 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 27 John Reiser 2008-11-30 16:48:35 EST
Works for me today under kernel-2.6.27.5-117.fc10.i686.

# echo 1 >/proc/sys/vm/drop_caches
# time dd if=flash bs=32k of=/dev/null
6000+0 records in
6000+0 records out
196608000 bytes (197 MB) copied, 16.8209 s, 11.7 MB/s

06:00.0 USB Controller: NEC Corporation USB (rev 44)
06:00.1 USB Controller: NEC Corporation USB 2.0 (rev 05)
06:00.0 0c03: 1033:0035 (rev 44)
06:00.1 0c03: 1033:00e0 (rev 05)

00:03.0 CardBus bridge: Texas Instruments PCI1420 PC card Cardbus Controller
00:03.1 CardBus bridge: Texas Instruments PCI1420 PC card Cardbus Controller
00:03.0 0607: 104c:ac51
00:03.1 0607: 104c:ac51
Comment 28 John Reiser 2008-11-30 17:00:32 EST
However the VT82xxxx still is slow:
kernel-2.6.27.5-117.fc10.i686

# echo 1 >/proc/sys/vm/drop_caches
# time dd if=flash bs=32k of=/dev/null
6000+0 records in
6000+0 records out
196608000 bytes (197 MB) copied, 276.482 s, 711 kB/s

06:00.0 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 61)
06:00.1 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 61)
06:00.2 USB Controller: VIA Technologies, Inc. USB 2.0 (rev 63)

06:00.0 0c03: 1106:3038 (rev 61)
06:00.1 0c03: 1106:3038 (rev 61)
06:00.2 0c03: 1106:3104 (rev 63)

I am changing this Bugzilla report to be against Fedora 10.
Comment 29 Bug Zapper 2009-11-18 03:07:27 EST
This message is a reminder that Fedora 10 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 10.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '10'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 10's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 10 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 30 Bug Zapper 2009-12-18 00:53:04 EST
Fedora 10 changed to end-of-life (EOL) status on 2009-12-17. Fedora 10 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.

Note You need to log in before you can comment on or make changes to this bug.