Hi.
(please keep me cc'ed in replies, I'm not subscribed)
I'm trying OpenWRT on a DSL modem[1] which has an out-of-tree HCI
driver. I'm getting one particular process to hang in D 100% of time
when talking to a 3G USB modem. I'm on current default OpenWRT kernel,
3.14.18 .
Here is the hung process:
root@OpenWrt:/# echo w > /proc/sysrq-trigger
[ 98.160000] SysRq : Show Blocked State
[ 98.160000] task PC stack pid father
[ 98.160000] gcom D 8030861c 0 2228 2188 0x08100020
[ 98.160000] Stack : 81bde880 00000001 00000000 80307b18 81bde880 80435698
81bde88c 80414c60
81d213c0 00010000 80410000 81bb7180 00000001 8030861c 81bcd480
81452e00
81452e00 803a0000 00000000 814bf070 8007fc04 80435698 80435698
81452e00
803a0000 00000004 81d21380 00000010 81be2800 81828900 00000000
81d08c28
00000000 00000000 81be2804 81be2884 81452e00 803a0000 00000000
81d08c28
...
[ 98.160000] Call Trace:
[ 98.160000] [<8000d954>] __schedule+0x4cc/0x578
[ 98.160000] [<8030861c>] usb_kill_urb+0xe0/0x164
[ 98.160000] [<81828900>] usb_wwan_close+0x100/0x2e4 [usb_wwan]
[ 98.160000] [<802b6e8c>] tty_port_shutdown+0xc0/0xdc
[ 98.160000] [<802b64ac>] tty_port_close+0x30/0xa4
[ 98.160000] [<802b7918>] tty_release+0x168/0x524
[ 98.160000] [<80041038>] __fput+0xf8/0x274
[ 98.160000] [<80289560>] task_work_run+0xf0/0x128
[ 98.160000] [<800ef3d0>] do_exit+0x3fc/0x858
[ 98.160000] [<800f154c>] do_group_exit+0x78/0xb4
[ 98.160000] [<800198a8>] SyS_faccessat+0x0/0x250
As can be seen, it is while cleaning up process resources on exit (at
kernel level) that the hang happens. If I unplug the modem, process
exits and I get the following output:
[ 2862.228000] option1 ttyUSB0: usb_wwan_indat_callback: resubmit read urb
failed. (-19)
[ 2862.236000] option1 ttyUSB0: usb_wwan_indat_callback: resubmit read urb
failed. (-19)
[ 2862.244000] option1 ttyUSB0: usb_wwan_indat_callback: resubmit read urb
failed. (-19)
[ 2862.252000] option1 ttyUSB0: usb_wwan_indat_callback: resubmit read urb
failed. (-19)
[ 2862.260000] option1 ttyUSB0: option_instat_callback: error -150
Here is the HCD driver source code:
http://git.openwrt.org/?p=openwrt.git;a=tree;f=package/kernel/lantiq/ltq-hcd/src;h=926980738d4eb39d78fdf116fe4f2f787040fa1d;hb=fee2d7ec702586850e0eafbd82f43c851d1c45b3
(to the revision I'm at locally, which is 2 days old as I'm writing
this, and no change since touch this path)
Poking around with printk debugging (*cough*), I found that the URB
__schedule is waiting upon has a use_count of 1. Adding printks after
the 2 atomic_dec and the only atomic_inc on it, I see this URB's history
as:
[ 99.284000] 81ae2900->use_count 1 drivers/usb/core/hcd.c:1553
[ 99.916000] 81ae2900->use_count 2 drivers/usb/core/hcd.c:1553
[ 99.916000] 81ae2900->use_count 1 drivers/usb/core/hcd.c:1691
[ 100.332000] 81ae2900->use_count 2 drivers/usb/core/hcd.c:1553
[ 100.332000] 81ae2900->use_count 1 drivers/usb/core/hcd.c:1691
[ 101.436000] IFXUSB: 81ae2900 urbd->phase 0
[ 101.440000] 81ae2900->use_count 2 drivers/usb/core/hcd.c:1553
[ 101.440000] 81ae2900->use_count 1 drivers/usb/core/hcd.c:1691
[ 101.512000] wait_event 81ae2900
1553 is right after usb_hcd_submit_urb's atomic_inc
1691 is right after __usb_hcd_giveback_urb's atomic_dec
usb_hcd_submit_urb's atomic_dec is not hit.
The IFXUSB line is the HCD driver's ifxhcd_urb_dequeue telling it is
dequeueing the URB, currently in given phase (here 0, so URBD_IDLE).
wait_event line is usb_kill_urb calling wait_event or given URB.
This URB does not appear at any time before 99.284, when I started gcom.
Is it legal for use_count to exceed 1 ?
What would it mean ?
Eyeballing usb_wwan I could not see any obvious issue. I saw a large
patch set for this driver since 3.14.18 and copied it over (as of
linux-stable b0a9aa6da8088b722326a858ab572a13b5b6f9cb), with the only
visible improvement of not getting errors when unplugging the modem on
stuck process.
Is my debugging approach even reliable ? I'm reading use_count right
after an atomic_inc, which looks like a bad idea...
Any idea on what I should search for/look at next ?
I tried calling dump_stack after 1553, but kernel fails booting (maybe
URBs timing out just because of printks going through 115200 bauds
serial link ?). After ~260 seconds the router reboots (no error
message, maybe out of memory because of message buffer growing faster
than serial empties it ?).
If I only call it when count reaches 2, kernel boots and gives
stack traces I do not understand, such as (extracted from above run):
[ 99.916000] CPU: 0 PID: 1413 Comm: logd Not tainted 3.14.18 #38
[ 99.916000] Stack : 00000000 00000000 00000000 00000000 8095cdbe 00000033
838bd7e8 803f0000
803c1644 8042136f 00000585 80953b00 838bd7e8 803f0000 81d395a8
00000020
0000000a 802f9998 00000000 80211878 00000000 00000000 803c49a4
838b5ccc
00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000
838b5c58
...
[ 99.916000] Call Trace:
[ 99.916000] [<80260c70>] show_stack+0x48/0x70
[ 99.916000] [<803071d0>] usb_hcd_submit_urb+0xdc/0xa24
[ 99.916000] [<8194aac0>] usb_wwan_close+0x298/0x2e8 [usb_wwan]
[ 99.916000] [<80066610>] __wake_up+0x28/0x48
[ 99.916000] [<81d3467c>] ifxhcd_hc_cleanup+0xae8/0xba4 [ltq_hcd_vr9]
[ 100.332000] CPU: 0 PID: 973 Comm: kworker/0:2 Not tainted 3.14.18 #38
[ 100.332000] Workqueue: events usb_serial_suspend [usbserial]
[ 100.332000] Stack : 818c8680 803c1644 80414c60 81ae2908 803f0000 803f0000
81d395a8 00000020
0000000a 802f9998 000003cd 80211ffc 00000000 00000000 803e2e00
818bdb34
818bdb34 802f9998 00000000 80211aa4 00000000 000005f2 000005f2
8094d7e0
00000000 00000000 00000000 00000000 00000000 00000000 6576656e
74730000
00000000 00000000 00000000 00000000 8381bb80 81085500 818507d4
818bdae0
...
[ 100.332000] Call Trace:
[ 100.332000] [<80260c70>] show_stack+0x48/0x70
[ 100.332000] [<803071d0>] usb_hcd_submit_urb+0xdc/0xa24
[ 100.332000] [<8194aac0>] usb_wwan_close+0x298/0x2e8 [usb_wwan]
[ 101.440000] CPU: 0 PID: 2254 Comm: gcom Not tainted 3.14.18 #38
[ 101.440000] Stack : 00000000 00000000 00000000 00000000 8095cdbe 00000033
81507748 803f0000
803c1644 8042136f 000008ce 80953b00 81507748 803f0000 80410000
00000020
7fc48cf0 802f9998 00000000 80211878 00000000 00000000 803c49a4
814c3b14
00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000
00000000 00000000 00000000 00000000 00000000 00000000 00000000
814c3aa0
...
[ 101.440000] Call Trace:
[ 101.440000] [<80260c70>] show_stack+0x48/0x70
[ 101.440000] [<803071d0>] usb_hcd_submit_urb+0xdc/0xa24
[ 101.440000] [<8194aac0>] usb_wwan_close+0x298/0x2e8 [usb_wwan]
[1] http://wiki.openwrt.org/toh/tp-link/td-w8970
Regards,
--
Vincent Pelletier
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
