Bug 202022
|
Description
John Reiser
2006-08-10 13:23:12 UTC
Created attachment 133941 [details]
output from lsmod (list of loaded kernel modules)
Created attachment 133942 [details]
lspci; lspci -n; lspci -v
Created attachment 133943 [details]
output from /proc/interrupts
Created attachment 133944 [details]
output from /proc/bus/usb/devices
Created attachment 133945 [details]
/var/log/messages: device configuration (boot + USB2.0)
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. 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. 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. Created attachment 292976 [details]
IRQ 11 disable
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 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. I wonder if this another manifestation of 438599 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? 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.) 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 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. (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 ----- Created attachment 301380 [details]
usbmon/1u at 120==max_sectors_kb
gzipped
Created attachment 301381 [details]
usbmon/1u at 64==max_sectors_kb
gzipped
Created attachment 301382 [details]
usbmon/1u at 32==max_sectors_kb
gzipped
Created attachment 301383 [details]
usbmon/1u at 16==max_sectors_kb
gzipped
Created attachment 301384 [details]
usbmon/1u at 8==max_sectors_kb
gzipped
Created attachment 301385 [details]
usbmon/1u at 4==max_sectors_kb
gzipped
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. 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.
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 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 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. 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 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. |