From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755202Ab1GLUP4 (ORCPT ); Tue, 12 Jul 2011 16:15:56 -0400 Received: from casper.infradead.org ([85.118.1.10]:45286 "EHLO casper.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753948Ab1GLUPy (ORCPT ); Tue, 12 Jul 2011 16:15:54 -0400 Subject: Re: lockdep circular locking error (rcu_node_level_0 vs rq->lock) From: Peter Zijlstra To: Dave Jones , "Paul E. McKenney" Cc: Linux Kernel In-Reply-To: <20110711231932.GB20367@redhat.com> References: <20110711231932.GB20367@redhat.com> Content-Type: text/plain; charset="UTF-8" Date: Tue, 12 Jul 2011 22:20:14 +0200 Message-ID: <1310502014.2309.7.camel@laptop> Mime-Version: 1.0 X-Mailer: Evolution 2.30.3 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 2011-07-11 at 19:19 -0400, Dave Jones wrote: > I was doing an install in a kvm guest, which wedged itself at the end. > This was in the host dmesg. > > > [ INFO: possible circular locking dependency detected ] > 3.0.0-rc6+ #91 > ------------------------------------------------------- > libvirtd/5720 is trying to acquire lock: > (rcu_node_level_0){..-.-.}, at: [] rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > > but task is already holding lock: > (&rq->lock){-.-.-.}, at: [] sched_ttwu_pending+0x39/0x5b > > which lock already depends on the new lock. > > > the existing dependency chain (in reverse order) is: > > -> #3 (&rq->lock){-.-.-.}: > [] lock_acquire+0xf3/0x13e > [] _raw_spin_lock+0x40/0x73 > [] __task_rq_lock+0x5e/0x8b > [] wake_up_new_task+0x46/0x10d > [] do_fork+0x231/0x331 > [] kernel_thread+0x75/0x77 > [] rest_init+0x26/0xdc > [] start_kernel+0x401/0x40c > [] x86_64_start_reservations+0xaf/0xb3 > [] x86_64_start_kernel+0x102/0x111 > > -> #2 (&p->pi_lock){-.-.-.}: > [] lock_acquire+0xf3/0x13e > [] _raw_spin_lock_irqsave+0x4f/0x89 > [] try_to_wake_up+0x2e/0x1db > [] default_wake_function+0x12/0x14 > [] autoremove_wake_function+0x18/0x3d > [] __wake_up_common+0x4d/0x83 > [] __wake_up+0x39/0x4d > [] rcu_report_exp_rnp+0x52/0x8b > [] __rcu_read_unlock+0x1d0/0x231 > [] rcu_read_unlock+0x26/0x28 > [] __d_lookup+0x103/0x115 > [] walk_component+0x1b1/0x3af > [] link_path_walk+0x1a1/0x43b > [] path_lookupat+0x5a/0x2af > [] do_path_lookup+0x28/0x97 > [] user_path_at+0x59/0x96 > [] sys_readlinkat+0x33/0x95 > [] sys_readlink+0x1b/0x1d > [] system_call_fastpath+0x16/0x1b > > -> #1 (sync_rcu_preempt_exp_wq.lock){......}: > [] lock_acquire+0xf3/0x13e > [] _raw_spin_lock_irqsave+0x4f/0x89 > [] __wake_up+0x22/0x4d > [] rcu_report_exp_rnp+0x52/0x8b > [] __rcu_read_unlock+0x1d0/0x231 > [] rcu_read_unlock+0x26/0x28 > [] __d_lookup+0x103/0x115 > [] walk_component+0x1b1/0x3af > [] link_path_walk+0x1a1/0x43b > [] path_lookupat+0x5a/0x2af > [] do_path_lookup+0x28/0x97 > [] user_path_at+0x59/0x96 > [] sys_readlinkat+0x33/0x95 > [] sys_readlink+0x1b/0x1d > [] system_call_fastpath+0x16/0x1b > > -> #0 (rcu_node_level_0){..-.-.}: > [] __lock_acquire+0xa2f/0xd0c > [] lock_acquire+0xf3/0x13e > [] _raw_spin_lock+0x40/0x73 > [] rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > [] __rcu_read_unlock+0x18e/0x231 > [] rcu_read_unlock+0x26/0x28 > [] cpuacct_charge+0x58/0x61 > [] update_curr+0x107/0x134 > [] check_preempt_wakeup+0xc9/0x1d0 > [] check_preempt_curr+0x2f/0x6e > [] ttwu_do_wakeup+0x7b/0x111 > [] ttwu_do_activate.constprop.76+0x5c/0x61 > [] sched_ttwu_pending+0x49/0x5b > [] scheduler_ipi+0xe/0x10 > [] smp_reschedule_interrupt+0x1b/0x1d > [] reschedule_interrupt+0x13/0x20 > [] rcu_read_unlock+0x26/0x28 > [] sock_def_readable+0x88/0x8d > [] unix_stream_sendmsg+0x264/0x2ff > [] sock_aio_write+0x112/0x126 > [] do_sync_write+0xbf/0xff > [] vfs_write+0xb6/0xf6 > [] sys_write+0x4d/0x74 > [] system_call_fastpath+0x16/0x1b > > other info that might help us debug this: > > Chain exists of: > rcu_node_level_0 --> &p->pi_lock --> &rq->lock > > Possible unsafe locking scenario: > > CPU0 CPU1 > ---- ---- > lock(&rq->lock); > lock(&p->pi_lock); > lock(&rq->lock); > lock(rcu_node_level_0); > > *** DEADLOCK *** > > 1 lock held by libvirtd/5720: > #0: (&rq->lock){-.-.-.}, at: [] sched_ttwu_pending+0x39/0x5b > > stack backtrace: > Pid: 5720, comm: libvirtd Not tainted 3.0.0-rc6+ #91 > Call Trace: > [] print_circular_bug+0x1f8/0x209 > [] __lock_acquire+0xa2f/0xd0c > [] ? sched_clock_local+0x12/0x75 > [] ? rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > [] lock_acquire+0xf3/0x13e > [] ? rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > [] ? lock_release_holdtime.part.10+0x59/0x62 > [] _raw_spin_lock+0x40/0x73 > [] ? rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > [] ? _raw_spin_unlock+0x47/0x54 > [] rcu_report_unblock_qs_rnp.part.5+0x3f/0x60 > [] ? __rcu_read_unlock+0xb8/0x231 > [] __rcu_read_unlock+0x18e/0x231 > [] rcu_read_unlock+0x26/0x28 > [] cpuacct_charge+0x58/0x61 > [] update_curr+0x107/0x134 > [] check_preempt_wakeup+0xc9/0x1d0 > [] check_preempt_curr+0x2f/0x6e > [] ttwu_do_wakeup+0x7b/0x111 > [] ttwu_do_activate.constprop.76+0x5c/0x61 > [] sched_ttwu_pending+0x49/0x5b > [] scheduler_ipi+0xe/0x10 > [] smp_reschedule_interrupt+0x1b/0x1d > [] reschedule_interrupt+0x13/0x20 > [] ? sched_clock_local+0x12/0x75 > [] ? __rcu_read_unlock+0x49/0x231 > [] ? lock_release+0x1b1/0x1de > [] rcu_read_unlock+0x26/0x28 > [] sock_def_readable+0x88/0x8d > [] unix_stream_sendmsg+0x264/0x2ff > [] sock_aio_write+0x112/0x126 > [] ? inode_has_perm+0x6a/0x77 > [] do_sync_write+0xbf/0xff > [] ? security_file_permission+0x2e/0x33 > [] ? rw_verify_area+0xb6/0xd3 > [] vfs_write+0xb6/0xf6 > [] ? fget_light+0x97/0xa2 > [] sys_write+0x4d/0x74 > [] ? remove_wait_queue+0x1a/0x3a > [] system_call_fastpath+0x16/0x1b Hi Paul, RCU is doing really bad things here, rcu_read_unlock() -> rcu_read_unlock_special() can do all kinds of nasty, including as per the above call back into the scheduler, which is kinda a death-warrant seeing as the scheduler itself can use RCU.