On Tue, May 17, 2005 at 03:45:40AM -0400, Glenn Maynard wrote:
> (Unfortunately, this is hard to test: sometimes we'll go a whole day without
> this happening, and the next day it'll happen every half hour. I wonder how
> I could simulate this ...)
Just to (hopefully) wrap this up:
I was finally able to reproduce and test this. Using the attached patch, I
get the attached log (hopefully not double-spaced this time), which seems to
confirm the effect, at least: hub_events loops indefinitely, never giving up
the hub long enough for anyone else to get it. Adding msleep(25) to the bottom
of the loop fixes the symptom for me: lsusb always finishes in a second or two,
instead of getting stuck until I unload ohcd_hcd. It's not a correct fix, but
due to time constraints (and paranoia) I'm opting for the simplest fix that
works.
--
Glenn Maynard
diff -ru ../../../orig/linux-2.6.12-rc3/drivers/usb/core/hub.c core/hub.c
--- ../../../orig/linux-2.6.12-rc3/drivers/usb/core/hub.c 2005-04-20
20:03:15.000000000 -0400
+++ core/hub.c 2005-05-21 01:53:37.097047691 -0400
@@ -2602,6 +2602,7 @@
u16 portchange;
int i, ret;
int connect_change;
+ pr_debug ("%s: hub_events\n", usbcore_name);
/*
* We restart the list every time to avoid a deadlock with
@@ -2610,6 +2611,7 @@
* Not the most efficient, but avoids deadlocks.
*/
while (1) {
+ pr_debug ("%s: hub_events loop\n", usbcore_name);
/* Grab the first entry at the beginning of the list */
spin_lock_irq(&hub_event_lock);
@@ -2792,6 +2794,7 @@
usb_put_intf(intf);
} /* end while (1) */
+ pr_debug ("%s: hub_events loop exit\n", usbcore_name);
}
static int hub_thread(void *__unused)
7658082.716494: <7>usbcore: hub_events loop
7658082.716509: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0010
7658082.721468: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658083.831678: <7>hub 1-3:1.0: debounce: port 4: total 950ms stable 100ms
status 0x100
7658083.831702: <7>usbcore: hub_events loop
7658083.831717: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658083.837675: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658083.954684: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658083.960684: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658085.722014: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658085.722039: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658085.724999: <7>usbcore: hub_events loop
7658085.725022: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658085.730996: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658085.845016: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658085.851016: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658086.517138: <7>hub 1-3:1.0: debounce: port 4: total 575ms stable 100ms
status 0x100
7658086.517162: <7>usbcore: hub_events loop
7658086.517178: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0010
7658086.520144: <7>usbcore: hub_events loop
7658086.520166: <7>usbcore: hub_events loop exit
7658086.557144: <7>usbcore: hub_events
7658086.557167: <7>usbcore: hub_events loop
7658086.557182: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658086.562141: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658086.676162: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658086.682162: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658086.796189: <7>hub 1-3:1.0: debounce: port 4: total 100ms stable 100ms
status 0x100
7658086.796225: <7>usbcore: hub_events loop
7658086.796241: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0000
7658086.796257: <7>usbcore: hub_events loop
7658086.796272: <7>usbcore: hub_events loop exit
7658086.813189: <7>usbcore: hub_events
7658086.813222: <7>usbcore: hub_events loop
7658086.813238: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0010
7658086.818186: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658088.584516: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658088.584540: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658088.587499: <7>usbcore: hub_events loop
7658088.587522: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658088.593497: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658088.707518: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658088.713518: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658090.404820: <7>hub 1-3:1.0: debounce: port 4: total 1450ms stable 100ms
status 0x100
7658090.404844: <7>usbcore: hub_events loop
7658090.404860: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658090.410816: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658090.554842: <7>hub 1-3:1.0: debounce: port 1: total 125ms stable 100ms
status 0x100
7658090.560842: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658092.310169: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658092.310193: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658092.313153: <7>usbcore: hub_events loop
7658092.313175: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658092.319150: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658092.433171: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658092.439171: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658094.184497: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 25ms
status 0x100
7658094.184521: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658094.187481: <7>usbcore: hub_events loop
7658094.187504: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658094.193479: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658094.307500: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658094.313500: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658096.071839: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 25ms
status 0x100
7658096.071863: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658096.074823: <7>usbcore: hub_events loop
7658096.074845: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658096.080820: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658096.197829: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658096.203829: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658097.935155: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658097.935179: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658097.938139: <7>usbcore: hub_events loop
7658097.938161: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658097.944136: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658098.058157: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658098.064157: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658099.833489: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658099.833513: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658099.836471: <7>usbcore: hub_events loop
7658099.836494: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658099.842469: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658100.013500: <7>hub 1-3:1.0: debounce: port 1: total 150ms stable 100ms
status 0x100
7658100.019499: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658101.765826: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658101.765850: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658101.768809: <7>usbcore: hub_events loop
7658101.768832: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658101.774808: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658101.888828: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658101.894828: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658103.658158: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 25ms
status 0x100
7658103.658182: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658103.661142: <7>usbcore: hub_events loop
7658103.661164: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658103.667139: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658103.781160: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658103.787161: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658105.532487: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658105.532514: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658105.535470: <7>usbcore: hub_events loop
7658105.535493: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658105.541468: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658105.712499: <7>hub 1-3:1.0: debounce: port 1: total 150ms stable 100ms
status 0x100
7658105.718499: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658107.464826: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658107.464850: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658107.467809: <7>usbcore: hub_events loop
7658107.467832: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658107.473806: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658107.587827: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658107.593827: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658109.348156: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658109.348181: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658109.351139: <7>usbcore: hub_events loop
7658109.351162: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658109.357137: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658109.471157: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658109.477158: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658111.232486: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658111.232523: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658111.235468: <7>usbcore: hub_events loop
7658111.235490: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658111.241466: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658111.355500: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658111.361498: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658113.118816: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658113.118841: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658113.121802: <7>usbcore: hub_events loop
7658113.121825: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0002
7658113.127798: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658113.436853: <7>hub 1-3:1.0: debounce: port 1: total 275ms stable 100ms
status 0x100
7658113.442853: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658115.219185: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658115.219209: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658115.222168: <7>usbcore: hub_events loop
7658115.222190: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658115.228165: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658115.342186: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658115.348187: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658117.106515: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658117.106540: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658117.109498: <7>usbcore: hub_events loop
7658117.109521: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658117.115496: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658117.229517: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658117.235517: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658119.001848: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658119.001872: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658119.004831: <7>usbcore: hub_events loop
7658119.004853: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658119.010828: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658119.208864: <7>hub 1-3:1.0: debounce: port 1: total 175ms stable 100ms
status 0x100
7658119.214863: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658120.975194: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658120.975218: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658120.978177: <7>usbcore: hub_events loop
7658120.978200: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658120.984174: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658121.098195: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658121.104196: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658122.874526: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658122.874550: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658122.877509: <7>usbcore: hub_events loop
7658122.877532: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658122.883508: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658122.997528: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658123.003528: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
7658124.763857: <7>hub 1-3:1.0: debounce: port 4: total 1500ms stable 0ms
status 0x100
7658124.763881: <3>hub 1-3:1.0: connect-debounce failed, port 4 disabled
7658124.766841: <7>usbcore: hub_events loop
7658124.766864: <7>hub 1-3:1.0: state 5 ports 4 chg 0000 evt 0012
7658124.772838: <7>hub 1-3:1.0: port 1, status 0100, change 0001, 12 Mb/s
7658124.886859: <7>hub 1-3:1.0: debounce: port 1: total 100ms stable 100ms
status 0x100
7658124.892859: <7>hub 1-3:1.0: port 4, status 0100, change 0001, 12 Mb/s
diff -ru ../../../orig/linux-2.6.12-rc3/drivers/usb/core/hub.c core/hub.c
--- ../../../orig/linux-2.6.12-rc3/drivers/usb/core/hub.c 2005-04-20
20:03:15.000000000 -0400
+++ core/hub.c 2005-05-21 02:05:57.101293136 -0400
@@ -2791,6 +2791,7 @@
usb_unlock_device(hdev);
usb_put_intf(intf);
+ msleep(25);
} /* end while (1) */
}
