From mboxrd@z Thu Jan 1 00:00:00 1970 From: "Paul E. McKenney" Subject: Re: kvm: RCU warning in async pf Date: Tue, 3 Apr 2012 06:06:44 -0700 Message-ID: <20120403130643.GA2302@linux.vnet.ibm.com> References: <1333414472.11455.7.camel@lappy> Reply-To: paulmck@linux.vnet.ibm.com Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Cc: Avi Kivity , Marcelo Tosatti , Gleb Natapov , Thomas Gleixner , Peter Zijlstra , Ingo Molnar , kvm , linux-kernel , Dave Jones To: Sasha Levin Return-path: Content-Disposition: inline In-Reply-To: <1333414472.11455.7.camel@lappy> Sender: linux-kernel-owner@vger.kernel.org List-Id: kvm.vger.kernel.org On Mon, Apr 02, 2012 at 08:54:32PM -0400, Sasha Levin wrote: > Hi all, > > I got the spew at the bottom of the mail in a KVM guest using the KVM tools and running trinity. > > I'm not quite sure how default_idle managed to trigger a pagefault, so that part looks odd to me. Wrapping the offending RCU read-side critical section in RCU_NONIDLE() is the intended solution -- though that assumes that you can tell where the page fault will occur. Thanx, Paul > [12140.220507] =============================== > [12140.220507] [ INFO: suspicious RCU usage. ] > [12140.220507] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.220507] ------------------------------- > [12140.220507] include/linux/rcupdate.h:729 rcu_read_lock() used illegally while idle! > [12140.220507] > [12140.220507] other info that might help us debug this: > [12140.220507] > [12140.220507] > [12140.220507] RCU used illegally from idle CPU! > [12140.220507] rcu_scheduler_active = 1, debug_locks = 1 > [12140.220507] RCU used illegally from extended quiescent state! > [12140.220507] 4 locks held by swapper/1/0: > [12140.253991] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.253991] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.253991] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.253991] #3: (rcu_read_lock){.+.+..}, at: [] select_task_rq_fair+0xb0/0x5c0 > [12140.253991] > [12140.253991] stack backtrace: > [12140.253991] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.253991] Call Trace: > [12140.253991] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.253991] [] select_task_rq_fair+0x115/0x5c0 > [12140.253991] [] ? select_task_rq_fair+0xb0/0x5c0 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] try_to_wake_up+0x191/0x290 > [12140.253991] [] ? __lock_acquired+0x1c0/0x210 > [12140.253991] [] default_wake_function+0xd/0x10 > [12140.253991] [] autoremove_wake_function+0x18/0x40 > [12140.253991] [] __wake_up_common+0x52/0x90 > [12140.253991] [] ? __wake_up+0x2d/0x70 > [12140.253991] [] __wake_up+0x43/0x70 > [12140.253991] [] apf_task_wake_one+0x87/0x90 > [12140.253991] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.253991] [] do_async_page_fault+0x86/0xa0 > [12140.253991] [] async_page_fault+0x25/0x30 > [12140.253991] [] ? native_safe_halt+0x6/0x10 > [12140.253991] [] ? trace_hardirqs_on+0xd/0x10 > [12140.253991] [] default_idle+0x4d/0xa0 > [12140.253991] [] cpu_idle+0x11f/0x180 > [12140.253991] [] ? setup_APIC_timer+0x88/0x8c > [12140.253991] [] start_secondary+0xe1/0xe8 > [12140.253991] > [12140.253991] =============================== > [12140.253991] [ INFO: suspicious RCU usage. ] > [12140.253991] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.253991] ------------------------------- > [12140.253991] kernel/sched/fair.c:2716 suspicious rcu_dereference_check() usage! > [12140.253991] > [12140.253991] other info that might help us debug this: > [12140.253991] > [12140.253991] > [12140.253991] RCU used illegally from idle CPU! > [12140.253991] rcu_scheduler_active = 1, debug_locks = 1 > [12140.253991] RCU used illegally from extended quiescent state! > [12140.253991] 4 locks held by swapper/1/0: > [12140.253991] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.253991] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.253991] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.253991] #3: (rcu_read_lock){.+.+..}, at: [] select_task_rq_fair+0xb0/0x5c0 > [12140.253991] > [12140.253991] stack backtrace: > [12140.253991] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.253991] Call Trace: > [12140.253991] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.253991] [] select_task_rq_fair+0x17c/0x5c0 > [12140.253991] [] ? select_task_rq_fair+0xb0/0x5c0 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] try_to_wake_up+0x191/0x290 > [12140.253991] [] ? __lock_acquired+0x1c0/0x210 > [12140.253991] [] default_wake_function+0xd/0x10 > [12140.253991] [] autoremove_wake_function+0x18/0x40 > [12140.253991] [] __wake_up_common+0x52/0x90 > [12140.253991] [] ? __wake_up+0x2d/0x70 > [12140.253991] [] __wake_up+0x43/0x70 > [12140.253991] [] apf_task_wake_one+0x87/0x90 > [12140.253991] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.253991] [] do_async_page_fault+0x86/0xa0 > [12140.253991] [] async_page_fault+0x25/0x30 > [12140.253991] [] ? native_safe_halt+0x6/0x10 > [12140.253991] [] ? trace_hardirqs_on+0xd/0x10 > [12140.253991] [] default_idle+0x4d/0xa0 > [12140.253991] [] cpu_idle+0x11f/0x180 > [12140.253991] [] ? setup_APIC_timer+0x88/0x8c > [12140.253991] [] start_secondary+0xe1/0xe8 > [12140.253991] > [12140.253991] =============================== > [12140.253991] [ INFO: suspicious RCU usage. ] > [12140.253991] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.253991] ------------------------------- > [12140.253991] kernel/sched/fair.c:2660 suspicious rcu_dereference_check() usage! > [12140.253991] > [12140.253991] other info that might help us debug this: > [12140.253991] > [12140.253991] > [12140.253991] RCU used illegally from idle CPU! > [12140.253991] rcu_scheduler_active = 1, debug_locks = 1 > [12140.253991] RCU used illegally from extended quiescent state! > [12140.253991] 4 locks held by swapper/1/0: > [12140.253991] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.253991] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.253991] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.253991] #3: (rcu_read_lock){.+.+..}, at: [] select_task_rq_fair+0xb0/0x5c0 > [12140.253991] > [12140.253991] stack backtrace: > [12140.253991] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.253991] Call Trace: > [12140.253991] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.253991] [] select_idle_sibling+0xaf/0x1c0 > [12140.253991] [] select_task_rq_fair+0x381/0x5c0 > [12140.253991] [] ? select_task_rq_fair+0xb0/0x5c0 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] try_to_wake_up+0x191/0x290 > [12140.253991] [] ? __lock_acquired+0x1c0/0x210 > [12140.253991] [] default_wake_function+0xd/0x10 > [12140.253991] [] autoremove_wake_function+0x18/0x40 > [12140.253991] [] __wake_up_common+0x52/0x90 > [12140.253991] [] ? __wake_up+0x2d/0x70 > [12140.253991] [] __wake_up+0x43/0x70 > [12140.253991] [] apf_task_wake_one+0x87/0x90 > [12140.253991] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.253991] [] do_async_page_fault+0x86/0xa0 > [12140.253991] [] async_page_fault+0x25/0x30 > [12140.253991] [] ? native_safe_halt+0x6/0x10 > [12140.253991] [] ? trace_hardirqs_on+0xd/0x10 > [12140.253991] [] default_idle+0x4d/0xa0 > [12140.253991] [] cpu_idle+0x11f/0x180 > [12140.253991] [] ? setup_APIC_timer+0x88/0x8c > [12140.253991] [] start_secondary+0xe1/0xe8 > [12140.253991] > [12140.253991] =============================== > [12140.253991] [ INFO: suspicious RCU usage. ] > [12140.253991] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.253991] ------------------------------- > [12140.253991] include/linux/rcupdate.h:750 rcu_read_unlock() used illegally while idle! > [12140.253991] > [12140.253991] other info that might help us debug this: > [12140.253991] > [12140.253991] > [12140.253991] RCU used illegally from idle CPU! > [12140.253991] rcu_scheduler_active = 1, debug_locks = 1 > [12140.253991] RCU used illegally from extended quiescent state! > [12140.253991] 4 locks held by swapper/1/0: > [12140.253991] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.253991] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.253991] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.253991] #3: (rcu_read_lock){.+.+..}, at: [] select_task_rq_fair+0xb0/0x5c0 > [12140.253991] > [12140.253991] stack backtrace: > [12140.253991] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.253991] Call Trace: > [12140.253991] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.253991] [] select_task_rq_fair+0x55a/0x5c0 > [12140.253991] [] ? select_task_rq_fair+0xb0/0x5c0 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] ? try_to_wake_up+0x34/0x290 > [12140.253991] [] try_to_wake_up+0x191/0x290 > [12140.253991] [] ? __lock_acquired+0x1c0/0x210 > [12140.253991] [] default_wake_function+0xd/0x10 > [12140.253991] [] autoremove_wake_function+0x18/0x40 > [12140.253991] [] __wake_up_common+0x52/0x90 > [12140.253991] [] ? __wake_up+0x2d/0x70 > [12140.253991] [] __wake_up+0x43/0x70 > [12140.253991] [] apf_task_wake_one+0x87/0x90 > [12140.253991] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.253991] [] do_async_page_fault+0x86/0xa0 > [12140.253991] [] async_page_fault+0x25/0x30 > [12140.253991] [] ? native_safe_halt+0x6/0x10 > [12140.253991] [] ? trace_hardirqs_on+0xd/0x10 > [12140.253991] [] default_idle+0x4d/0xa0 > [12140.253991] [] cpu_idle+0x11f/0x180 > [12140.253991] [] ? setup_APIC_timer+0x88/0x8c > [12140.253991] [] start_secondary+0xe1/0xe8 > [12140.623131] > [12140.623131] =============================== > [12140.623131] [ INFO: suspicious RCU usage. ] > [12140.623131] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.623131] ------------------------------- > [12140.623131] include/linux/rcupdate.h:729 rcu_read_lock() used illegally while idle! > [12140.623131] > [12140.623131] other info that might help us debug this: > [12140.623131] > [12140.623131] > [12140.623131] RCU used illegally from idle CPU! > [12140.623131] rcu_scheduler_active = 1, debug_locks = 1 > [12140.623131] RCU used illegally from extended quiescent state! > [12140.623131] 4 locks held by swapper/1/0: > [12140.623131] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.623131] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.623131] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.623131] #3: (rcu_read_lock){.+.+..}, at: [] ttwu_stat+0x50/0x230 > [12140.623131] > [12140.623131] stack backtrace: > [12140.623131] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.623131] Call Trace: > [12140.623131] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.623131] [] ttwu_stat+0xc7/0x230 > [12140.623131] [] ? ttwu_stat+0x50/0x230 > [12140.623131] [] ? try_to_wake_up+0x34/0x290 > [12140.623131] [] try_to_wake_up+0x25a/0x290 > [12140.623131] [] ? __lock_acquired+0x1c0/0x210 > [12140.623131] [] default_wake_function+0xd/0x10 > [12140.623131] [] autoremove_wake_function+0x18/0x40 > [12140.623131] [] __wake_up_common+0x52/0x90 > [12140.623131] [] ? __wake_up+0x2d/0x70 > [12140.623131] [] __wake_up+0x43/0x70 > [12140.623131] [] apf_task_wake_one+0x87/0x90 > [12140.623131] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.623131] [] do_async_page_fault+0x86/0xa0 > [12140.623131] [] async_page_fault+0x25/0x30 > [12140.623131] [] ? native_safe_halt+0x6/0x10 > [12140.623131] [] ? trace_hardirqs_on+0xd/0x10 > [12140.623131] [] default_idle+0x4d/0xa0 > [12140.623131] [] cpu_idle+0x11f/0x180 > [12140.623131] [] ? setup_APIC_timer+0x88/0x8c > [12140.623131] [] start_secondary+0xe1/0xe8 > [12140.623131] > [12140.623131] =============================== > [12140.623131] [ INFO: suspicious RCU usage. ] > [12140.623131] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.623131] ------------------------------- > [12140.623131] kernel/sched/core.c:1375 suspicious rcu_dereference_check() usage! > [12140.623131] > [12140.623131] other info that might help us debug this: > [12140.623131] > [12140.623131] > [12140.623131] RCU used illegally from idle CPU! > [12140.623131] rcu_scheduler_active = 1, debug_locks = 1 > [12140.623131] RCU used illegally from extended quiescent state! > [12140.623131] 4 locks held by swapper/1/0: > [12140.623131] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.623131] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.623131] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.623131] #3: (rcu_read_lock){.+.+..}, at: [] ttwu_stat+0x50/0x230 > [12140.623131] > [12140.623131] stack backtrace: > [12140.623131] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.623131] Call Trace: > [12140.623131] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.623131] [] ttwu_stat+0x138/0x230 > [12140.623131] [] ? ttwu_stat+0x50/0x230 > [12140.623131] [] ? try_to_wake_up+0x34/0x290 > [12140.623131] [] try_to_wake_up+0x25a/0x290 > [12140.623131] [] ? __lock_acquired+0x1c0/0x210 > [12140.623131] [] default_wake_function+0xd/0x10 > [12140.623131] [] autoremove_wake_function+0x18/0x40 > [12140.623131] [] __wake_up_common+0x52/0x90 > [12140.623131] [] ? __wake_up+0x2d/0x70 > [12140.623131] [] __wake_up+0x43/0x70 > [12140.623131] [] apf_task_wake_one+0x87/0x90 > [12140.623131] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.623131] [] do_async_page_fault+0x86/0xa0 > [12140.623131] [] async_page_fault+0x25/0x30 > [12140.623131] [] ? native_safe_halt+0x6/0x10 > [12140.623131] [] ? trace_hardirqs_on+0xd/0x10 > [12140.623131] [] default_idle+0x4d/0xa0 > [12140.623131] [] cpu_idle+0x11f/0x180 > [12140.623131] [] ? setup_APIC_timer+0x88/0x8c > [12140.623131] [] start_secondary+0xe1/0xe8 > [12140.623131] > [12140.623131] =============================== > [12140.623131] [ INFO: suspicious RCU usage. ] > [12140.623131] 3.4.0-rc1-next-20120402-sasha #46 Tainted: G W > [12140.623131] ------------------------------- > [12140.623131] include/linux/rcupdate.h:750 rcu_read_unlock() used illegally while idle! > [12140.623131] > [12140.623131] other info that might help us debug this: > [12140.623131] > [12140.623131] > [12140.623131] RCU used illegally from idle CPU! > [12140.623131] rcu_scheduler_active = 1, debug_locks = 1 > [12140.623131] RCU used illegally from extended quiescent state! > [12140.623131] 4 locks held by swapper/1/0: > [12140.623131] #0: (&(&async_pf_sleepers[i].lock)->rlock){..-...}, at: [] kvm_async_pf_task_wake+0x48/0x130 > [12140.623131] #1: (&n.wq){......}, at: [] __wake_up+0x2d/0x70 > [12140.623131] #2: (&p->pi_lock){-.-.-.}, at: [] try_to_wake_up+0x34/0x290 > [12140.623131] #3: (rcu_read_lock){.+.+..}, at: [] ttwu_stat+0x50/0x230 > [12140.623131] > [12140.623131] stack backtrace: > [12140.623131] Pid: 0, comm: swapper/1 Tainted: G W 3.4.0-rc1-next-20120402-sasha #46 > [12140.623131] Call Trace: > [12140.623131] [] lockdep_rcu_suspicious+0x113/0x130 > [12140.623131] [] ttwu_stat+0x1d3/0x230 > [12140.623131] [] ? ttwu_stat+0x50/0x230 > [12140.623131] [] ? try_to_wake_up+0x34/0x290 > [12140.623131] [] try_to_wake_up+0x25a/0x290 > [12140.623131] [] ? __lock_acquired+0x1c0/0x210 > [12140.623131] [] default_wake_function+0xd/0x10 > [12140.623131] [] autoremove_wake_function+0x18/0x40 > [12140.623131] [] __wake_up_common+0x52/0x90 > [12140.623131] [] ? __wake_up+0x2d/0x70 > [12140.623131] [] __wake_up+0x43/0x70 > [12140.623131] [] apf_task_wake_one+0x87/0x90 > [12140.623131] [] kvm_async_pf_task_wake+0x75/0x130 > [12140.623131] [] do_async_page_fault+0x86/0xa0 > [12140.623131] [] async_page_fault+0x25/0x30 > [12140.623131] [] ? native_safe_halt+0x6/0x10 > [12140.623131] [] ? trace_hardirqs_on+0xd/0x10 > [12140.623131] [] default_idle+0x4d/0xa0 > [12140.623131] [] cpu_idle+0x11f/0x180 > [12140.623131] [] ? setup_APIC_timer+0x88/0x8c > [12140.623131] [] start_secondary+0xe1/0xe8 > > -- > > Sasha. >