On Sunday 29 April 2007, Dirk Försterling wrote:
> On 29.04.2007 23:17 Alan Stern wrote:
> > You might be able to get some more useful information by doing this: Turn
> > on CONFIG_USB_DEBUG and rebuild the USB drivers. Then with the new
> > drivers loaded, plug in the USB drive and unplug it again a little while
> > later. Presumably the overall system slowdown will continue. Post the
> > output from dmesg so we can see if anything strange shows up in the log.
>
> Okay, here you go:
Two strange things, one good and the other explaining your slowdown.
> (loading ehci_hcd)
> usbcore: registered new interface driver usbfs
> usbcore: registered new interface driver hub
> usbcore: registered new device driver usb
> ehci_hcd: block sizes: qh 128 qtd 96 itd 192 sitd 96
> PCI: Found IRQ 3 for device 0000:00:13.2
> PCI: Sharing IRQ 3 with 0000:00:11.0
> ehci_hcd 0000:00:13.2: EHCI Host Controller
> drivers/usb/core/inode.c: creating file 'devices'
> drivers/usb/core/inode.c: creating file '001'
> ehci_hcd 0000:00:13.2: new USB bus registered, assigned bus number 1
> ehci_hcd 0000:00:13.2: reset hcs_params 0x2204 dbg=0 cc=2 pcc=2 ordered !ppc
> ports=4
> ehci_hcd 0000:00:13.2: reset hcc_params 6872 thresh 7 uframes 256/512/1024
> ehci_hcd 0000:00:13.2: MWI active
That's the good one. It means that a more efficient PCI transaction
will be used when writing memory ... "memory write invalidate" so the
CPU data cache is managed with less overhead.
In fact this is the first time I've ever seen that message. I think it's
because your CPU has a relatively small CPU cacheline size. Larger
ones prevent Linux from turning MWI (doesn't seem right to me, but
that's the way it works for now).
> ehci_hcd 0000:00:13.2: supports USB remote wakeup
> ehci_hcd 0000:00:13.2: irq 3, io mem 0xea001000
> ehci_hcd 0000:00:13.2: reset command 080002 (park)=0 ithresh=8 period=1024
> Reset HALT
> ehci_hcd 0000:00:13.2: init command 010009 (park)=0 ithresh=1 period=256 RUN
> ehci_hcd 0000:00:13.2: USB 2.0 started, EHCI 1.00, driver 10 Dec 2004
> usb usb1: default language 0x0409
> usb usb1: new device strings: Mfr=3, Product=2, SerialNumber=1
> usb usb1: Product: EHCI Host Controller
> usb usb1: Manufacturer: Linux 2.6.21.1z1 ehci_hcd
> usb usb1: SerialNumber: 0000:00:13.2
> usb usb1: uevent
> usb usb1: usb_probe_device
> usb usb1: configuration #1 chosen from 1 choice
> usb usb1: adding 1-0:1.0 (config #1, interface 0)
> usb 1-0:1.0: uevent
> hub 1-0:1.0: usb_probe_interface
> hub 1-0:1.0: usb_probe_interface - got id
> hub 1-0:1.0: USB hub found
> hub 1-0:1.0: 4 ports detected
> hub 1-0:1.0: standalone hub
> hub 1-0:1.0: no power switching (usb 1.0)
> hub 1-0:1.0: individual port over-current protection
> hub 1-0:1.0: Single TT
> hub 1-0:1.0: TT requires at most 8 FS bit times (666 ns)
> hub 1-0:1.0: power on to power good time: 20ms
> hub 1-0:1.0: local power source is good
> hub 1-0:1.0: trying to enable port power on non-switchable hub
> hub 1-0:1.0: state 7 ports 4 chg 0000 evt 0000
> drivers/usb/core/inode.c: creating file '001'
The plug/unplug looked normal...
> Immediately after the rmmod, the network speed was up again.
As expected, since rmmod turns off the controller...
> > And include also the contents of the files in
> >
> > /sys/class/usb_host/usb_host1
This is clearly after the device enumerated, but before your
rmmod!
> ### /sys/class/usb_host/usb_host1/companion:
> (empty)
> ### /sys/class/usb_host/usb_host1/registers:
> bus pci, device 0000:00:13.2 (driver 10 Dec 2004)
> EHCI Host Controller
> EHCI 1.00, hcd state 1
> ownership 00000001
> SMI sts/enable 0xc0080000
> structural params 0x00002204
> capability params 0x00006872
> status a008 Async Recl FLR
^^^^^
> command 010009 (park)=0 ithresh=1 period=256 RUN
And that's the problem. The controller is scanning the async
schedule ... but it shouldn't be, since it's not enabled in the
command word. Where "scanning" means it's doing DMA to read
an empty async schedule ring ... a LOT of DMA, keeping your
network controllers from their DMA.
This could well be the root cause of some problems other folk
have reported. It's a "not supposed to be possible" thing.
> intrenable 37 IAA FATAL PCD ERR INT
> uframe 182d <--- (this value changes constantly)
> port 1 status 001000 POWER sig=se0
> port 2 status 001000 POWER sig=se0
> port 3 status 001000 POWER sig=se0
> port 4 status 001000 POWER sig=se0
> irq normal 13 err 0 reclaim 5 (lost 0)
> complete 12 unlink 0
> ### /sys/class/usb_host/usb_host1/periodic:
> size = 256
> ### /sys/class/usb_host/usb_host1/async:
> (empty)
I don't have time to sort this out, but the problem is quite
clear: somehow, turning off the CMD_ASE bit (to disable the
async schedule) isn't actually disabling the schedule.
There are only a few places in the EHCI driver where that bit,
and its sibling STS_ASS bit, are used. Someone with time and
a bit of skill should be able to track down what's going on,
and come up with a patch. (Read the EHCI 1.0 spec to see in
detail what the requirements are.)
The only tricky thing about turning the async schedule on or
off is that it's done in a non-blocking way. So my guess
would be that on some code path ASE is cleared before ASS
gets set, or there's a similar no-no ... likely a race of some
kind, since not every system seems to experience such problems.
- Dave
-------------------------------------------------------------------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and take
control of your XML. No limits. Just data. Click to get it now.
http://sourceforge.net/powerbar/db2/
_______________________________________________
Linux-usb-users@lists.sourceforge.net
To unsubscribe, use the last form field at:
https://lists.sourceforge.net/lists/listinfo/linux-usb-users
