From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755522Ab1GLUvb (ORCPT ); Tue, 12 Jul 2011 16:51:31 -0400 Received: from e5.ny.us.ibm.com ([32.97.182.145]:53931 "EHLO e5.ny.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755208Ab1GLUv3 (ORCPT ); Tue, 12 Jul 2011 16:51:29 -0400 Date: Tue, 12 Jul 2011 13:51:26 -0700 From: "Paul E. McKenney" To: Peter Zijlstra Cc: Dave Jones , Linux Kernel Subject: Re: lockdep circular locking error (rcu_node_level_0 vs rq->lock) Message-ID: <20110712205126.GM2326@linux.vnet.ibm.com> Reply-To: paulmck@linux.vnet.ibm.com References: <20110711231932.GB20367@redhat.com> <1310502014.2309.7.camel@laptop> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1310502014.2309.7.camel@laptop> User-Agent: Mutt/1.5.20 (2009-06-14) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, Jul 12, 2011 at 10:20:14PM +0200, Peter Zijlstra wrote: > 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. As we discussed on IRC, it doesn't look like RCU can safely defer this processing. For example, if softirqd is lower priority than an RCU priority boosted task, softirqd might never get a chance to lower the priority. Plus this could mess up the accounting for the rt_mutex used to carry out the priority boosting. And for reporting the end of an expedited RCU grace period, the possibly long-term deferral could easily defeat the whole purpose of expediting. So I am hoping that your idea of doing rcu_read_lock() before acquiring rq locks (and pi locks) and doing rcu_read_unlock() after releasing them does work out! Thanx, Paul