Re: USB-related lock inversion complaint

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



On Fri, 28 Apr 2017, Bart Van Assche wrote:

> Hello,
> 
> Every time I boot a particular development server the complaint shown
> below appears in the system log. I don't know when this behavior has
> been introduced. But I noticed that I can reproduce this with older
> kernel versions, e.g. 4.4.63. Does anyone know what is going on or how
> to fix this?
> 
> Thanks,
> 
> Bart.
> 
> usb 1-8: new low-speed USB device number 2 using xhci_hcd
> usb 3-1: new high-speed USB device number 2 using ehci-pci
> 
> =========================================================
> [ INFO: possible irq lock inversion dependency detected ]
> 4.11.0-rc8-dbg+ #1 Not tainted
> ---------------------------------------------------------
> swapper/7/0 just changed the state of lock:
> �(&(&ehci->lock)->rlock){-.-...}, at: [<ffffffffa0130a69>] ehci_hrtimer_func+0x29/0xc0 [ehci_hcd]
> but this lock took another, HARDIRQ-unsafe lock in the past:
> �(hcd_urb_list_lock){+.....}
> 
> 
> and interrupts could create inverse lock ordering between them.

I often find these lockdep splats difficult to understand.  In this 
case, why does lockdep think hcd_urb_list_lock is hardirq-unsafe?  It's 
supposed to be hardirq-safe.

Alan Stern

> other info that might help us debug this:
> �Possible interrupt unsafe locking scenario:
> 
> �������CPU0��������������������CPU1
> �������----��������������������----
> � lock(hcd_urb_list_lock);
> �������������������������������local_irq_disable();
> �������������������������������lock(&(&ehci->lock)->rlock);
> �������������������������������lock(hcd_urb_list_lock);
> � <Interrupt>
> ����lock(&(&ehci->lock)->rlock);
> �*** DEADLOCK ***
> 
> no locks held by swapper/7/0.
> the shortest dependencies between 2nd lock and 1st lock:
> �-> (hcd_urb_list_lock){+.....} ops: 252 {
> ����HARDIRQ-ON-W at:
> ����������������������__lock_acquire+0x602/0x1280
> ����������������������lock_acquire+0xd5/0x1c0
> ����������������������_raw_spin_lock+0x2f/0x40
> ����������������������usb_hcd_unlink_urb_from_ep+0x1b/0x60 [usbcore]
> ����������������������xhci_giveback_urb_in_irq.isra.45+0x70/0x1b0 [xhci_hcd]
> ����������������������finish_td.constprop.60+0x1d8/0x2e0 [xhci_hcd]
> ����������������������xhci_irq+0xdd6/0x1fa0 [xhci_hcd]
> ����������������������usb_hcd_irq+0x26/0x40 [usbcore]
> ����������������������irq_forced_thread_fn+0x2f/0x70
> ����������������������irq_thread+0x149/0x1d0
> ����������������������kthread+0x113/0x150
> ����������������������ret_from_fork+0x2e/0x40
> ����INITIAL USE at:
> ���������������������__lock_acquire+0x343/0x1280
> ���������������������lock_acquire+0xd5/0x1c0
> ���������������������_raw_spin_lock+0x2f/0x40
> ���������������������usb_hcd_link_urb_to_ep+0x2e/0xd0 [usbcore]
> ���������������������usb_hcd_submit_urb+0x117/0xb40 [usbcore]
> ���������������������usb_submit_urb+0x2f4/0x560 [usbcore]
> ���������������������usb_start_wait_urb+0x5f/0x150 [usbcore]
> ���������������������usb_control_msg+0xc1/0xf0 [usbcore]
> ���������������������usb_get_descriptor+0x79/0xc0 [usbcore]
> ���������������������usb_get_device_descriptor+0x57/0x100 [usbcore]
> ���������������������usb_add_hcd+0x329/0x8a0 [usbcore]
> ���������������������usb_hcd_pci_probe+0x1af/0x450 [usbcore]
> ���������������������xhci_pci_probe+0x1c/0x180 [xhci_pci]
> ���������������������local_pci_probe+0x24/0x60
> ���������������������pci_device_probe+0xd8/0x130
> ���������������������driver_probe_device+0x26a/0x410
> ���������������������__driver_attach+0xe3/0xf0
> ���������������������bus_for_each_dev+0x62/0xa0
> ���������������������driver_attach+0x1e/0x20
> ���������������������bus_add_driver+0x173/0x270
> ���������������������driver_register+0x60/0xe0
> ���������������������__pci_register_driver+0x5d/0x60
> ���������������������0xffffffffa0147031
> ���������������������do_one_initcall+0x43/0x170
> ���������������������do_init_module+0x5f/0x1fa
> ���������������������load_module+0x24ab/0x2c00
> ���������������������SYSC_finit_module+0xbc/0xf0
> ���������������������SyS_finit_module+0xe/0x10
> ���������������������do_syscall_64+0x5c/0x140
> ���������������������return_from_SYSCALL_64+0x0/0x7a
> � }
> � ... key������at: [<ffffffffa008bf18>] hcd_urb_list_lock+0x18/0xffffffffffff7100 [usbcore]
> � ... acquired at:
> ���lock_acquire+0xd5/0x1c0
> ���_raw_spin_lock+0x2f/0x40
> ���usb_hcd_link_urb_to_ep+0x2e/0xd0 [usbcore]
> ���ehci_urb_enqueue+0xab/0x107f [ehci_hcd]
> ���usb_hcd_submit_urb+0x8f/0xb40 [usbcore]
> ���usb_submit_urb+0x2f4/0x560 [usbcore]
> ���usb_start_wait_urb+0x5f/0x150 [usbcore]
> ���usb_control_msg+0xc1/0xf0 [usbcore]
> ���hub_port_init+0x305/0xb90 [usbcore]
> ���hub_event+0x690/0x1250 [usbcore]
> ���process_one_work+0x20b/0x6a0
> ���worker_thread+0x4e/0x4a0
> ���kthread+0x113/0x150
> ���ret_from_fork+0x2e/0x40
> 
> -> (&(&ehci->lock)->rlock){-.-...} ops: 38 {
> ���IN-HARDIRQ-W at:
> ��������������������__lock_acquire+0x67d/0x1280
> ��������������������lock_acquire+0xd5/0x1c0
> ��������������������_raw_spin_lock_irqsave+0x3a/0x50
> ��������������������ehci_hrtimer_func+0x29/0xc0 [ehci_hcd]
> ��������������������__hrtimer_run_queues+0xde/0x4c0
> ��������������������hrtimer_interrupt+0xaa/0x200
> ��������������������local_apic_timer_interrupt+0x38/0x60
> ��������������������smp_apic_timer_interrupt+0x38/0x50
> ��������������������apic_timer_interrupt+0x90/0xa0
> ��������������������cpuidle_enter_state+0x135/0x380
> ��������������������cpuidle_enter+0x17/0x20
> ��������������������call_cpuidle+0x23/0x40
> ��������������������do_idle+0xe8/0x1c0
> ��������������������cpu_startup_entry+0x1d/0x20
> ��������������������start_secondary+0x103/0x130
> ��������������������verify_cpu+0x0/0xfc
> ���IN-SOFTIRQ-W at:
> ��������������������__lock_acquire+0x560/0x1280
> ��������������������lock_acquire+0xd5/0x1c0
> ��������������������_raw_spin_lock_irqsave+0x3a/0x50
> ��������������������ehci_hub_status_data+0x6c/0x1a0 [ehci_hcd]
> ��������������������usb_hcd_poll_rh_status+0x49/0x140 [usbcore]
> ��������������������rh_timer_func+0xe/0x10 [usbcore]
> ��������������������call_timer_fn+0x90/0x330
> ��������������������run_timer_softirq+0x21a/0x5b0
> ��������������������__do_softirq+0xbf/0x4b7
> ��������������������run_ksoftirqd+0x1f/0x60
> ��������������������smpboot_thread_fn+0x128/0x1f0
> ��������������������kthread+0x113/0x150
> ��������������������ret_from_fork+0x2e/0x40
> ���INITIAL USE at:
> �������������������__lock_acquire+0x343/0x1280
> �������������������lock_acquire+0xd5/0x1c0
> �������������������_raw_spin_lock_irq+0x35/0x50
> �������������������ehci_halt+0x1e/0xf0 [ehci_hcd]
> �������������������ehci_setup+0x4de/0x810 [ehci_hcd]
> �������������������ehci_pci_setup+0xb7/0x576 [ehci_pci]
> �������������������usb_add_hcd+0x22e/0x8a0 [usbcore]
> �������������������usb_hcd_pci_probe+0x36d/0x450 [usbcore]
> �������������������ehci_pci_probe+0x36/0x40 [ehci_pci]
> �������������������local_pci_probe+0x24/0x60
> �������������������pci_device_probe+0xd8/0x130
> �������������������driver_probe_device+0x26a/0x410
> �������������������__driver_attach+0xe3/0xf0
> �������������������bus_for_each_dev+0x62/0xa0
> �������������������driver_attach+0x1e/0x20
> �������������������bus_add_driver+0x173/0x270
> �������������������driver_register+0x60/0xe0
> �������������������__pci_register_driver+0x5d/0x60
> �������������������0xffffffffa015006a
> �������������������do_one_initcall+0x43/0x170
> �������������������do_init_module+0x5f/0x1fa
> �������������������load_module+0x24ab/0x2c00
> �������������������SYSC_finit_module+0xbc/0xf0
> �������������������SyS_finit_module+0xe/0x10
> �������������������do_syscall_64+0x5c/0x140
> �������������������return_from_SYSCALL_64+0x0/0x7a
> �}
> �... key������at: [<ffffffffa013d390>] __key.38270+0x0/0xffffffffffffcc70 [ehci_hcd]
> �... acquired at:
> ���check_usage_forwards+0x120/0x130
> ���mark_lock+0x3bf/0x5c0
> ���__lock_acquire+0x67d/0x1280
> ���lock_acquire+0xd5/0x1c0
> ���_raw_spin_lock_irqsave+0x3a/0x50
> ���ehci_hrtimer_func+0x29/0xc0 [ehci_hcd]
> ���__hrtimer_run_queues+0xde/0x4c0
> ���hrtimer_interrupt+0xaa/0x200
> ���local_apic_timer_interrupt+0x38/0x60
> ���smp_apic_timer_interrupt+0x38/0x50
> ���apic_timer_interrupt+0x90/0xa0
> ���cpuidle_enter_state+0x135/0x380
> ���cpuidle_enter+0x17/0x20
> ���call_cpuidle+0x23/0x40
> ���do_idle+0xe8/0x1c0
> ���cpu_startup_entry+0x1d/0x20
> ���start_secondary+0x103/0x130
> ���verify_cpu+0x0/0xfc
> 
> stack backtrace:
> CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.11.0-rc8-dbg+ #1
> Hardware name: Dell Inc. PowerEdge R430/03XKDV, BIOS 1.0.2 11/17/2014
> Call Trace:
> �<IRQ>
> �dump_stack+0x68/0x93
> �print_irq_inversion_bug.part.37+0x1a5/0x1b1
> �check_usage_forwards+0x120/0x130
> �mark_lock+0x3bf/0x5c0
> �__lock_acquire+0x67d/0x1280
> �lock_acquire+0xd5/0x1c0
> �_raw_spin_lock_irqsave+0x3a/0x50
> �ehci_hrtimer_func+0x29/0xc0 [ehci_hcd]
> �__hrtimer_run_queues+0xde/0x4c0
> �hrtimer_interrupt+0xaa/0x200
> �local_apic_timer_interrupt+0x38/0x60
> �smp_apic_timer_interrupt+0x38/0x50
> �apic_timer_interrupt+0x90/0xa0
> �</IRQ>
> �cpuidle_enter+0x17/0x20
> �call_cpuidle+0x23/0x40
> �do_idle+0xe8/0x1c0
> �cpu_startup_entry+0x1d/0x20
> �start_secondary+0x103/0x130
> �start_cpu+0x14/0x14--
> 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

--
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



[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux