From: Justin Piszcz on


On Thu, 25 Mar 2010, Alan Stern wrote:

> On Thu, 25 Mar 2010, Justin Piszcz wrote:
>
> > # cat /sys/kernel/debug/usb/devices
> >
> > T: Bus=02 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 8
> > B: Alloc= 26/900 us ( 3%), #Int= 2, #Iso= 0
> > D: Ver= 1.10 Cls=09(hub ) Sub=00 Prot=00 MxPS=64 #Cfgs= 1
> > P: Vendor=1d6b ProdID=0001 Rev= 2.06
> > S: Manufacturer=Linux 2.6.33 ohci_hcd
> > S: Product=OHCI Host Controller
> > S: SerialNumber=0000:00:0b.0
> > C:* #Ifs= 1 Cfg#= 1 Atr=e0 MxPwr= 0mA
> > I:* If#= 0 Alt= 0 #EPs= 1 Cls=09(hub ) Sub=00 Prot=00 Driver=hub
> > E: Ad=81(I) Atr=03(Int.) MxPS= 2 Ivl=255ms
> >
> > T: Bus=02 Lev=01 Prnt=01 Port=04 Cnt=01 Dev#= 2 Spd=1.5 MxCh= 0
> > D: Ver= 1.10 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
> > P: Vendor=413c ProdID=2005 Rev= 1.05
> > S: Manufacturer=DELL
> > S: Product=DELL USB Keyboard
> > C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr=100mA
> > I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=01 Driver=usbhid
> > E: Ad=81(I) Atr=03(Int.) MxPS= 8 Ivl=10ms
> >
> > T: Bus=02 Lev=01 Prnt=01 Port=05 Cnt=02 Dev#= 3 Spd=1.5 MxCh= 0
> > D: Ver= 2.00 Cls=00(>ifc ) Sub=00 Prot=00 MxPS= 8 #Cfgs= 1
> > P: Vendor=046d ProdID=c018 Rev=43.01
> > S: Manufacturer=Logitech
> > S: Product=USB Optical Mouse
> > C:* #Ifs= 1 Cfg#= 1 Atr=a0 MxPwr=100mA
> > I:* If#= 0 Alt= 0 #EPs= 1 Cls=03(HID ) Sub=01 Prot=02 Driver=usbhid
> > E: Ad=81(I) Atr=03(Int.) MxPS= 5 Ivl=10ms
>
> All right, the problematic mouse is attached to bus 2 (as is the
> keyboard). So the next step is to run a kernel with CONFIG_USB_DEBUG
> enabled. When the mouse stops working, go to
> /sys/kernel/debug/usb/ohci/0000:00:0b.0 and see what the various files
> in that directory contain. Also, check if any additional debugging
> info shows up in the system log.

Ok, done, it froze up again:

# cat async
#

# cat periodic
size = 32
0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
1 [ 98]: ed8/f674a0c0 (ls dev3 ep1in-int qlen 1 max 5 00053083)
8 [117]: ed8/f674a040
9 [ 98]: ed8/f674a0c0
16 [117]: ed8/f674a040
17 [ 98]: ed8/f674a0c0
24 [117]: ed8/f674a040
25 [ 98]: ed8/f674a0c0

# cat registers
bus pci, device 0000:00:0b.0
OHCI Host Controller
ohci_hcd
OHCI 1.0, NO legacy support registers
control 0x68f RWE RWC HCFS=operational IE PLE CBSR=3
cmdstatus 0x00000 SOC=0
intrstatus 0x00000024 FNO SF
intrenable 0x8000004a MIE RHSC RD WDH
ed_controlhead 3674a080
hcca frame 0x61e7
fmintvl 0xa7782edf FIT FSMPS=0xa778 FI=0x2edf
fmremaining 0x80002565 FRT FR=0x2565
periodicstart 0x2a2f
lsthresh 0x0628
hub poll timer off
roothub.a 01000208 POTPGT=1 NPS NDP=8(8)
roothub.b 00000000 PPCM=0000 DR=0000
roothub.status 00008000 DRWE
roothub.portstatus [0] 0x00000100 PPS
roothub.portstatus [1] 0x00000100 PPS
roothub.portstatus [2] 0x00000100 PPS
roothub.portstatus [3] 0x00000100 PPS
roothub.portstatus [4] 0x00000303 LSDA PPS PES CCS
roothub.portstatus [5] 0x00000303 LSDA PPS PES CCS
roothub.portstatus [6] 0x00000100 PPS
roothub.portstatus [7] 0x00000100 PPS

Nothing unusal in dmesg:

[ 30.569377] usb 2-5:1.0: uevent
[ 30.572365] usb 2-6:1.0: uevent
[ 1053.663314] usb usb1: uevent
[ 1053.663404] usb 1-0:1.0: uevent
[ 1053.663455] usb usb2: uevent
[ 1053.663530] usb 2-0:1.0: uevent
[ 1053.663582] usb 2-5: uevent
[ 1053.663656] usb 2-5:1.0: uevent
[ 1053.663706] usb 2-6: uevent
[ 1053.663777] usb 2-6:1.0: uevent
<ends here>

Anything else worth gathering?
Does the above output show the problem?

BTW this keyboard and mouse were used on another system for 4+ years without
any problems, so it is not a device issue.

Justin.



>
> > > Suppose you don't run X at all. Do the mouse and keyboard eventually
> > > stop working even then?
> > I have not tried that, the reason I use the host locally is for X.
>
> You should try it anyway. If the failure still occurs, then you can
> rule out any connection with X or the nVidia graphics.
It takes a very long time for it to happen when I want it to happen, but
if the above output does not help/this bug cannot be found/fixed, I can try
that too.

Justin.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Alan Stern on
On Thu, 25 Mar 2010, Justin Piszcz wrote:

> Ok, done, it froze up again:
>
> # cat async
> #
>
> # cat periodic
> size = 32
> 0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
> 1 [ 98]: ed8/f674a0c0 (ls dev3 ep1in-int qlen 1 max 5 00053083)
> 8 [117]: ed8/f674a040
> 9 [ 98]: ed8/f674a0c0
> 16 [117]: ed8/f674a040
> 17 [ 98]: ed8/f674a0c0
> 24 [117]: ed8/f674a040
> 25 [ 98]: ed8/f674a0c0
>
> # cat registers
> bus pci, device 0000:00:0b.0
> OHCI Host Controller
> ohci_hcd
> OHCI 1.0, NO legacy support registers
> control 0x68f RWE RWC HCFS=operational IE PLE CBSR=3
> cmdstatus 0x00000 SOC=0
> intrstatus 0x00000024 FNO SF
> intrenable 0x8000004a MIE RHSC RD WDH
> ed_controlhead 3674a080
> hcca frame 0x61e7
> fmintvl 0xa7782edf FIT FSMPS=0xa778 FI=0x2edf
> fmremaining 0x80002565 FRT FR=0x2565
> periodicstart 0x2a2f
> lsthresh 0x0628
> hub poll timer off
> roothub.a 01000208 POTPGT=1 NPS NDP=8(8)
> roothub.b 00000000 PPCM=0000 DR=0000
> roothub.status 00008000 DRWE
> roothub.portstatus [0] 0x00000100 PPS
> roothub.portstatus [1] 0x00000100 PPS
> roothub.portstatus [2] 0x00000100 PPS
> roothub.portstatus [3] 0x00000100 PPS
> roothub.portstatus [4] 0x00000303 LSDA PPS PES CCS
> roothub.portstatus [5] 0x00000303 LSDA PPS PES CCS
> roothub.portstatus [6] 0x00000100 PPS
> roothub.portstatus [7] 0x00000100 PPS

> Anything else worth gathering?
> Does the above output show the problem?

No, it all looks normal. As a check you could compare this with the
file contents while the mouse is still operating normally. About the
only difference should be the "hcca frame" line, which changes
constantly.

I guess the next test should be to wait for the mouse to stop working,
unplug the mouse, and then see once again what these files contain.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Justin Piszcz on


On Thu, 25 Mar 2010, Alan Stern wrote:

> On Thu, 25 Mar 2010, Justin Piszcz wrote:
>
> No, it all looks normal. As a check you could compare this with the
> file contents while the mouse is still operating normally. About the
> only difference should be the "hcca frame" line, which changes
> constantly.
>
> I guess the next test should be to wait for the mouse to stop working,
> unplug the mouse, and then see once again what these files contain.
>
> Alan Stern

Done, here is the output:

BEFORE UNPLUG:

# cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
size = 32
0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
1 [ 98]: ed8/f674a0c0 (ls dev3 ep1in-int qlen 1 max 5 00053083)
8 [117]: ed8/f674a040
9 [ 98]: ed8/f674a0c0
16 [117]: ed8/f674a040
17 [ 98]: ed8/f674a0c0
24 [117]: ed8/f674a040
25 [ 98]: ed8/f674a0c0

UNPLUG:

# cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
size = 32
0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
8 [117]: ed8/f674a040
16 [117]: ed8/f674a040
24 [117]: ed8/f674a040

AFTER PLUG BACK IN:

# cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
size = 32
0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
8 [117]: ed8/f674a040
16 [117]: ed8/f674a040
24 [117]: ed8/f674a040

KERNEL MESSAGES:

[ 30.569377] usb 2-5:1.0: uevent
[ 30.572365] usb 2-6:1.0: uevent
[ 1053.663314] usb usb1: uevent
[ 1053.663404] usb 1-0:1.0: uevent
[ 1053.663455] usb usb2: uevent
[ 1053.663530] usb 2-0:1.0: uevent
[ 1053.663582] usb 2-5: uevent
[ 1053.663656] usb 2-5:1.0: uevent
[ 1053.663706] usb 2-6: uevent
[ 1053.663777] usb 2-6:1.0: uevent
[333937.016444] hub 2-0:1.0: state 7 ports 8 chg 0000 evt 0040
[333937.016453] ohci_hcd 0000:00:0b.0: GetStatus roothub.portstatus [5] = 0x00030300 PESC CSC LSDA PPS
[333937.016458] hub 2-0:1.0: port 6, status 0300, change 0003, 1.5 Mb/s
[333937.016461] usb 2-6: USB disconnect, address 3
[333937.016463] usb 2-6: unregistering device
[333937.016465] usb 2-6: usb_disable_device nuking all URBs
[333937.016472] ohci_hcd 0000:00:0b.0: shutdown urb f6a2d540 ep1in-intr

Justin.

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Alan Stern on
On Mon, 29 Mar 2010, Justin Piszcz wrote:

> Done, here is the output:
>
> BEFORE UNPLUG:
>
> # cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
> size = 32
> 0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
> 1 [ 98]: ed8/f674a0c0 (ls dev3 ep1in-int qlen 1 max 5 00053083)
> 8 [117]: ed8/f674a040
> 9 [ 98]: ed8/f674a0c0
> 16 [117]: ed8/f674a040
> 17 [ 98]: ed8/f674a0c0
> 24 [117]: ed8/f674a040
> 25 [ 98]: ed8/f674a0c0
>
> UNPLUG:
>
> # cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
> size = 32
> 0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
> 8 [117]: ed8/f674a040
> 16 [117]: ed8/f674a040
> 24 [117]: ed8/f674a040
>
> AFTER PLUG BACK IN:
>
> # cat ./kernel/debug/usb/ohci/0000:00:0b.0/periodic
> size = 32
> 0 [117]: ed8/f674a040 (ls dev2 ep1in-int qlen 1 max 8 00083082)
> 8 [117]: ed8/f674a040
> 16 [117]: ed8/f674a040
> 24 [117]: ed8/f674a040

What about the "registers" file?

> KERNEL MESSAGES:
>
> [ 30.569377] usb 2-5:1.0: uevent
> [ 30.572365] usb 2-6:1.0: uevent
> [ 1053.663314] usb usb1: uevent
> [ 1053.663404] usb 1-0:1.0: uevent
> [ 1053.663455] usb usb2: uevent
> [ 1053.663530] usb 2-0:1.0: uevent
> [ 1053.663582] usb 2-5: uevent
> [ 1053.663656] usb 2-5:1.0: uevent
> [ 1053.663706] usb 2-6: uevent
> [ 1053.663777] usb 2-6:1.0: uevent
> [333937.016444] hub 2-0:1.0: state 7 ports 8 chg 0000 evt 0040
> [333937.016453] ohci_hcd 0000:00:0b.0: GetStatus roothub.portstatus [5] = 0x00030300 PESC CSC LSDA PPS
> [333937.016458] hub 2-0:1.0: port 6, status 0300, change 0003, 1.5 Mb/s
> [333937.016461] usb 2-6: USB disconnect, address 3
> [333937.016463] usb 2-6: unregistering device
> [333937.016465] usb 2-6: usb_disable_device nuking all URBs
> [333937.016472] ohci_hcd 0000:00:0b.0: shutdown urb f6a2d540 ep1in-intr

This all looks normal. It's possible that we've been looking for the
bug in the wrong place; maybe there's nothing wrong with the OHCI
controller.

So next you should get a usbmon trace showing what happens on bus 2
when one of these mouse failures occurs. Instructions for usbmon are
in Documentation/usb/usbmon.txt.

At the same time, just to be increase my level of certainty, you should
apply the following debugging patch for ohci-hcd. Let's see both the
usbmon trace and the dmesg log for the same event. The trace and the
debugging patch will generate plenty of output during normal operation,
but don't worry about that. Only the part starting from shortly before
the mouse quits really matters.

Alan Stern


Index: usb-2.6/drivers/usb/host/ohci-hcd.c
===================================================================
--- usb-2.6.orig/drivers/usb/host/ohci-hcd.c
+++ usb-2.6/drivers/usb/host/ohci-hcd.c
@@ -290,6 +290,8 @@ static int ohci_urb_dequeue(struct usb_h
*/
urb_priv = urb->hcpriv;
if (urb_priv) {
+ ohci_info(ohci, "start unlink urb %p, ed %p\n",
+ urb, urb_priv->ed);
if (urb_priv->ed->state == ED_OPER)
start_ed_unlink (ohci, urb_priv->ed);
}
@@ -324,6 +326,9 @@ ohci_endpoint_disable (struct usb_hcd *h

if (!ed)
return;
+ ohci_info(ohci, "disable ed %p (#%02x) state %d%s\n",
+ ed, ep->desc.bEndpointAddress, ed->state,
+ list_empty(&ed->td_list) ? "" : " (has tds)");

rescan:
spin_lock_irqsave (&ohci->lock, flags);
@@ -770,6 +775,10 @@ static irqreturn_t ohci_irq (struct usb_
return IRQ_HANDLED;
}

+ ohci_info(ohci, "int %x enable %x rm_list %p\n", ints,
+ ohci_readl(ohci, &regs->intrenable),
+ ohci->ed_rm_list);
+
/* We only care about interrupts that are enabled */
ints &= ohci_readl(ohci, &regs->intrenable);


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Justin Piszcz on


On Mon, 29 Mar 2010, Alan Stern wrote:

> On Mon, 29 Mar 2010, Justin Piszcz wrote:
>
> What about the "registers" file?
Here it is (after I plugged it back in)

bus pci, device 0000:00:0b.0
OHCI Host Controller
ohci_hcd
OHCI 1.0, NO legacy support registers
control 0x68f RWE RWC HCFS=operational IE PLE CBSR=3
cmdstatus 0x00000 SOC=0
intrstatus 0x00000020 FNO
intrenable 0x8000004e MIE RHSC RD SF WDH
ed_controlhead 7bef1b90
hcca frame 0x4657
fmintvl 0xa7782edf FIT FSMPS=0xa778 FI=0x2edf
fmremaining 0x80002b76 FRT FR=0x2b76
periodicstart 0x2a2f
lsthresh 0x0628
hub poll timer off
roothub.a 01000208 POTPGT=1 NPS NDP=8(8)
roothub.b 00000000 PPCM=0000 DR=0000
roothub.status 00008000 DRWE
roothub.portstatus [0] 0x00000100 PPS
roothub.portstatus [1] 0x00000100 PPS
roothub.portstatus [2] 0x00000100 PPS
roothub.portstatus [3] 0x00000100 PPS
roothub.portstatus [4] 0x00000303 LSDA PPS PES CCS
roothub.portstatus [5] 0x00000303 LSDA PPS PES CCS
roothub.portstatus [6] 0x00000100 PPS
roothub.portstatus [7] 0x00000100 PPS

> This all looks normal. It's possible that we've been looking for the
> bug in the wrong place; maybe there's nothing wrong with the OHCI
> controller.
>
> So next you should get a usbmon trace showing what happens on bus 2
> when one of these mouse failures occurs. Instructions for usbmon are
> in Documentation/usb/usbmon.txt.
>
> At the same time, just to be increase my level of certainty, you should
> apply the following debugging patch for ohci-hcd. Let's see both the
> usbmon trace and the dmesg log for the same event. The trace and the
> debugging patch will generate plenty of output during normal operation,
> but don't worry about that. Only the part starting from shortly before
> the mouse quits really matters.
Yes, I've done this before for a bug in the Intel USB controller (P55) on
another motherboard.. Should be doable, always funny though how it does not
happen when you are trying to make it happen.

For your patch, what does this patch against? It does not apply cleanly
for 2.6.33.

>
> Alan Stern
>
>
> Index: usb-2.6/drivers/usb/host/ohci-hcd.c
> ===================================================================
> --- usb-2.6.orig/drivers/usb/host/ohci-hcd.c
> +++ usb-2.6/drivers/usb/host/ohci-hcd.c
> @@ -290,6 +290,8 @@ static int ohci_urb_dequeue(struct usb_h
> */
> urb_priv = urb->hcpriv;
> if (urb_priv) {
> + ohci_info(ohci, "start unlink urb %p, ed %p\n",
> + urb, urb_priv->ed);
> if (urb_priv->ed->state == ED_OPER)
> start_ed_unlink (ohci, urb_priv->ed);
> }
> @@ -324,6 +326,9 @@ ohci_endpoint_disable (struct usb_hcd *h
>
> if (!ed)
> return;
> + ohci_info(ohci, "disable ed %p (#%02x) state %d%s\n",
> + ed, ep->desc.bEndpointAddress, ed->state,
> + list_empty(&ed->td_list) ? "" : " (has tds)");
>
> rescan:
> spin_lock_irqsave (&ohci->lock, flags);
> @@ -770,6 +775,10 @@ static irqreturn_t ohci_irq (struct usb_
> return IRQ_HANDLED;
> }
>
> + ohci_info(ohci, "int %x enable %x rm_list %p\n", ints,
> + ohci_readl(ohci, &regs->intrenable),
> + ohci->ed_rm_list);
> +
> /* We only care about interrupts that are enabled */
> ints &= ohci_readl(ohci, &regs->intrenable);
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/