From mboxrd@z Thu Jan 1 00:00:00 1970 From: Sasha Levin Subject: kvm: RCU warning in async pf Date: Mon, 02 Apr 2012 20:54:32 -0400 Message-ID: <1333414472.11455.7.camel@lappy> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Cc: kvm , linux-kernel , Dave Jones To: Avi Kivity , Marcelo Tosatti , Gleb Natapov , Thomas Gleixner , Peter Zijlstra , Ingo Molnar , "Paul E. McKenney" Return-path: Sender: linux-kernel-owner@vger.kernel.org List-Id: kvm.vger.kernel.org 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. [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.