Hi,
On Wed, Dec 09, 2009 at 11:15:50AM -0500, Alan Stern wrote:
> I know extremely little about the operation of FTDI chips, so you'll
> have to figure the rest of this out by yourself. In particular, I
> don't know what's significanct in the usbmon data.
>
> But at least now you are started off in a productive direction.
Well, not so sure after all... ;)
I slightly upgraded, to 2.6.31.9 (from .6), and now I found something
rather more interesting: on this platform, I can plug/unplug things
as I like, as long as I don't open() anything.
After I actually did a cat /dev/ttyUSB0 (doesn't matter whether FTDI
8U232AM or pl2303 or FTDI 232RL), after the next unplug things will then
have gone haywire, with the result being this trace:
SysRq : Show Blocked State
task PC stack pid father
khubd D 8000b3d0 0 59 2 0x00100000
Stack : 00000000 8014d8b8 81c57dbc 00000004 1000d001 0002b880 00000001
80340000
81c57d28 00000003 00000002 00000001 00000003 8000b3d0 81c57dec
00000004
81c56000 81c57d48 815209b4 803a6628 0002b880 8003d6b4 81c2f000
803a6220
00000000 00000000 00000000 00000000 00000000 ffffffff a1dcb480
1000d001
81dca080 81dca158 81eb4258 801dbbe0 81eb4258 81eb4b00 00000001
81eb4b68
...
Call Trace:
[<8000acd4>] schedule+0x5b8/0x638
[<8000b3d0>] schedule_timeout+0x1d4/0x210
[<801dbbe0>] ehci_endpoint_disable+0x134/0x298
[<801cb558>] usb_disable_device+0x88/0x1cc
[<801c49c0>] usb_disconnect+0x104/0x264
[<801c60d8>] hub_thread+0x854/0x1664
[<8004a92c>] kthread+0x7c/0x84
[<8000fb4c>] kernel_thread_helper+0x10/0x18
Sched Debug Version: v0.09, 2.6.31.9-svn16441 #1
now at 1014147.892210 msecs
.jiffies : 178303
.sysctl_sched_latency : 20.000000
.sysctl_sched_min_granularity : 4.000000
.sysctl_sched_wakeup_granularity : 5.000000
.sysctl_sched_child_runs_first : 0.000001
.sysctl_sched_features : 113917
cpu#0
.nr_running : 1
.load : 1024
.nr_switches : 100686
.nr_load_updates : 63373
.nr_uninterruptible : 1
.next_balance : 0.000000
.curr->pid : 1122
.clock : 1013212.000000
IOW, it seems to keep waiting for QH_STATE_LINKED, QH_STATE_UNLINK or
QH_STATE_UNLINK_WAIT to clear.
Trying a lsusb then hangs on:
lsusb D 8000b234 0 1537 1122 0x00100000
Stack : 8033f900 8004fc24 00008000 80038244 8000c8b8 00000002 7fffffff 7fe757e8
004631c0 00462150 81de729c 81de7ba8 7fe75824 8000b234 00001000 81fa9da4
00002000 00000000 00010000 80001420 8033dab8 800272a8 003d0900 00000000
81fa9d00 8033f900 81dca080 10009001 81dca120 00000006 81112000 00000002
804ee480 7fe757e8 004631c0 8000c8b8 00000002 00000002 00000080 814f5558
...
Call Trace:
[<8000acd4>] schedule+0x5b8/0x638
[<8000b234>] schedule_timeout+0x38/0x210
[<8000c8b8>] __down+0x78/0xd0
[<80050698>] down+0x48/0x84
[<801d3374>] usbdev_ioctl+0x60/0x1804
[<800aecd0>] do_vfs_ioctl+0x61c/0x680
[<800aed84>] sys_ioctl+0x50/0x88
[<800031f0>] stack_done+0x20/0x3c
Trying to rmmod pl2303 then hangs on (most likely uninteresting):
[<8000acd4>] schedule+0x5b8/0x638
[<8000b234>] schedule_timeout+0x38/0x210
[<8000c8b8>] __down+0x78/0xd0
[<80050698>] down+0x48/0x84
[<8018f848>] driver_detach+0x54/0xb0
[<8018e6d0>] bus_remove_driver+0xd0/0x13c
[<801cde90>] usb_deregister+0xb8/0xd8
[<81438024>] pl2303_exit+0x14/0x28 [pl2303]
[<80065120>] sys_delete_module+0x234/0x2d8
[<800031f0>] stack_done+0x20/0x3c
It could also be that the open simply caused more USB traffic - I
suspect that perhaps _some_ of the URBs simply get stuck on this HC
(with likelihood higher with an opened device due to higher traffic).
And thus some URBs remain in-flight and the USB stack is unable to do
a proper shutdown.
However so far I haven't managed to make it hang by simply plugging/unplugging
(without opening the devices at all)...
Note that as an alternate debug attempt, using an USB audio card
and opening the mixer device does NOT cause the unplug to get stuck.
And also note than on ohci/x86 there's no such issue, on 2.6.32.1.
(neither on 2.6.31.6 uhci/x86).
Thus I'm currently suspecting operation of the ohci-ssb / ehci-ssb
drivers (or remaining problems with silicon bugs there).
ohci-ssb / ehci-ssb drivers are daisy-chained in a weird way,
since there's only one base SSB bus device, thus ohci needs to co-maintain
(launch) its ehci brother. And both drivers use IRQF_DISABLED | IRQF_SHARED
(resulting in sitting on the same IRQ, 6, without any other devices).
I've been testing several things in the ftdi_sio area before
(such as reset timing etc. or calling usb_clear_halt() etc.),
but so far everything certainly points away from ftdi_sio and towards HC issues
(especially since the pl2303 driver locks up, too).
Hmm - or is it a problem on the usb-serial level?
Interchanging various active/passive hubs etc. doesn't really change matters...
And the register set with or without open (and thus broken plugging)
remains very similar, only the counter values are changed when diffing:
/debug/usb/ohci# cat ssb0\:1/registers
bus ssb, device ssb0:1
SSB OHCI Controller
ohci_hcd
OHCI 1.0, NO legacy support registers
control 0x083 HCFS=operational CBSR=3
cmdstatus 0x00000 SOC=0
intrstatus 0x00000024 FNO SF
intrenable 0x8000005a MIE RHSC UE RD WDH
ed_controlhead 01ddb000
hcca frame 0x91ff
fmintvl 0xa7782edf FIT FSMPS=0xa778 FI=0x2edf
fmremaining 0x80001ab9 FRT FR=0x1ab9
periodicstart 0x2a2f
lsthresh 0x0628
hub poll timer off
roothub.a 02001202 POTPGT=2 NOCP NPS NDP=2(2)
roothub.b 00000000 PPCM=0000 DR=0000
roothub.status 00008000 DRWE
roothub.portstatus [0] 0x00000100 PPS
roothub.portstatus [1] 0x00000100 PPS
Another (albeit isolated) interesting fact is that cat /dev/ttyUSB0 on
the pl2303 driver will sit there and keep reading,
whereas the same thing on ftdi_sio driver (no matter which adapter)
will return immediately (tty stuff I guess, not USB).
Now the entire dmesg log of a successful USB pull:
drivers/usb/serial/usb-serial.c: get_free_serial - minor base = 0
drivers/usb/serial/usb-serial.c: usb_serial_probe - registering ttyUSB0
kobject: 'ttyUSB0' (81e4c148): kobject_add_internal: parent: '2-1.1.6:1.0', set: 'devices'
kobject: 'ttyUSB0' (81e4c148): kobject_uevent_env
kobject: 'ttyUSB0' (81e4c148): fill_kobj_path: path = '/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6/2-1.1.6:1.0/ttyUSB0'
kobject: 'tty' (81498b00): kobject_add_internal: parent: 'ttyUSB0', set: '<NULL>'
kobject: 'ttyUSB0' (81e4c688): kobject_add_internal: parent: 'tty', set: 'devices'
kobject: 'ttyUSB0' (81e4c688): kobject_uevent_env
kobject: 'ttyUSB0' (81e4c688): fill_kobj_path: path = '/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6/2-1.1.6:1.0/ttyUSB0/tty/
ttyUSB0'
usb 2-1.1.6: pl2303 converter now attached to ttyUSB0
kobject: 'pl2303' (81ee0a80): kobject_uevent_env
kobject: 'pl2303' (81ee0a80): fill_kobj_path: path = '/bus/usb/drivers/pl2303'
usbcore: registered new interface driver pl2303
pl2303: Prolific PL2303 USB to serial adaptor driver
hub 2-1.1:1.0: state 7 ports 7 chg 0000 evt 0040
hub 2-1.1:1.0: port 6, status 0100, change 0001, 12 Mb/s
usb 2-1.1.6: USB disconnect, address 8
usb 2-1.1.6: unregistering device
usb 2-1.1.6: usb_disable_device nuking all URBs
usb 2-1.1.6: unregistering interface 2-1.1.6:1.0
kobject: 'ep_81' (81e93090): kobject_uevent_env
kobject: 'ep_81' (81e93090): kobject_uevent_env: filter function caused the event to drop!
kobject: 'ep_81' (81e93090): kobject_cleanup
kobject: 'ep_81' (81e93090): calling ktype release
kobject: 'ep_81': free name
kobject: 'ep_02' (81e88090): kobject_uevent_env
kobject: 'ep_02' (81e88090): kobject_uevent_env: filter function caused the event to drop!
kobject: 'ep_02' (81e88090): kobject_cleanup
kobject: 'ep_02' (81e88090): calling ktype release
kobject: 'ep_02': free name
kobject: 'ep_83' (81e88b90): kobject_uevent_env
kobject: 'ep_83' (81e88b90): kobject_uevent_env: filter function caused the event to drop!
kobject: 'ep_83' (81e88b90): kobject_cleanup
kobject: 'ep_83' (81e88b90): calling ktype release
kobject: 'ep_83': free name
drivers/usb/serial/usb-serial.c: usb_serial_disconnect
kobject: 'ttyUSB0' (81e4c688): kobject_uevent_env
kobject: 'ttyUSB0' (81e4c688): fill_kobj_path: path =
'/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6/2-1.1.6:1.0/ttyUSB0/tty/
ttyUSB0'
kobject: 'tty' (81498b00): kobject_cleanup
kobject: 'tty' (81498b00): auto cleanup kobject_del
kobject: 'tty' (81498b00): calling ktype release
kobject: (81498b00): dynamic_kobj_release
kobject: 'tty': free name
kobject: 'ttyUSB0' (81e4c688): kobject_cleanup
kobject: 'ttyUSB0' (81e4c688): calling ktype release
kobject: 'ttyUSB0': free name
pl2303 ttyUSB0: pl2303 converter now disconnected from ttyUSB0
kobject: 'ttyUSB0' (81e4c148): kobject_uevent_env
kobject: 'ttyUSB0' (81e4c148): fill_kobj_path: path =
'/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6/2-1.1.6:1.0/ttyUSB0'
drivers/usb/serial/generic.c: usb_serial_generic_disconnect
drivers/usb/serial/generic.c: generic_cleanup - port 0
drivers/usb/serial/usb-serial.c: destroy_serial - pl2303
drivers/usb/serial/usb-serial.c: return_serial
kobject: 'ttyUSB0' (81e4c148): kobject_cleanup
kobject: 'ttyUSB0' (81e4c148): calling ktype release
drivers/usb/serial/usb-serial.c: port_release - ttyUSB0
kobject: 'ttyUSB0': free name
pl2303 2-1.1.6:1.0: device disconnected
kobject: '2-1.1.6:1.0' (81e927a8): kobject_uevent_env
kobject: '2-1.1.6:1.0' (81e927a8): fill_kobj_path: path =
'/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6/2-1.1.6:1.0'
usb 2-1.1.6:1.0: uevent
kobject: '2-1.1.6:1.0' (81e927a8): kobject_cleanup
kobject: '2-1.1.6:1.0' (81e927a8): calling ktype release
kobject: '2-1.1.6:1.0': free name
kobject: 'ep_00' (81e86890): kobject_uevent_env
kobject: 'ep_00' (81e86890): kobject_uevent_env: filter function caused the
event to drop!
kobject: 'ep_00' (81e86890): kobject_cleanup
kobject: 'ep_00' (81e86890): calling ktype release
kobject: 'ep_00': free name
kobject: '2-1.1.6' (81e680f0): kobject_uevent_env
kobject: '2-1.1.6' (81e680f0): fill_kobj_path: path =
'/devices/ssb0:1/usb2/2-1/2-1.1/2-1.1.6'
usb 2-1.1.6: uevent
kobject: '2-1.1.6' (81e680f0): kobject_cleanup
kobject: '2-1.1.6' (81e680f0): calling ktype release
kobject: '2-1.1.6': free name
In case of an open()ed driver, it would have gotten stuck directly after the
usb 2-1.1.6: usb_disable_device nuking all URBs
line, with any subsequent device plug remaining unsuccessful, no matter which device class.
(NOTE that an existing usb-storage device remains functional all the time!)
Any idea what to do next?
I could instrument the QH_STATE_LINKED / QH_STATE_UNLINK / QH_STATE_UNLINK_WAIT
thing, but on that router every change is quite a bit more painful than on x86...
Thanks,
Andreas Mohr
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
