Re: commit 554f76962d3a6eb5110415f1591aca83f96a84ae hangs USB for vmware 7.0.1

Dmitry Torokhov
2010-03-06T09:33:16Z

On Fri, Mar 05, 2010 at 10:46:26PM -0800, Petr Vandrovec wrote:
> Jeff Chua wrote:
> >
> >
> >On Sat, Mar 6, 2010 at 11:45 AM, Petr Vandrovec <petr@vmware.com
> ><mailto:petr@vmware.com>> wrote:
> >
> > does your box hang, or is it just vmware process that is hung?
> >
> >
> >Just the "vmware" process that hangs only. It just got stuck, and
> >even kill -9 doesn't free it.
> >
> > I've noticed that my box here at work has this change too, and I do
> > not see any hang - neither in kernel, or in GUI startup, nor in test
> > sample:
> >
> > open("/proc/bus/usb/devices", O_RDWR) = 3
> > poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
> > poll([{fd=3, events=POLLIN}], 1, 5000) = 0 (Timeout)
> > exit_group(0) = ?
> > petr-dev3:/tmp# uname -a
> > Linux petr-dev3 2.6.33-64-05079-g6517b45-dirty #51 SMP PREEMPT Thu
> > Mar 4 20:29:55 PST 2010 x86_64 GNU/Linux
> >
> >
> >Here's mine ...
> >open("/proc/bus/usb/devices", O_RDONLY) = 65
> >fcntl(65, F_GETFL) = 0x8000 (flags
> >O_RDONLY|O_LARGEFILE)
> >fstat(65, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
> >mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS,
> >-1, 0) = 0x7f85396c8000
> >lseek(65, 0, SEEK_CUR) = 0
> >read(65,
> >
> >
> >Again in my previous email, on my box, "cat
> >/proc/bus/usb/devices" hangs as well. You sure you've commit
> >554f76962d3a6eb5110415f1591aca83f96a84ae
> > on yours?
>
> Well, I hope. Disassembly of usbcore says that I have
> mutex_lock(&usbfs_mutex) in usbfs_conn_disc_event, so that checkin
> should be in my tree:
>
> 000000000001cc10 <usbfs_conn_disc_event>:
> 1cc10: 55 push %rbp
> 1cc11: 48 89 e5 mov %rsp,%rbp
> 1cc14: e8 00 00 00 00 callq 1cc19
> <usbfs_conn_disc_event+0x9>
> 1cc15: R_X86_64_PC32 mcount+0xfffffffffffffffc
> 1cc19: 31 f6 xor %esi,%esi
> 1cc1b: 48 c7 c7 00 00 00 00 mov $0x0,%rdi
> 1cc1e: R_X86_64_32S usbfs_mutex
> 1cc22: e8 00 00 00 00 callq 1cc27
> <usbfs_conn_disc_event+0x17>
> 1cc23: R_X86_64_PC32
> mutex_lock_nested+0xfffffffffffffffc
> 1cc27: 48 c7 c7 00 00 00 00 mov $0x0,%rdi
> 1cc2a: R_X86_64_32S usbfs_mutex
> 1cc2e: ff 05 00 00 00 00 incl 0x0(%rip) #
> 1cc34 <usbfs_conn_disc_event+0x24>
> 1cc30: R_X86_64_PC32 .bss+0x9a4
> 1cc34: e8 00 00 00 00 callq 1cc39
> <usbfs_conn_disc_event+0x29>
> 1cc35: R_X86_64_PC32
> mutex_unlock+0xfffffffffffffffc
> 1cc39: 31 c9 xor %ecx,%ecx
> 1cc3b: ba 01 00 00 00 mov $0x1,%edx
> 1cc40: be 03 00 00 00 mov $0x3,%esi
> 1cc45: 48 c7 c7 00 00 00 00 mov $0x0,%rdi
> 1cc48: R_X86_64_32S .data+0x1d00
> 1cc4c: e8 00 00 00 00 callq 1cc51
> <usbfs_conn_disc_event+0x41>
> 1cc4d: R_X86_64_PC32
> __wake_up+0xfffffffffffffffc
> 1cc51: c9 leaveq
> 1cc52: c3 retq
>
>
> One thing is that I brought my only USB device home, so currently I
> have none attached to the box:
>
> petr-dev3:/usr/src/git/linux-2.6# cat /proc/bus/usb/devices
>
> T: Bus=02 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 3
> B: Alloc= 0/900 us ( 0%), #Int= 0, #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-64-05079-g6517b45-dirty ohci_hcd
> S: Product=OHCI Host Controller
> S: SerialNumber=0000:03:00.1
> 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=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#= 1 Spd=12 MxCh= 3
> B: Alloc= 0/900 us ( 0%), #Int= 0, #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-64-05079-g6517b45-dirty ohci_hcd
> S: Product=OHCI Host Controller
> S: SerialNumber=0000:03:00.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
> petr-dev3:/usr/src/git/linux-2.6#
>
> I'll try upgrading my box at home. Maybe that one will hang.

I did not have issues with bringing VMware GUI with
64096c17417380d8a472d096645f4cbc9406c987 as tip of Linus's tree (which
is a believe the latest published), but got the following traces when
yanked USB keyboard out:

[ 1784.954389] usb 5-1: USB disconnect, address 2
[ 1784.954394] usb 5-1.3: USB disconnect, address 3
[ 1920.558046] INFO: task khubd:27 blocked for more than 120 seconds.
[ 1920.558051] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1920.558054] khubd D 0000000000000202 0 27 2 0x00000000
[ 1920.558060] ffff88011ba29960 0000000000000046 ffff88000260eec0 ffff88011ba20000
[ 1920.558067] ffff88011ba28000 ffff88011ba29fd8 ffff88011ba29fd8 ffff88011ba20000
[ 1920.558073] ffff88011ba29fd8 0000000000013d80 0000000000013d80 0000000000013d80
[ 1920.558079] Call Trace:
[ 1920.558088] [<ffffffff81478591>] __mutex_lock_common+0x1a1/0x4a0
[ 1920.558094] [<ffffffff8136f922>] ? usbfs_conn_disc_event+0x12/0x40
[ 1920.558099] [<ffffffff8107eb7d>] ? trace_hardirqs_on+0xd/0x10
[ 1920.558103] [<ffffffff8136f922>] ? usbfs_conn_disc_event+0x12/0x40
[ 1920.558107] [<ffffffff8147896e>] mutex_lock_nested+0x3e/0x50
[ 1920.558111] [<ffffffff8136f922>] usbfs_conn_disc_event+0x12/0x40
[ 1920.558115] [<ffffffff81371184>] usbfs_notify+0xa4/0x240
[ 1920.558119] [<ffffffff8147e007>] notifier_call_chain+0x47/0x90
[ 1920.558124] [<ffffffff8106f495>] __blocking_notifier_call_chain+0x55/0x80
[ 1920.558128] [<ffffffff8106f4d1>] blocking_notifier_call_chain+0x11/0x20
[ 1920.558132] [<ffffffff8136e7be>] usb_notify_remove_device+0x2e/0x50
[ 1920.558135] [<ffffffff8136e8a1>] generic_disconnect+0x11/0x30
[ 1920.558140] [<ffffffff81365db9>] usb_unbind_device+0x29/0x50
[ 1920.558145] [<ffffffff81303830>] __device_release_driver+0x70/0xe0
[ 1920.558149] [<ffffffff81303998>] device_release_driver+0x28/0x40
[ 1920.558153] [<ffffffff813029fc>] bus_remove_device+0xac/0xe0
[ 1920.558157] [<ffffffff81300d67>] device_del+0x127/0x1a0
[ 1920.558161] [<ffffffff8135bf2c>] usb_disconnect+0xec/0x160
[ 1920.558165] [<ffffffff8135bef7>] usb_disconnect+0xb7/0x160
[ 1920.558169] [<ffffffff8135c6ee>] hub_port_connect_change+0x8e/0x9f0
[ 1920.558172] [<ffffffff814783e9>] ? mutex_unlock+0x9/0x10
[ 1920.558176] [<ffffffff8135e263>] hub_events+0x3c3/0x580
[ 1920.558180] [<ffffffff8147a3cd>] ? _raw_spin_unlock_irqrestore+0x5d/0x70
[ 1920.558184] [<ffffffff8135e475>] hub_thread+0x55/0x190
[ 1920.558189] [<ffffffff810695a0>] ? autoremove_wake_function+0x0/0x40
[ 1920.558193] [<ffffffff8135e420>] ? hub_thread+0x0/0x190
[ 1920.558197] [<ffffffff8106908e>] kthread+0x8e/0xa0
[ 1920.558202] [<ffffffff81003dd4>] kernel_thread_helper+0x4/0x10
[ 1920.558206] [<ffffffff8147ab40>] ? restore_args+0x0/0x30
[ 1920.558210] [<ffffffff81069000>] ? kthread+0x0/0xa0
[ 1920.558213] [<ffffffff81003dd0>] ? kernel_thread_helper+0x0/0x10
[ 1920.558216] INFO: lockdep is turned off.
[ 1920.558254] INFO: task vmware-usbarbit:8039 blocked for more than 120 seconds.
[ 1920.558256] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1920.558259] vmware-usbarb D 0000000000000202 0 8039 1 0x00000080
[ 1920.558264] ffff8800cf7099a8 0000000000000046 ffff8800cf709928 ffff8800c5f22010
[ 1920.558270] ffff8800cf708000 ffff8800cf709fd8 ffff8800cf709fd8 ffff8800c5f22010
[ 1920.558276] ffff8800cf709fd8 0000000000013d80 0000000000013d80 0000000000013d80
[ 1920.558281] Call Trace:
[ 1920.558286] [<ffffffff81478591>] __mutex_lock_common+0x1a1/0x4a0
[ 1920.558290] [<ffffffff8136f97f>] ? usb_device_poll+0x2f/0x170
[ 1920.558293] [<ffffffff8136f97f>] ? usb_device_poll+0x2f/0x170
[ 1920.558297] [<ffffffff8106cfd0>] ? hrtimer_wakeup+0x0/0x30
[ 1920.558301] [<ffffffff8147896e>] mutex_lock_nested+0x3e/0x50
[ 1920.558305] [<ffffffff8136f97f>] usb_device_poll+0x2f/0x170
[ 1920.558309] [<ffffffff8112e104>] ? poll_schedule_timeout+0x44/0x60
[ 1920.558313] [<ffffffff8112e22b>] do_poll+0x10b/0x2b0
[ 1920.558317] [<ffffffff8112ef0e>] do_sys_poll+0x16e/0x230
[ 1920.558320] [<ffffffff8112e490>] ? __pollwait+0x0/0xf0
[ 1920.558324] [<ffffffff8112e580>] ? pollwake+0x0/0x60
[ 1920.558327] [<ffffffff8112e580>] ? pollwake+0x0/0x60
[ 1920.558331] [<ffffffff8112e580>] ? pollwake+0x0/0x60
[ 1920.558335] [<ffffffff81127bdc>] ? path_put+0x2c/0x40
[ 1920.558339] [<ffffffff81129854>] ? link_path_walk+0x424/0xc60
[ 1920.558343] [<ffffffff811272b5>] ? path_init+0xb5/0x1d0
[ 1920.558347] [<ffffffff81138bb4>] ? mntput_no_expire+0x24/0xf0
[ 1920.558351] [<ffffffff81114315>] ? kmem_cache_free+0xd5/0x140
[ 1920.558356] [<ffffffff8107ea09>] ? trace_hardirqs_on_caller+0x29/0x190
[ 1920.558360] [<ffffffff8107eb7d>] ? trace_hardirqs_on+0xd/0x10
[ 1920.558363] [<ffffffff81127400>] ? putname+0x30/0x50
[ 1920.558367] [<ffffffff81127400>] ? putname+0x30/0x50
[ 1920.558371] [<ffffffff8112afad>] ? user_path_at+0x5d/0xa0
[ 1920.558375] [<ffffffff81121817>] ? vfs_fstatat+0x37/0x70
[ 1920.558380] [<ffffffff81074029>] ? ktime_get_ts+0xa9/0xe0
[ 1920.558383] [<ffffffff8112e090>] ? poll_select_set_timeout+0x70/0xa0
[ 1920.558387] [<ffffffff8112f1b7>] sys_poll+0x77/0x110
[ 1920.558391] [<ffffffff81002fab>] system_call_fastpath+0x16/0x1b
[ 1920.558394] INFO: lockdep is turned off.

--
Dmitry