Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753107Ab3GXONr (ORCPT ); Wed, 24 Jul 2013 10:13:47 -0400 Received: from e9.ny.us.ibm.com ([32.97.182.139]:44047 "EHLO e9.ny.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752751Ab3GXONm (ORCPT ); Wed, 24 Jul 2013 10:13:42 -0400 Date: Wed, 24 Jul 2013 07:13:34 -0700 From: "Paul E. McKenney" To: Linus Torvalds Cc: Dave Jones , Linux Kernel , Thomas Gleixner , Ingo Molnar Subject: Re: spinlock lockup, rcu stalls etc. Message-ID: <20130724141334.GA3668@linux.vnet.ibm.com> Reply-To: paulmck@linux.vnet.ibm.com References: <20130723162835.GA20430@redhat.com> 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-TM-AS-MML: No X-Content-Scanned: Fidelis XPS MAILER x-cbid: 13072414-7182-0000-0000-000007D6BF70 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 4969 Lines: 94 On Tue, Jul 23, 2013 at 07:24:31PM -0700, Linus Torvalds wrote: > [ Added Thomas and Ingo due to that timer/nmi thing. ] > > On Tue, Jul 23, 2013 at 9:28 AM, Dave Jones wrote: > > Woke up to a box that I could log into, but would hang as soon as I tried to > > do any disk IO. This is what hit the logs before that. > > > > [28853.503179] hrtimer: interrupt took 4847 ns > > Ugh. There's some nasty timer congestion there.. > > > [28932.599607] BUG: spinlock lockup suspected on CPU#0, trinity-child2/6990 > > [28932.600419] lock: inode_sb_list_lock+0x0/0x80, .magic: dead4ead, .owner: trinity-child1/6763, .owner_cpu: 1 > > So the current owner of the lock is cpu 1. The other CPU's agree: > > > [28932.606666] BUG: spinlock lockup suspected on CPU#2, trinity-child2/6764 > > [28932.606669] lock: inode_sb_list_lock+0x0/0x80, .magic: dead4ead, .owner: trinity-child1/6763, .owner_cpu: 1 > > [28932.617231] sending NMI to all CPUs: > > [28932.635092] BUG: spinlock lockup suspected on CPU#3, trinity-child3/6975 > > [28932.635095] lock: inode_sb_list_lock+0x0/0x80, .magic: dead4ead, .owner: trinity-child1/6763, .owner_cpu: 1 > > .. and their backtrace all points to them trying to take that > spinlock. So that is all consistent. > > And here's cpu1, edited down a bit: > > > [28932.777623] NMI backtrace for cpu 1 > > [28932.777625] INFO: NMI handler (arch_trigger_all_cpu_backtrace_handler) took too long to run: 91.230 msecs > > Whee. 91 msec? We have something going on there too. irq entry locks? Not sure what the deal is with the other stuff, but the stacks are being dumped from NMI handlers, and maybe the console got backed up a bit, slowing down the dump. -Might- account for the 91msec in an NMI handler. Thanx, Paul > > [28932.779440] CPU: 1 PID: 6763 Comm: trinity-child1 Not tainted 3.11.0-rc2+ #54 > > [28932.782283] RIP: 0010:[] [] add_preempt_count+0x25/0xf0 > > [28932.797761] Call Trace: > > [28932.798737] > > [28932.799715] [] delay_tsc+0x61/0xe0 > > [28932.800693] [] __const_udelay+0x29/0x30 > > [28932.801674] [] __rcu_read_unlock+0x54/0xa0 > > [28932.802657] [] cpuacct_account_field+0xf1/0x200 > > [28932.804613] [] account_system_time+0xb0/0x1b0 > > [28932.805561] [] __vtime_account_system+0x35/0x40 > > [28932.806506] [] vtime_account_system.part.2+0x2d/0x50 > > [28932.807445] [] vtime_account_irq_enter+0x55/0x80 > > [28932.808365] [] irq_enter+0x4f/0x90 > > [28932.809269] [] smp_apic_timer_interrupt+0x35/0x60 > > [28932.810156] [] apic_timer_interrupt+0x6f/0x80 > > [28932.812756] [] irq_exit+0xcd/0xe0 > > [28932.813618] [] smp_apic_timer_interrupt+0x45/0x60 > > [28932.814483] [] apic_timer_interrupt+0x6f/0x80 > > [28932.815345] > > [28932.816207] [] ? retint_restore_args+0xe/0xe > > [28932.817069] [] ? lock_acquired+0x105/0x3f0 > > [28932.817924] [] ? sync_inodes_sb+0x1c2/0x2a0 > > [28932.818767] [] _raw_spin_lock+0x6c/0x80 > > [28932.819616] [] ? sync_inodes_sb+0x1c2/0x2a0 > > [28932.820468] [] sync_inodes_sb+0x1c2/0x2a0 > > [28932.821310] [] ? wait_for_completion+0xdf/0x110 > > [28932.823819] [] sync_inodes_one_sb+0x19/0x20 > > [28932.824649] [] iterate_supers+0xb2/0x110 > > [28932.825477] [] sys_sync+0x35/0x90 > > [28932.826300] [] tracesys+0xdd/0xe2 > > [28932.827119] [] ? 0xffffffff9fffffff > > .. and again, it actually looks like the time is not necessarily spent > inside the spinlock in sync_inodes_sb(), but in a timer interrupt that > just happened to go off during that. I wonder if this is the same > issue that caused that earlier hrtimer long delay.. I'm not > necessarily seeing 91 msecs worth, but.. > > You seem to have CONFIG_PROVE_RCU_DELAY enabled, which explains that > delay_tsc() call in there. I wonder how much things like that make it > worse. Together with the (crazy bad) back-off in __spin_lock_debug(), > there might be a *lot* of these delays. > > That said, the fact that your machine is dead after all this implies > that there is something else wrong than just things being very slow. > But I suspect at least *part* of your problems may be due to these > kinds of debugging options that make things much much worse. > > Linus > -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/