From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932406Ab2D0PXs (ORCPT ); Fri, 27 Apr 2012 11:23:48 -0400 Received: from e7.ny.us.ibm.com ([32.97.182.137]:39095 "EHLO e7.ny.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932290Ab2D0PXp (ORCPT ); Fri, 27 Apr 2012 11:23:45 -0400 Date: Fri, 27 Apr 2012 08:23:23 -0700 From: "Paul E. McKenney" To: Sasha Levin Cc: Gleb Natapov , Avi Kivity , Marcelo Tosatti , "linux-kernel@vger.kernel.org List" , kvm@vger.kernel.org Subject: Re: async pf: INFO: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected Message-ID: <20120427152323.GB2419@linux.vnet.ibm.com> Reply-To: paulmck@linux.vnet.ibm.com References: 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) X-Content-Scanned: Fidelis XPS MAILER x-cbid: 12042715-5806-0000-0000-000014AD924A Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu, Apr 26, 2012 at 04:50:35PM +0200, Sasha Levin wrote: > Hi all. > > I got a "INFO: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected" warning > while running LTP inside a KVM guest using the recent -next kernel. > > It seems that it was initially originated from rcu_torture_rea(), but I > don't think that it's a problem with RCU itself (I'll cc. Paul just in > case). RCU torture was indeed configured to run during the testing. I might be missing something, but I don't see how RCU is involved in this one. Thanx, Paul > The output is attached since it's a bit long. > > Thanks. > [ 4248.579019] ====================================================== > [ 4248.579019] [ INFO: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected ] > [ 4248.579019] 3.4.0-rc4-next-20120424-sasha #94 Tainted: G W > [ 4248.579019] ------------------------------------------------------ > [ 4248.579019] rcu_torture_rea/1615 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: > [ 4248.579019] (pgd_lock){+.+...}, at: [] pgd_free+0x26/0xa0 > [ 4248.579019] > [ 4248.579019] and this task is already holding: > [ 4248.579019] (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [ 4248.579019] which would create a new lock dependency: > [ 4248.579019] (&(&async_pf_sleepers[i].lock)->rlock){..-...} -> (pgd_lock){+.+...} > [ 4248.579019] > [ 4248.579019] but this new dependency connects a SOFTIRQ-irq-safe lock: > [ 4248.579019] (&(&async_pf_sleepers[i].lock)->rlock){..-...} > [ 4248.579019] ... which became SOFTIRQ-irq-safe at: > [ 4248.579019] [] mark_irqflags+0x95/0x170 > [ 4248.579019] [] __lock_acquire+0x2bb/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] kvm_async_pf_task_wake+0x48/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] call_softirq+0x1c/0x30 > [ 4248.579019] [] do_softirq+0x75/0x120 > [ 4248.579019] [] irq_exit+0x5b/0xf0 > [ 4248.579019] [] smp_apic_timer_interrupt+0x8a/0xa0 > [ 4248.579019] [] apic_timer_interrupt+0x6f/0x80 > [ 4248.579019] [] do_async_page_fault+0x5e/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] do_huge_pmd_wp_page+0x308/0x520 > [ 4248.579019] [] handle_mm_fault+0x25c/0x350 > [ 4248.579019] [] do_page_fault+0x421/0x450 > [ 4248.579019] [] do_async_page_fault+0x31/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] > [ 4248.579019] to a SOFTIRQ-irq-unsafe lock: > [ 4248.579019] (pgd_lock){+.+...} > [ 4248.579019] ... which became SOFTIRQ-irq-unsafe at: > [ 4248.579019] ... [] mark_irqflags+0x110/0x170 > [ 4248.579019] [] __lock_acquire+0x2bb/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] sync_global_pgds+0x61/0x1b0 > [ 4248.579019] [] vmalloc_sync_all+0x1d/0x20 > [ 4248.579019] [] register_die_notifier+0x11/0x30 > [ 4248.579019] [] init_uprobes+0x75/0x79 > [ 4248.579019] [] do_one_initcall+0x7a/0x155 > [ 4248.579019] [] do_basic_setup+0x9c/0xba > [ 4248.579019] [] kernel_init+0x1fe/0x280 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] > [ 4248.579019] other info that might help us debug this: > [ 4248.579019] > [ 4248.579019] Possible interrupt unsafe locking scenario: > [ 4248.579019] > [ 4248.579019] CPU0 CPU1 > [ 4248.579019] ---- ---- > [ 4248.579019] lock(pgd_lock); > [ 4248.579019] local_irq_disable(); > [ 4248.579019] lock(&(&async_pf_sleepers[i].lock)->rlock); > [ 4248.579019] lock(pgd_lock); > [ 4248.579019] > [ 4248.579019] lock(&(&async_pf_sleepers[i].lock)->rlock); > [ 4248.579019] > [ 4248.579019] *** DEADLOCK *** > [ 4248.579019] > [ 4248.579019] 1 lock held by rcu_torture_rea/1615: > [ 4248.579019] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [ 4248.579019] > [ 4248.579019] the dependencies between SOFTIRQ-irq-safe lock and the holding lock: > [ 4248.579019] -> (&(&async_pf_sleepers[i].lock)->rlock){..-...} ops: 1556 { > [ 4248.579019] IN-SOFTIRQ-W at: > [ 4248.579019] [] mark_irqflags+0x95/0x170 > [ 4248.579019] [] __lock_acquire+0x2bb/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] kvm_async_pf_task_wake+0x48/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] call_softirq+0x1c/0x30 > [ 4248.579019] [] do_softirq+0x75/0x120 > [ 4248.579019] [] irq_exit+0x5b/0xf0 > [ 4248.579019] [] smp_apic_timer_interrupt+0x8a/0xa0 > [ 4248.579019] [] apic_timer_interrupt+0x6f/0x80 > [ 4248.579019] [] do_async_page_fault+0x5e/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] do_huge_pmd_wp_page+0x308/0x520 > [ 4248.579019] [] handle_mm_fault+0x25c/0x350 > [ 4248.579019] [] do_page_fault+0x421/0x450 > [ 4248.579019] [] do_async_page_fault+0x31/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] INITIAL USE at: > [ 4248.579019] [] __lock_acquire+0x2e5/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] apf_task_wake_all+0x20/0x80 > [ 4248.579019] [] kvm_async_pf_task_wake+0x32/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] con_init+0x1b/0x23f > [ 4248.579019] [] console_init+0x19/0x2a > [ 4248.579019] [] start_kernel+0x30c/0x3f8 > [ 4248.579019] [] x86_64_start_reservations+0xff/0x104 > [ 4248.579019] [] x86_64_start_kernel+0x155/0x164 > [ 4248.579019] } > [ 4248.579019] ... key at: [] __key.35787+0x0/0x8 > [ 4248.579019] ... acquired at: > [ 4248.579019] [] check_usage+0x1ac/0x1d0 > [ 4248.579019] [] check_irq_usage+0x71/0xf0 > [ 4248.579019] [] check_prev_add+0x16b/0x4d0 > [ 4248.579019] [] validate_chain+0x69e/0x790 > [ 4248.579019] [] __lock_acquire+0x423/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] pgd_free+0x26/0xa0 > [ 4248.579019] [] __mmdrop+0x31/0xf0 > [ 4248.579019] [] apf_task_wake_one+0x4c/0x90 > [ 4248.579019] [] kvm_async_pf_task_wake+0x75/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] __schedule+0xce/0x880 > [ 4248.579019] [] schedule+0x55/0x60 > [ 4248.579019] [] rcu_torture_reader+0x2a2/0x380 > [ 4248.579019] [] kthread+0xb2/0xc0 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] > [ 4248.579019] > [ 4248.579019] the dependencies between the lock to be acquired and SOFTIRQ-irq-unsafe lock: > [ 4248.579019] -> (pgd_lock){+.+...} ops: 2112935 { > [ 4248.579019] HARDIRQ-ON-W at: > [ 4248.579019] [] mark_irqflags+0xf0/0x170 > [ 4248.579019] [] __lock_acquire+0x2bb/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] sync_global_pgds+0x61/0x1b0 > [ 4248.579019] [] vmalloc_sync_all+0x1d/0x20 > [ 4248.579019] [] register_die_notifier+0x11/0x30 > [ 4248.579019] [] init_uprobes+0x75/0x79 > [ 4248.579019] [] do_one_initcall+0x7a/0x155 > [ 4248.579019] [] do_basic_setup+0x9c/0xba > [ 4248.579019] [] kernel_init+0x1fe/0x280 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] SOFTIRQ-ON-W at: > [ 4248.579019] [] mark_irqflags+0x110/0x170 > [ 4248.579019] [] __lock_acquire+0x2bb/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] sync_global_pgds+0x61/0x1b0 > [ 4248.579019] [] vmalloc_sync_all+0x1d/0x20 > [ 4248.579019] [] register_die_notifier+0x11/0x30 > [ 4248.579019] [] init_uprobes+0x75/0x79 > [ 4248.579019] [] do_one_initcall+0x7a/0x155 > [ 4248.579019] [] do_basic_setup+0x9c/0xba > [ 4248.579019] [] kernel_init+0x1fe/0x280 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] INITIAL USE at: > [ 4248.579019] [] __lock_acquire+0x2e5/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] update_page_count+0x25/0x50 > [ 4248.579019] [] phys_pte_init+0x16d/0x180 > [ 4248.579019] [] phys_pmd_init+0x250/0x337 > [ 4248.579019] [] phys_pud_init+0x161/0x3a4 > [ 4248.579019] [] kernel_physical_mapping_init+0xed/0x1d9 > [ 4248.579019] [] init_memory_mapping+0x38b/0x460 > [ 4248.579019] [] setup_arch+0x691/0x815 > [ 4248.579019] [] start_kernel+0xf5/0x3f8 > [ 4248.579019] [] x86_64_start_reservations+0xff/0x104 > [ 4248.579019] [] x86_64_start_kernel+0x155/0x164 > [ 4248.579019] } > [ 4248.579019] ... key at: [] pgd_lock+0x18/0x50 > [ 4248.579019] ... acquired at: > [ 4248.579019] [] check_usage+0x1ac/0x1d0 > [ 4248.579019] [] check_irq_usage+0x71/0xf0 > [ 4248.579019] [] check_prev_add+0x16b/0x4d0 > [ 4248.579019] [] validate_chain+0x69e/0x790 > [ 4248.579019] [] __lock_acquire+0x423/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] pgd_free+0x26/0xa0 > [ 4248.579019] [] __mmdrop+0x31/0xf0 > [ 4248.579019] [] apf_task_wake_one+0x4c/0x90 > [ 4248.579019] [] kvm_async_pf_task_wake+0x75/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] __schedule+0xce/0x880 > [ 4248.579019] [] schedule+0x55/0x60 > [ 4248.579019] [] rcu_torture_reader+0x2a2/0x380 > [ 4248.579019] [] kthread+0xb2/0xc0 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] > [ 4248.579019] > [ 4248.579019] stack backtrace: > [ 4248.579019] Pid: 1615, comm: rcu_torture_rea Tainted: G W 3.4.0-rc4-next-20120424-sasha #94 > [ 4248.579019] Call Trace: > [ 4248.579019] [] print_bad_irq_dependency+0x2f2/0x310 > [ 4248.579019] [] check_usage+0x1ac/0x1d0 > [ 4248.579019] [] ? pvclock_clocksource_read+0x58/0xd0 > [ 4248.579019] [] check_irq_usage+0x71/0xf0 > [ 4248.579019] [] check_prev_add+0x16b/0x4d0 > [ 4248.579019] [] ? kvm_clock_read+0x46/0x80 > [ 4248.579019] [] validate_chain+0x69e/0x790 > [ 4248.579019] [] ? sched_clock_cpu+0x108/0x120 > [ 4248.579019] [] __lock_acquire+0x423/0x4c0 > [ 4248.579019] [] lock_acquire+0xdc/0x120 > [ 4248.579019] [] ? pgd_free+0x26/0xa0 > [ 4248.579019] [] _raw_spin_lock+0x3b/0x70 > [ 4248.579019] [] ? pgd_free+0x26/0xa0 > [ 4248.579019] [] pgd_free+0x26/0xa0 > [ 4248.579019] [] __mmdrop+0x31/0xf0 > [ 4248.579019] [] apf_task_wake_one+0x4c/0x90 > [ 4248.579019] [] kvm_async_pf_task_wake+0x75/0x130 > [ 4248.579019] [] do_async_page_fault+0x96/0xb0 > [ 4248.579019] [] async_page_fault+0x25/0x30 > [ 4248.579019] [] ? lock_is_held+0xfd/0x110 > [ 4248.579019] [] __schedule+0xce/0x880 > [ 4248.579019] [] schedule+0x55/0x60 > [ 4248.579019] [] rcu_torture_reader+0x2a2/0x380 > [ 4248.579019] [] ? T.842+0x50/0x50 > [ 4248.579019] [] ? rcu_torture_read_unlock+0x60/0x60 > [ 4248.579019] [] kthread+0xb2/0xc0 > [ 4248.579019] [] kernel_thread_helper+0x4/0x10 > [ 4248.579019] [] ? finish_task_switch+0x8d/0x110 > [ 4248.579019] [] ? retint_restore_args+0x13/0x13 > [ 4248.579019] [] ? __init_kthread_worker+0x70/0x70 > [ 4248.579019] [] ? gs_change+0x13/0x13