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