From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754195AbcBEPOO (ORCPT ); Fri, 5 Feb 2016 10:14:14 -0500 Received: from mail-wm0-f50.google.com ([74.125.82.50]:35617 "EHLO mail-wm0-f50.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753951AbcBEPOL (ORCPT ); Fri, 5 Feb 2016 10:14:11 -0500 Date: Fri, 5 Feb 2016 15:14:07 +0000 From: Chris Bainbridge To: Alan Stern Cc: mathias.nyman@linux.intel.com, johan@kernel.org, linux-usb@vger.kernel.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH] usb: host: xhci: Replace bus lock with host controller lock Message-ID: <20160205151407.GA5257@localhost> References: <20160204220621.GA5612@localhost> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.23 (2014-03-12) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Running task list at fail point: [ 8.978405] kworker/3:0 R running task 11760 24 2 0x00000000 [ 8.979624] Workqueue: usb_hub_wq hub_event [ 8.980831] ffff880260613af8 ffff880260613ac0 00000000811247ed ffff8802604597c0 [ 8.982061] ffff880260608000 ffff880260614000 0000000000000100 ffff880260613b70 [ 8.983280] ffff880260613c14 0000000000001388 ffff880260613b10 ffffffff81b9bab7 [ 8.984500] Call Trace: [ 8.985698] [] schedule+0x37/0x90 [ 8.986918] [] usb_kill_urb+0x8d/0xd0 [ 8.988130] [] ? wake_up_atomic_t+0x30/0x30 [ 8.989343] [] usb_start_wait_urb+0xbe/0x150 [ 8.990561] [] usb_control_msg+0xbc/0xf0 [ 8.991766] [] hub_port_init+0x51e/0xb70 [ 8.992964] [] hub_event+0x817/0x1570 [ 8.994156] [] process_one_work+0x1ff/0x620 [ 8.995342] [] ? process_one_work+0x15f/0x620 [ 8.996528] [] worker_thread+0x64/0x4b0 [ 8.997707] [] ? rescuer_thread+0x390/0x390 [ 8.998883] [] kthread+0x105/0x120 [ 9.000056] [] ? kthread_create_on_node+0x200/0x200 [ 9.001241] [] ret_from_fork+0x3f/0x70 [ 9.002420] [] ? kthread_create_on_node+0x200/0x200 [ 9.094152] kworker/3:1 R running task 11496 238 2 0x00000000 [ 9.095361] Workqueue: pm pm_runtime_work [ 9.096545] ffff88025fc13ae0 ffff88025fc13aa8 00000003811247ed ffff880260bc0000 [ 9.097767] ffff8802603aaf80 ffff88025fc14000 ffff88025cc7a520 ffff88007c4b7978 [ 9.098986] ffff88025cc7a520 ffff88007c4b7978 ffff88025fc13af8 ffffffff81b9bab7 [ 9.100213] Call Trace: [ 9.101415] [] schedule+0x37/0x90 [ 9.102626] [] usb_kill_urb+0x8d/0xd0 [ 9.103835] [] ? wake_up_atomic_t+0x30/0x30 [ 9.105035] [] hub_quiesce+0x6b/0xa0 [ 9.106226] [] hub_suspend+0x12a/0x250 [ 9.107417] [] usb_suspend_both+0x95/0x1d0 [ 9.108600] [] usb_runtime_suspend+0x2e/0x70 [ 9.109783] [] ? usb_probe_interface+0x310/0x310 [ 9.110958] [] __rpm_callback+0x2d/0x70 [ 9.112130] [] ? usb_probe_interface+0x310/0x310 [ 9.113305] [] rpm_callback+0x1d/0x90 [ 9.114482] [] rpm_suspend+0x14b/0x750 [ 9.115664] [] __pm_runtime_suspend+0x57/0x90 [ 9.116852] [] ? usb_runtime_resume+0x20/0x20 [ 9.118034] [] usb_runtime_idle+0x25/0x30 [ 9.119210] [] __rpm_callback+0x2d/0x70 [ 9.120382] [] rpm_idle+0x221/0x410 [ 9.121541] [] pm_runtime_work+0xa9/0xc0 [ 9.122693] [] process_one_work+0x1ff/0x620 [ 9.123850] [] ? process_one_work+0x15f/0x620 [ 9.124993] [] worker_thread+0x64/0x4b0 [ 9.126134] [] ? rescuer_thread+0x390/0x390 [ 9.127272] [] ? rescuer_thread+0x390/0x390 [ 9.128403] [] kthread+0x105/0x120 [ 9.129524] [] ? kthread_create_on_node+0x200/0x200 [ 9.130653] [] ret_from_fork+0x3f/0x70 [ 9.131781] [] ? kthread_create_on_node+0x200/0x200 [ 9.864737] kworker/3:2 R running task 11888 1348 2 0x00000008 [ 9.865947] Workqueue: usb_hub_wq hub_event [ 9.867152] ffff88025dbcdf00 ffff88025dbd3b88 ffffffff81109a8c ffffffff811099a9 [ 9.868386] ffff88025dbcdf00 0000000000000000 ffff88025dbce270 ffff88025dbd3bb8 [ 9.869610] ffffffff81109c04 ffff88025dac8000 ffff88025dac8368 ffff88025c8a4000 [ 9.870837] Call Trace: [ 9.872044] [] sched_show_task+0x15c/0x260 [ 9.873248] [] ? sched_show_task+0x79/0x260 [ 9.874456] [] show_state_filter+0x74/0xc0 [ 9.875664] [] xhci_setup_device+0x53d/0xa40 [ 9.876871] [] xhci_address_device+0xe/0x10 [ 9.878068] [] hub_port_init+0x1bf/0xb70 [ 9.879262] [] ? trace_hardirqs_on+0xd/0x10 [ 9.880465] [] hub_event+0x817/0x1570 [ 9.881668] [] process_one_work+0x1ff/0x620 [ 9.882869] [] ? process_one_work+0x15f/0x620 [ 9.884074] [] worker_thread+0x64/0x4b0 [ 9.885268] [] ? rescuer_thread+0x390/0x390 [ 9.886457] [] kthread+0x105/0x120 [ 9.887634] [] ? kthread_create_on_node+0x200/0x200 [ 9.888817] [] ret_from_fork+0x3f/0x70 [ 9.889995] [] ? kthread_create_on_node+0x200/0x200 [ 9.891174] kworker/3:3 R running task 10808 1350 2 0x00000000 [ 9.892367] Workqueue: events_freezable usb_stor_scan_dwork [ 9.893560] ffff88025dbdbb78 ffff88026a0ccd80 000000006a0ccd80 ffff8802604597c0 [ 9.894773] ffff88025dbcc740 ffff88025dbdc000 ffff88025dbdbbb0 ffff88026a0ccd80 [ 9.896004] ffff88026a0ccd80 0000000000000003 ffff88025dbdbb90 ffffffff81b9bab7 [ 9.897233] Call Trace: [ 9.898444] [] schedule+0x37/0x90 [ 9.899670] [] schedule_timeout+0x17c/0x2f0 [ 9.900893] [] ? init_timer_on_stack_key+0x40/0x40 [ 9.902099] [] wait_for_completion_interruptible_timeout+0xcd/0x160 [ 9.903324] [] ? wake_up_q+0x70/0x70 [ 9.904536] [] usb_stor_msg_common+0xd8/0x130 [ 9.905751] [] usb_stor_control_msg+0x96/0xb0 [ 9.906961] [] usb_stor_Bulk_max_lun+0x51/0xa0 [ 9.908163] [] usb_stor_scan_dwork+0x7f/0xe0 [ 9.909361] [] process_one_work+0x1ff/0x620 [ 9.910563] [] ? process_one_work+0x15f/0x620 [ 9.911762] [] worker_thread+0x64/0x4b0 [ 9.912976] [] ? rescuer_thread+0x390/0x390 [ 9.914190] [] kthread+0x105/0x120 [ 9.915396] [] ? kthread_create_on_node+0x200/0x200 [ 9.916607] [] ret_from_fork+0x3f/0x70 [ 9.917817] [] ? kthread_create_on_node+0x200/0x200 [ 11.003856] 7 locks held by kworker/3:2/1348: [ 11.005032] #0: ("usb_hub_wq"){.+.+.+}, at: [] process_one_work+0x15f/0x620 [ 11.006250] #1: ((&hub->events)){+.+.+.}, at: [] process_one_work+0x15f/0x620 [ 11.007479] #2: (&dev->mutex){......}, at: [] hub_event+0x64/0x1570 [ 11.008723] #3: (&port_dev->status_lock){+.+.+.}, at: [] hub_event+0x805/0x1570 [ 11.009975] #4: (&bus->usb_address0_mutex){+.+.+.}, at: [] hub_port_init+0x5d/0xb70 [ 11.011233] #5: (&xhci->mutex){+.+.+.}, at: [] xhci_setup_device+0x5f/0xa40 [ 11.012496] #6: (tasklist_lock){.+.+..}, at: [] debug_show_all_locks+0x3f/0x1b0 kworker/3:0 and kworker/3:2 are both in hub_port_init. (I don't think the other running threads are relevant but include them for completeness). Some of the functions appear to be inlined, the exact call chain is: hub_port_init usb_get_device_descriptor usb_get_descriptor usb_control_msg usb_internal_control_msg usb_start_wait_urb usb_submit_urb / wait_for_completion_timeout / usb_kill_urb hub_port_init hub_set_address xhci_address_device xhci_setup_device So xhci_setup_device is entered while there is an outstanding URB on the other bus. Unless anyone can think of a better way to fix this I'll make the requested changes and resend my patch.