From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754006AbZBPWt3 (ORCPT ); Mon, 16 Feb 2009 17:49:29 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751237AbZBPWtU (ORCPT ); Mon, 16 Feb 2009 17:49:20 -0500 Received: from gw.goop.org ([64.81.55.164]:37771 "EHLO mail.goop.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751141AbZBPWtR (ORCPT ); Mon, 16 Feb 2009 17:49:17 -0500 Message-ID: <4999ED6A.8000803@goop.org> Date: Mon, 16 Feb 2009 14:49:14 -0800 From: Jeremy Fitzhardinge User-Agent: Thunderbird 2.0.0.19 (X11/20090105) MIME-Version: 1.0 To: Peter Zijlstra CC: Ingo Molnar , Linux Kernel Mailing List , the arch/x86 maintainers , Nick Piggin Subject: (spurious?) lockdep warning on Xen boot X-Enigmail-Version: 0.95.6 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org I've been seeing this warning appear early when I boot under Xen: ------------[ cut here ]------------ WARNING: at /home/jeremy/git/linux/kernel/lockdep.c:2185 trace_hardirqs_on_caller+0xbc/0x13c() Modules linked in: Pid: 0, comm: swapper Not tainted 2.6.29-rc4-tip #12 Call Trace: [] warn_slowpath+0xd8/0x114 [] ? __raw_callee_save_xen_save_fl+0x11/0x1e [] ? xen_mc_flush+0x1e2/0x21b [] ? trace_hardirqs_off_caller+0x2e/0x8c [] ? trace_hardirqs_off+0xd/0xf [] ? xen_setup_kernel_pagetable+0x442/0x4a4 [] trace_hardirqs_on_caller+0xbc/0x13c [] trace_hardirqs_on+0xd/0xf [] xen_setup_kernel_pagetable+0x442/0x4a4 [] xen_start_kernel+0x34e/0x4da ---[ end trace 4eaa2a86a8e2da22 ]--- Which corresponds to: if (DEBUG_LOCKS_WARN_ON(unlikely(!early_boot_irqs_enabled))) return; The code in question is running before start_kernel, and ends up doing some local_irq_save(flags)/local_irq_restore(flags) calls, which result in interrupts being re-enabled. I tried two approaches to fixing this. One was to disable interrupts early, before calling anything that would try to change the interrupt state (which seems sane, since I guess head.S enters the kernel with interrupts disabled), and the other was to call early_boot_irqs_on() to suppress the warning. Both cleared up the quoted warning, but then I got a huge lump of lockdep spew which seemed to be as a result of an interaction between usb and swiotlb via Xen (quoted below). I'm not sure if this is a real report, or fallout from something going wrong in the early init stages of lockdep. Or perhaps the second warning is real; in which case, where does the problem lie? (I guess another case of being bitten by calling __purge_vmap_area_lazy from interrupt context.) And if this second warning is real, why does it get suppressed by the first warning? Clues? Thanks, J /home/jeremy/git/linux/drivers/usb/core/inode.c: creating file '001' xen: registering gsi 18 triggering 0 polarity 1 usb 1-3: new high speed USB device using ehci_hcd and address 2 ====================================================== [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] 2.6.29-rc5-tip #22 ------------------------------------------------------ khubd/158 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: (&retval->lock){......}, at: [] dma_pool_alloc+0x30/0x29d and this task is already holding: (&ehci->lock){-.....}, at: [] ehci_urb_enqueue+0xab/0xe96 which would create a new lock dependency: (&ehci->lock){-.....} -> (&retval->lock){......} but this new dependency connects a HARDIRQ-irq-safe lock: (&ehci->lock){-.....} ... which became HARDIRQ-irq-safe at: [] 0xffffffffffffffff to a HARDIRQ-irq-unsafe lock: (purge_lock){+.+...} ... which became HARDIRQ-irq-unsafe at: ... [] __lock_acquire+0x77d/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] __purge_vmap_area_lazy+0x50/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] xen_create_contiguous_region+0x49/0xef [] xen_swiotlb_fixup+0x97/0xd0 [] swiotlb_alloc_boot+0x3e/0x49 [] swiotlb_init_with_default_size+0x3c/0x120 [] swiotlb_init+0xe/0x10 [] pci_swiotlb_init+0x6f/0x7c [] pci_iommu_alloc+0x59/0x5d [] mem_init+0xd/0xb7 [] start_kernel+0x3c0/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff other info that might help us debug this: 2 locks held by khubd/158: #0: (usb_address0_mutex){+.+...}, at: [] hub_port_init+0x83/0x617 #1: (&ehci->lock){-.....}, at: [] ehci_urb_enqueue+0xab/0xe96 the HARDIRQ-irq-safe lock's dependencies: -> (&ehci->lock){-.....} ops: 0 { IN-HARDIRQ-W at: [] 0xffffffffffffffff INITIAL USE at: [] 0xffffffffffffffff } ... key at: [] __key.31741+0x0/0x8 -> (hcd_urb_list_lock){......} ops: 0 { INITIAL USE at: [] __lock_acquire+0x80f/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] usb_hcd_link_urb_to_ep+0x28/0xab [] usb_hcd_submit_urb+0x460/0xa8a [] usb_submit_urb+0x2f8/0x315 [] usb_start_wait_urb+0x56/0x17b [] usb_control_msg+0xd4/0xf6 [] usb_get_descriptor+0x76/0xa6 [] usb_get_device_descriptor+0x59/0x88 [] usb_add_hcd+0x4ad/0x64a [] usb_hcd_pci_probe+0x25c/0x30d [] local_pci_probe+0x17/0x1b [] pci_device_probe+0x61/0x8b [] driver_probe_device+0xc9/0x177 [] __driver_attach+0x67/0x91 [] bus_for_each_dev+0x57/0x91 [] driver_attach+0x21/0x23 [] bus_add_driver+0xbf/0x20c [] driver_register+0xb0/0x130 [] __pci_register_driver+0x68/0xa0 [] ehci_hcd_init+0xb8/0xe3 [] do_one_initcall+0x5b/0x13e [] kernel_init+0x134/0x18c [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] hcd_urb_list_lock+0x18/0x30 ... acquired at: [] __lock_acquire+0x1354/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] usb_hcd_link_urb_to_ep+0x28/0xab [] ehci_urb_enqueue+0xd4/0xe96 [] usb_hcd_submit_urb+0x9b0/0xa8a [] usb_submit_urb+0x2f8/0x315 [] usb_start_wait_urb+0x56/0x17b [] usb_control_msg+0xd4/0xf6 [] hub_port_init+0x297/0x617 [] hub_thread+0xae5/0x1295 [] kthread+0x4e/0x7b [] child_rip+0xa/0x20 [] 0xffffffffffffffff the HARDIRQ-irq-unsafe lock's dependencies: -> (purge_lock){+.+...} ops: 0 { HARDIRQ-ON-W at: [] __lock_acquire+0x77d/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] __purge_vmap_area_lazy+0x50/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] xen_create_contiguous_region+0x49/0xef [] xen_swiotlb_fixup+0x97/0xd0 [] swiotlb_alloc_boot+0x3e/0x49 [] swiotlb_init_with_default_size+0x3c/0x120 [] swiotlb_init+0xe/0x10 [] pci_swiotlb_init+0x6f/0x7c [] pci_iommu_alloc+0x59/0x5d [] mem_init+0xd/0xb7 [] start_kernel+0x3c0/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff SOFTIRQ-ON-W at: [] __lock_acquire+0x7a6/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] __purge_vmap_area_lazy+0x50/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] xen_create_contiguous_region+0x49/0xef [] xen_swiotlb_fixup+0x97/0xd0 [] swiotlb_alloc_boot+0x3e/0x49 [] swiotlb_init_with_default_size+0x3c/0x120 [] swiotlb_init+0xe/0x10 [] pci_swiotlb_init+0x6f/0x7c [] pci_iommu_alloc+0x59/0x5d [] mem_init+0xd/0xb7 [] start_kernel+0x3c0/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x80f/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] __purge_vmap_area_lazy+0x50/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] xen_create_contiguous_region+0x49/0xef [] xen_swiotlb_fixup+0x97/0xd0 [] swiotlb_alloc_boot+0x3e/0x49 [] swiotlb_init_with_default_size+0x3c/0x120 [] swiotlb_init+0xe/0x10 [] pci_swiotlb_init+0x6f/0x7c [] pci_iommu_alloc+0x59/0x5d [] mem_init+0xd/0xb7 [] start_kernel+0x3c0/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff } ... key at: [] purge_lock.24514+0x18/0x30 -> (vmap_area_lock){+.+...} ops: 0 { HARDIRQ-ON-W at: [] __lock_acquire+0x77d/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] alloc_vmap_area+0x99/0x1ca [] __get_vm_area_node+0xdd/0x18d [] get_vm_area_caller+0x34/0x36 [] vmap+0x36/0x66 [] text_poke+0x11c/0x1b2 [] alternatives_smp_unlock+0x4f/0x67 [] alternatives_smp_switch+0x15f/0x19e [] alternative_instructions+0xf2/0x131 [] check_bugs+0xe/0x2d [] start_kernel+0x436/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff SOFTIRQ-ON-W at: [] __lock_acquire+0x7a6/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] alloc_vmap_area+0x99/0x1ca [] __get_vm_area_node+0xdd/0x18d [] get_vm_area_caller+0x34/0x36 [] vmap+0x36/0x66 [] text_poke+0x11c/0x1b2 [] alternatives_smp_unlock+0x4f/0x67 [] alternatives_smp_switch+0x15f/0x19e [] alternative_instructions+0xf2/0x131 [] check_bugs+0xe/0x2d [] start_kernel+0x436/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x80f/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] alloc_vmap_area+0x99/0x1ca [] __get_vm_area_node+0xdd/0x18d [] get_vm_area_caller+0x34/0x36 [] vmap+0x36/0x66 [] text_poke+0x11c/0x1b2 [] alternatives_smp_unlock+0x4f/0x67 [] alternatives_smp_switch+0x15f/0x19e [] alternative_instructions+0xf2/0x131 [] check_bugs+0xe/0x2d [] start_kernel+0x436/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff } ... key at: [] vmap_area_lock+0x18/0x30 ... acquired at: [] __lock_acquire+0x1354/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock+0x31/0x3d [] __purge_vmap_area_lazy+0x157/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] xen_alloc_ptpage+0xa8/0xd9 [] xen_alloc_pte+0x13/0x15 [] __pte_alloc_kernel+0x5b/0xb1 [] vmap_page_range+0x19b/0x30f [] map_vm_area+0x32/0x46 [] vmap+0x4d/0x66 [] text_poke+0x11c/0x1b2 [] alternatives_smp_unlock+0x4f/0x67 [] alternatives_smp_switch+0x15f/0x19e [] alternative_instructions+0xf2/0x131 [] check_bugs+0xe/0x2d [] start_kernel+0x436/0x452 [] x86_64_start_reservations+0xaa/0xae [] xen_start_kernel+0x4e4/0x4eb [] 0xffffffffffffffff -> (&q->lock#2){-.....} ops: 0 { IN-HARDIRQ-W at: [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x80f/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock_irqsave+0x47/0x5b [] generic_exec_single+0x41/0x8f [] smp_call_function_single+0x10e/0x127 [] smp_call_function_many+0xc5/0x1f8 [] smp_call_function+0x25/0x29 [] on_each_cpu+0x1d/0x48 [] kmem_cache_shrink+0x5a/0x1c8 [] acpi_os_purge_cache+0xe/0x12 [] acpi_purge_cached_objects+0x15/0x3d [] acpi_initialize_objects+0x4e/0x59 [] acpi_init+0x91/0x234 [] do_one_initcall+0x5b/0x13e [] kernel_init+0x134/0x18c [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.12205+0x0/0x8 ... acquired at: [] __lock_acquire+0x1354/0x16d9 [] lock_acquire+0x61/0x84 [] _spin_lock_irqsave+0x47/0x5b [] generic_exec_single+0x41/0x8f [] smp_call_function_single+0x10e/0x127 [] smp_call_function_many+0xc5/0x1f8 [] smp_call_function+0x25/0x29 [] on_each_cpu+0x1d/0x48 [] flush_tlb_all+0x1c/0x1e [] __purge_vmap_area_lazy+0x142/0x1a8 [] vm_unmap_aliases+0x1a9/0x1b8 [] __xen_pgd_pin+0x1d/0x19d [] xen_activate_mm+0x2a/0x37 [] flush_old_exec+0x32d/0x72c [] load_elf_binary+0x397/0x1940 [] search_binary_handler+0xbc/0x261 [] do_execve+0x1b9/0x269 [] sys_execve+0x43/0x65 [] kernel_execve+0x68/0xd0 [] child_rip+0xa/0x20 [] 0xffffffffffffffff stack backtrace: Pid: 158, comm: khubd Not tainted 2.6.29-rc5-tip #22 Call Trace: [] check_usage+0x3d6/0x3e7 [] ? check_noncircular+0xe8/0x11d [] check_irq_usage+0x61/0xc5 [] __lock_acquire+0x108e/0x16d9 [] ? print_context_stack+0xf8/0x116 [] ? dump_trace+0x265/0x277 [] lock_acquire+0x61/0x84 [] ? dma_pool_alloc+0x30/0x29d [] _spin_lock_irqsave+0x47/0x5b [] ? dma_pool_alloc+0x30/0x29d [] dma_pool_alloc+0x30/0x29d [] ? __lock_acquire+0x15f6/0x16d9 [] ? __lock_acquire+0x15f6/0x16d9 [] ehci_qh_alloc+0x28/0xbd [] ? check_events+0x12/0x20 [] ? xen_restore_fl_direct_end+0x0/0x1 [] qh_append_tds+0x3f/0x581 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? lock_release+0x164/0x171 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? usb_hcd_link_urb_to_ep+0x28/0xab [] ehci_urb_enqueue+0xf9/0xe96 [] ? string+0x3d/0xa1 [] ? vsnprintf+0x8d6/0x930 [] ? dump_trace+0x265/0x277 [] ? xen_range_needs_mapping+0xe/0x10 [] ? swiotlb_arch_range_needs_mapping+0x19/0x1b [] usb_hcd_submit_urb+0x9b0/0xa8a [] ? xen_force_evtchn_callback+0xd/0xf [] ? swiotlb_map_page+0x0/0x1a1 [] ? lockdep_init_map+0x92/0x529 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? debug_check_no_locks_freed+0x13a/0x147 [] usb_submit_urb+0x2f8/0x315 [] usb_start_wait_urb+0x56/0x17b [] ? check_events+0x12/0x20 [] ? usb_init_urb+0x27/0x37 [] usb_control_msg+0xd4/0xf6 [] ? kmem_cache_alloc+0xc1/0xe5 [] hub_port_init+0x297/0x617 [] hub_thread+0xae5/0x1295 [] ? trace_hardirqs_on+0xd/0xf [] ? autoremove_wake_function+0x0/0x3d [] ? _spin_unlock_irqrestore+0x53/0x58 [] ? hub_thread+0x0/0x1295 [] ? hub_thread+0x0/0x1295 [] kthread+0x4e/0x7b [] child_rip+0xa/0x20 [] ? restore_args+0x0/0x30 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? xen_restore_fl_direct_end+0x0/0x1 [] ? child_rip+0x0/0x20