From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757620Ab3ENSbS (ORCPT ); Tue, 14 May 2013 14:31:18 -0400 Received: from mail-ea0-f172.google.com ([209.85.215.172]:40615 "EHLO mail-ea0-f172.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754656Ab3ENSbQ (ORCPT ); Tue, 14 May 2013 14:31:16 -0400 Date: Tue, 14 May 2013 20:31:08 +0200 From: Ingo Molnar To: Jiri Kosina Cc: Linus Torvalds , linux-kernel@vger.kernel.org Subject: Re: [GIT] HID Message-ID: <20130514183108.GA4904@gmail.com> References: <20130510114759.GA19857@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org * Jiri Kosina wrote: > > FYI, there's a new HID related lockdep and RCU splat upstream, probably > > relatd to the debugfs locking fixes: > > > > [ 79.088631] ====================================================== > > [ 79.088631] [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] > > [ 79.088631] 3.9.0-13694-g7cf229a-dirty #224212 Tainted: G W > > [ 79.088631] ------------------------------------------------------ > > [ 79.088631] swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: > > [ 79.088631] (&hdev->debug_list_lock){+.+...}, at: [] hid_debug_event+0x2e/0xd0 > > [ 79.088631] > > > > See the full bootlog below. It's from an allyesconfig x86-64 bootup log. > > Hi Ingo, > > thanks for the report. I have a fix for this in my tree already and am > going to send pull request to Linus shortly. FYI, the fixes in your tree apparently did not fix the bug - I'm still getting the same lockdep splat below. Thanks, Ingo initcall sensor_hub_driver_init+0x0/0x16 returned 0 after 7779 usecs calling hid_init+0x0/0x45 @ 1 bus: 'usb': add driver usbhid bus: 'usb': driver_probe_device: matched device 2-2:1.0 with driver usbhid bus: 'usb': really_probe: probing driver usbhid with device 2-2:1.0 usbhid 2-2:1.0: usb_probe_interface usbhid 2-2:1.0: usb_probe_interface - got id device: '0003:1241:1503.0001': device_add bus: 'hid': add device 0003:1241:1503.0001 PM: Adding info for hid:0003:1241:1503.0001 bus: 'hid': driver_probe_device: matched device 0003:1241:1503.0001 with driver hid-generic bus: 'hid': really_probe: probing driver hid-generic with device 0003:1241:1503.0001 device: 'input2': device_add PM: Adding info for No Bus:input2 input: USB Keyboard as /devices/pci0000:00/0000:00:02.0/usb2/2-2/2-2:1.0/input/input2 ====================================================== [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] 3.9.0+ #224324 Not tainted ------------------------------------------------------ swapper/0/1 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: (&hdev->debug_list_lock){+.+...}, at: [] hid_debug_event+0x1e/0xa8 and this task is already holding: (&(&usbhid->lock)->rlock){-.....}, at: [] usb_hidinput_input_event+0x7c/0xaf which would create a new lock dependency: (&(&usbhid->lock)->rlock){-.....} -> (&hdev->debug_list_lock){+.+...} but this new dependency connects a HARDIRQ-irq-safe lock: (&(&usbhid->lock)->rlock){-.....} ... which became HARDIRQ-irq-safe at: [] __lock_acquire+0x241/0xd54 [] lock_acquire+0x76/0x8a [] _raw_spin_lock+0x3d/0x4a [] hid_ctrl+0x28/0x12c [] usb_hcd_giveback_urb+0x40/0x84 [] finish_urb+0xbe/0xf4 [] takeback_td+0x39/0x99 [] dl_done_list+0x1b5/0x1e4 [] ohci_irq+0x16c/0x27a [] usb_hcd_irq+0x26/0x4f [] handle_irq_event_percpu+0x24/0x11f [] handle_irq_event+0x2c/0x43 [] handle_fasteoi_irq+0x6a/0x97 to a HARDIRQ-irq-unsafe lock: (&hdev->debug_list_lock){+.+...} ... which became HARDIRQ-irq-unsafe at: ... [] __lock_acquire+0x2a4/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usbhid_set_leds+0x77/0x8b [] usbhid_start+0x39e/0x3fd [] hid_device_probe+0xa0/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 other info that might help us debug this: Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&hdev->debug_list_lock); local_irq_disable(); lock(&(&usbhid->lock)->rlock); lock(&hdev->debug_list_lock); lock(&(&usbhid->lock)->rlock); *** DEADLOCK *** 7 locks held by swapper/0/1: #0: (&__lockdep_no_validate__){......}, at: [] device_lock+0xd/0xf #1: (&__lockdep_no_validate__){......}, at: [] device_lock+0xd/0xf #2: (&__lockdep_no_validate__){......}, at: [] device_lock+0xd/0xf #3: (input_mutex){+.+.+.}, at: [] input_register_device+0x2e3/0x38f #4: (&(&dev->event_lock)->rlock){......}, at: [] input_inject_event+0x35/0x75 #5: (rcu_read_lock){.+.+..}, at: [] rcu_lock_acquire.constprop.16+0x0/0x35 #6: (&(&usbhid->lock)->rlock){-.....}, at: [] usb_hidinput_input_event+0x7c/0xaf the dependencies between HARDIRQ-irq-safe lock and the holding lock: -> (&(&usbhid->lock)->rlock){-.....} ops: 4 { IN-HARDIRQ-W at: [] __lock_acquire+0x241/0xd54 [] lock_acquire+0x76/0x8a [] _raw_spin_lock+0x3d/0x4a [] hid_ctrl+0x28/0x12c [] usb_hcd_giveback_urb+0x40/0x84 [] finish_urb+0xbe/0xf4 [] takeback_td+0x39/0x99 [] dl_done_list+0x1b5/0x1e4 [] ohci_irq+0x16c/0x27a [] usb_hcd_irq+0x26/0x4f [] handle_irq_event_percpu+0x24/0x11f [] handle_irq_event+0x2c/0x43 [] handle_fasteoi_irq+0x6a/0x97 INITIAL USE at: [] __lock_acquire+0x304/0xd54 [] lock_acquire+0x76/0x8a [] _raw_spin_lock_irqsave+0x4b/0x5b [] usbhid_submit_report+0x23/0x45 [] usbhid_init_reports+0x2a/0xb8 [] usbhid_start+0x382/0x3fd [] hid_device_probe+0xa0/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 } ... key at: [] __key.27543+0x0/0x8 ... acquired at: [] check_irq_usage+0x40/0x86 [] __lock_acquire+0xa32/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usb_hidinput_input_event+0x8c/0xaf [] input_handle_event+0x376/0x444 [] input_inject_event+0x5e/0x75 [] kbd_update_leds_helper+0x4e/0x7b [] kbd_start+0x2d/0x36 [] input_register_handle+0x89/0x93 [] kbd_connect+0x31/0x60 [] input_attach_handler+0x168/0x19e [] input_register_device+0x31d/0x38f [] hidinput_connect+0x3a2/0x3e0 [] hid_connect+0x64/0x27a [] hid_device_probe+0xb2/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock: -> (&hdev->debug_list_lock){+.+...} ops: 2 { HARDIRQ-ON-W at: [] __lock_acquire+0x2a4/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usbhid_set_leds+0x77/0x8b [] usbhid_start+0x39e/0x3fd [] hid_device_probe+0xa0/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 SOFTIRQ-ON-W at: [] __lock_acquire+0x2c3/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usbhid_set_leds+0x77/0x8b [] usbhid_start+0x39e/0x3fd [] hid_device_probe+0xa0/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 INITIAL USE at: [] __lock_acquire+0x304/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usbhid_set_leds+0x77/0x8b [] usbhid_start+0x39e/0x3fd [] hid_device_probe+0xa0/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 } ... key at: [] __key.24951+0x0/0x8 ... acquired at: [] check_irq_usage+0x40/0x86 [] __lock_acquire+0xa32/0xd54 [] lock_acquire+0x76/0x8a [] __mutex_lock_common+0x4f/0x36f [] mutex_lock_nested+0x3e/0x44 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] usb_hidinput_input_event+0x8c/0xaf [] input_handle_event+0x376/0x444 [] input_inject_event+0x5e/0x75 [] kbd_update_leds_helper+0x4e/0x7b [] kbd_start+0x2d/0x36 [] input_register_handle+0x89/0x93 [] kbd_connect+0x31/0x60 [] input_attach_handler+0x168/0x19e [] input_register_device+0x31d/0x38f [] hidinput_connect+0x3a2/0x3e0 [] hid_connect+0x64/0x27a [] hid_device_probe+0xb2/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] usb_register_driver+0x6c/0x111 [] hid_init+0x26/0x45 [] do_one_initcall+0x4b/0x10e [] kernel_init_freeable+0x114/0x1b3 [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 stack backtrace: CPU: 0 PID: 1 Comm: swapper/0 Not tainted 3.9.0+ #224324 Hardware name: System manufacturer System Product Name/A8N-E, BIOS ASUS A8N-E ACPI BIOS Revision 1008 08/22/2005 c21546c7 c21546c7 f647b884 c1daff0d f647b918 c1067cf3 c2153749 c21546c7 00000001 00000000 00000000 00000000 00000000 00000000 00000001 f647b8c4 c27d5bf8 c27d5ae8 f647b8c4 f647b8e8 c21546b7 f6480000 c27d5ae8 00000029 Call Trace: [] dump_stack+0x16/0x18 [] check_usage+0x2df/0x2e9 [] ? __bfs+0x13/0x17e [] check_irq_usage+0x40/0x86 [] __lock_acquire+0xa32/0xd54 [] ? check_usage+0x33/0x2e9 [] ? find_usage_backwards+0x58/0x5f [] ? check_usage+0x33/0x2e9 [] lock_acquire+0x76/0x8a [] ? hid_debug_event+0x1e/0xa8 [] __mutex_lock_common+0x4f/0x36f [] ? hid_debug_event+0x1e/0xa8 [] ? vsnprintf+0x149/0x2a2 [] ? kmem_cache_alloc+0xbb/0xe9 [] mutex_lock_nested+0x3e/0x44 [] ? hid_debug_event+0x1e/0xa8 [] hid_debug_event+0x1e/0xa8 [] hid_dump_input+0x4d/0x78 [] hid_set_field+0x29/0xab [] ? _raw_spin_lock_irqsave+0x52/0x5b [] usb_hidinput_input_event+0x8c/0xaf [] ? hid_ctrl+0x12c/0x12c [] input_handle_event+0x376/0x444 [] ? hid_ctrl+0x12c/0x12c [] input_inject_event+0x5e/0x75 [] kbd_update_leds_helper+0x4e/0x7b [] kbd_start+0x2d/0x36 [] input_register_handle+0x89/0x93 [] kbd_connect+0x31/0x60 [] input_attach_handler+0x168/0x19e [] input_register_device+0x31d/0x38f [] hidinput_connect+0x3a2/0x3e0 [] hid_connect+0x64/0x27a [] ? trace_hardirqs_on+0xb/0xd [] ? _raw_spin_unlock_irq+0x22/0x30 [] ? device_wakeup_enable+0x62/0x77 [] ? device_set_wakeup_enable+0x19/0x2a [] ? usbhid_start+0x3ab/0x3fd [] ? hid_open_report+0x178/0x1fd [] ? hid_match_id+0x14/0x29 [] hid_device_probe+0xb2/0x109 [] driver_probe_device+0xe2/0x24e [] __device_attach+0x1c/0x2e [] bus_for_each_drv+0x3a/0x6b [] device_attach+0x58/0x69 [] ? __driver_attach+0x5f/0x5f [] bus_probe_device+0x22/0x77 [] device_add+0x3bc/0x542 [] hid_add_device+0x1f0/0x224 [] ? kmem_cache_open+0xf6/0x254 [] usbhid_probe+0x37f/0x3c0 [] usb_probe_interface+0x129/0x17a [] driver_probe_device+0xe2/0x24e [] __driver_attach+0x43/0x5f [] bus_for_each_dev+0x3e/0x68 [] driver_attach+0x17/0x19 [] ? driver_probe_device+0x24e/0x24e [] bus_add_driver+0xd6/0x1e5 [] driver_register+0x7c/0xf7 [] ? __raw_spin_lock_init+0x2d/0x4d [] usb_register_driver+0x6c/0x111 [] ? timekeeping_get_ns.constprop.9+0xf/0x54 [] hid_init+0x26/0x45 [] ? sensor_hub_driver_init+0x16/0x16 [] do_one_initcall+0x4b/0x10e [] ? sensor_hub_driver_init+0x16/0x16 [] kernel_init_freeable+0x114/0x1b3 [] ? loglevel+0x2b/0x2b [] kernel_init+0xb/0xbe [] ret_from_kernel_thread+0x1b/0x28 [] ? rest_init+0xc1/0xc1 device: 'event2': device_add PM: Adding info for No Bus:event2 evbug: Connected device: input2 ( USB Keyboard at usb-0000:00:02.0-2/input0) device: 'hidraw0': device_add PM: Adding info for No Bus:hidraw0 hid-generic 0003:1241:1503.0001: input,hidraw0: USB HID v1.10 Keyboard [ USB Keyboard] on usb-0000:00:02.0-2/input0 driver: '0003:1241:1503.0001': driver_bound: bound to device 'hid-generic' bus: 'hid': really_probe: bound device 0003:1241:1503.0001 to driver hid-generic driver: '2-2:1.0': driver_bound: bound to device 'usbhid' bus: 'usb': really_probe: bound device 2-2:1.0 to driver usbhid bus: 'usb': driver_probe_device: matched device 2-2:1.1 with driver usbhid bus: 'usb': really_probe: probing driver usbhid with device 2-2:1.1 usbhid 2-2:1.1: usb_probe_interface usbhid 2-2:1.1: usb_probe_interface - got id device: '0003:1241:1503.0002': device_add bus: 'hid': add device 0003:1241:1503.0002 PM: Adding info for hid:0003:1241:1503.0002 bus: 'hid': driver_probe_device: matched device 0003:1241:1503.0002 with driver hid-generic bus: 'hid': really_probe: probing driver hid-generic with device 0003:1241:1503.0002 device: 'input3': device_add PM: Adding info for No Bus:input3 input: USB Keyboard as /devices/pci0000:00/0000:00:02.0/usb2/2-2/2-2:1.1/input/input3 device: 'event3': device_add PM: Adding info for No Bus:event3 evbug: Connected device: input3 ( USB Keyboard at usb-0000:00:02.0-2/input1) device: 'hidraw1': device_add PM: Adding info for No Bus:hidraw1 hid-generic 0003:1241:1503.0002: input,hidraw1: USB HID v1.10 Device [ USB Keyboard] on usb-0000:00:02.0-2/input1 driver: '0003:1241:1503.0002': driver_bound: bound to device 'hid-generic' bus: 'hid': really_probe: bound device 0003:1241:1503.0002 to driver hid-generic driver: '2-2:1.1': driver_bound: bound to device 'usbhid' bus: 'usb': really_probe: bound device 2-2:1.1 to driver usbhid usbcore: registered new interface driver usbhid usbhid: USB HID core driver