Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756879Ab3CHUsl (ORCPT ); Fri, 8 Mar 2013 15:48:41 -0500 Received: from userp1040.oracle.com ([156.151.31.81]:51137 "EHLO userp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753147Ab3CHUsk (ORCPT ); Fri, 8 Mar 2013 15:48:40 -0500 Message-ID: <513A4E8F.2020704@oracle.com> Date: Fri, 08 Mar 2013 15:48:15 -0500 From: Sasha Levin User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130227 Thunderbird/17.0.3 MIME-Version: 1.0 To: paulmck@linux.vnet.ibm.com CC: Steven Rostedt , Frederic Weisbecker , Thomas Gleixner , Ingo Molnar , Andrew Morton , paul.gortmaker@windriver.com, Dave Jones , "linux-kernel@vger.kernel.org" Subject: Re: irq_work: WARNING: at kernel/irq_work.c:98 irq_work_needs_cpu+0x8a/0xb0() References: <51397B96.7030008@oracle.com> <20130308164435.GI3268@linux.vnet.ibm.com> <513A2CF1.9060006@oracle.com> <20130308194608.GK3268@linux.vnet.ibm.com> In-Reply-To: <20130308194608.GK3268@linux.vnet.ibm.com> Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit X-Source-IP: acsinet22.oracle.com [141.146.126.238] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 10045 Lines: 167 On 03/08/2013 02:46 PM, Paul E. McKenney wrote: > On Fri, Mar 08, 2013 at 01:24:49PM -0500, Sasha Levin wrote: >> On 03/08/2013 11:44 AM, Paul E. McKenney wrote: >>> On Fri, Mar 08, 2013 at 12:48:06AM -0500, Sasha Levin wrote: >>>> Hi guys, >>>> >>>> While fuzzing with trinity inside a KVM tools guest it seemed to have hit the >>>> new warning in kernel/irq_work.c: >>>> >>>> [ 486.527075] ------------[ cut here ]------------ >>>> [ 486.527788] WARNING: at kernel/irq_work.c:98 irq_work_needs_cpu+0x8a/0xb0() >>>> [ 486.528870] Modules linked in: >>>> [ 486.529377] Pid: 0, comm: swapper/2 Tainted: G W 3.9.0-rc1-next-20130307-sasha-00047-g0a7d304-dirty #1037 >>>> [ 486.530165] Call Trace: >>>> [ 486.530165] [] warn_slowpath_common+0x8c/0xc0 >>>> [ 486.530165] [] warn_slowpath_null+0x15/0x20 >>>> [ 486.530165] [] irq_work_needs_cpu+0x8a/0xb0 >>>> [ 486.530165] [] tick_nohz_stop_sched_tick+0x95/0x2a0 >>>> [ 486.530165] [] __tick_nohz_idle_enter+0x189/0x1b0 >>>> [ 486.530165] [] tick_nohz_idle_enter+0xa1/0xd0 >>>> [ 486.530165] [] cpu_idle+0x77/0x180 >>>> [ 486.530165] [] ? setup_APIC_timer+0xc9/0xce >>>> [ 486.530165] [] start_secondary+0xe1/0xe8 >>>> [ 486.530165] ---[ end trace dd075f5cfc2c4f26 ]--- >>>> >>>> Obviously this was happening when trinity tried to exercise the shutdown syscall. >>>> >>>> It was followed by RCU choking and causing a bunch of locked tasks, preventing >>>> shutdown. I guess it's the result of whatever caused this warning above to >>>> happen, but in-case it isn't, the relevant parts of the RCU hang are: >>>> >>>> [ 607.040283] INFO: task init:1 blocked for more than 120 seconds. >>>> [ 607.042932] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. >>>> [ 607.047046] init D ffff8800ba308000 2736 1 0 0x00000000 >>>> [ 607.050498] ffff8800ba311b18 0000000000000002 0000000000000003 ffff8800ba308000 >>>> [ 607.055110] ffff8800ba310000 ffff8800ba310010 ffff8800ba311fd8 ffff8800ba310000 >>>> [ 607.058208] ffff8800ba310010 ffff8800ba311fd8 ffffffff8542c420 ffff8800ba308000 >>>> [ 607.060611] Call Trace: >>>> [ 607.060847] [] ? __mutex_lock_common+0x365/0x5d0 >>>> [ 607.061462] [] schedule+0x55/0x60 >>>> [ 607.061948] [] schedule_preempt_disabled+0x13/0x20 >>>> [ 607.062590] [] __mutex_lock_common+0x3a5/0x5d0 >>>> [ 607.063209] [] ? rcu_cleanup_dead_cpu+0x52/0x250 >>>> [ 607.063840] [] ? free_cpumask_var+0x9/0x10 >>>> [ 607.064453] [] ? rcu_cleanup_dead_cpu+0x52/0x250 >>>> [ 607.065035] [] mutex_lock_nested+0x40/0x50 >>>> [ 607.065606] [] rcu_cleanup_dead_cpu+0x52/0x250 >>>> [ 607.066230] [] ? trace_hardirqs_on+0xd/0x10 >>>> [ 607.066810] [] rcu_cpu_notify+0x1b4/0x1ef >>>> [ 607.067375] [] notifier_call_chain+0xee/0x130 >>>> [ 607.067975] [] __raw_notifier_call_chain+0x9/0x10 >>>> [ 607.068631] [] __cpu_notify+0x1b/0x30 >>>> [ 607.069165] [] cpu_notify_nofail+0x10/0x30 >>>> [ 607.069749] [] _cpu_down+0x185/0x2e0 >>>> [ 607.070319] [] disable_nonboot_cpus+0x88/0x1b0 >>>> [ 607.070937] [] kernel_restart+0x16/0x60 >>>> [ 607.071487] [] SYSC_reboot+0x18c/0x2a0 >>>> [ 607.072020] [] ? rcu_cleanup_after_idle+0x23/0xf0 >>>> [ 607.072635] [] ? rcu_eqs_exit_common+0x64/0x280 >>>> [ 607.073251] [] ? user_exit+0xc5/0x100 >>>> [ 607.073772] [] ? trace_hardirqs_on+0xd/0x10 >>>> [ 607.074352] [] ? syscall_trace_enter+0x23/0x290 >>>> [ 607.075054] [] SyS_reboot+0x9/0x10 >>>> [ 607.075495] [] tracesys+0xdd/0xe2 >>>> [ 607.075967] 4 locks held by init/1: >>>> [ 607.076439] #0: (reboot_mutex){+.+.+.}, at: [] SYSC_reboot+0xe6/0x2a0 >>>> [ 607.077276] #1: (cpu_add_remove_lock){+.+.+.}, at: [] cpu_maps_update_begin+0x12/0x20 >>>> [ 607.078288] #2: (cpu_hotplug.lock){+.+.+.}, at: [] cpu_hotplug_begin+0x27/0x60 >>>> [ 607.079260] #3: (rcu_preempt_state.onoff_mutex){+.+...}, at: [] rcu_cleanup_dead_cpu+0x52/0x250 >>>> >>>> [ 607.187177] rcu_preempt D ffff8800aa8884a8 5136 11 2 0x00000000 >>>> [ 607.187890] ffff8800ba391c08 0000000000000002 ffff8800ba391bb8 000000078117e00a >>>> [ 607.188674] ffff8800ba390000 ffff8800ba390010 ffff8800ba391fd8 ffff8800ba390000 >>>> [ 607.189472] ffff8800ba390010 ffff8800ba391fd8 ffff8800ba308000 ffff8800ba388000 >>>> [ 607.190581] Call Trace: >>>> [ 607.190849] [] schedule+0x55/0x60 >>>> [ 607.191336] [] schedule_timeout+0x276/0x2c0 >>>> [ 607.191904] [] ? lock_timer_base+0x70/0x70 >>>> [ 607.192460] [] schedule_timeout_uninterruptible+0x19/0x20 >>>> [ 607.193132] [] rcu_gp_init+0x438/0x490 >>>> [ 607.193646] [] ? trace_hardirqs_on+0xd/0x10 >>>> [ 607.194216] [] rcu_gp_kthread+0xbc/0x2d0 >>>> [ 607.194760] [] ? rcu_gp_init+0x490/0x490 >>>> [ 607.195298] [] ? wake_up_bit+0x40/0x40 >>>> [ 607.195823] [] ? rcu_gp_init+0x490/0x490 >>>> [ 607.196364] [] kthread+0xe2/0xf0 >>>> [ 607.196842] [] ? __lock_release+0x1da/0x1f0 >>>> [ 607.197405] [] ? __init_kthread_worker+0x70/0x70 >>>> [ 607.198022] [] ret_from_fork+0x7c/0xb0 >>>> [ 607.198559] [] ? __init_kthread_worker+0x70/0x70 >>>> >>>> [ 609.414891] Showing all locks held in the system: >>>> [ 609.415490] 4 locks held by init/1: >>>> [ 609.415836] #0: (reboot_mutex){+.+.+.}, at: [] SYSC_reboot+0xe6/0x2a0 >>>> [ 609.416708] #1: (cpu_add_remove_lock){+.+.+.}, at: [] cpu_maps_update_begin+0x12/0x20 >>>> [ 609.417712] #2: (cpu_hotplug.lock){+.+.+.}, at: [] cpu_hotplug_begin+0x27/0x60 >>>> [ 609.418668] #3: (rcu_preempt_state.onoff_mutex){+.+...}, at: [] rcu_cleanup_dead_cpu+0x52/0x250 >>>> [ 609.419819] 1 lock held by rcu_preempt/11: >>>> [ 609.420277] #0: (rcu_preempt_state.onoff_mutex){+.+...}, at: [] rcu_gp_init+0x169/0x490 >>>> [ 609.421391] 2 locks held by khungtaskd/3087: >>>> [ 609.421811] #0: (rcu_read_lock){.+.+..}, at: [] check_hung_uninterruptible_tasks+0x3c/0x390 >>>> [ 609.422867] #1: (tasklist_lock){.+.+..}, at: [] debug_show_all_locks+0x5c/0x270 >>>> [ 609.423841] 2 locks held by sh/7108: >>>> [ 609.424199] #0: (&tty->ldisc_sem){.+.+.+}, at: [] tty_ldisc_ref_wait+0x1f/0x50 >>>> [ 609.425134] #1: (&ldata->atomic_read_lock){+.+...}, at: [] n_tty_read+0x31e/0x980 >>>> >>>> It looks like rcu_gp_init() went sleeping with the onoff_mutex held and >>>> never got it's wakeup, while the rcu_cleanup_dead_cpu() code is waiting >>>> to grab on that mutex. >>> >>> If your workload was busy enough with enough non-SCHED_OTHER activity >>> that SCHED_OTHER tasks (like RCU's grace-period kthread) don't get to >>> run, this is expected behavior. If this is reproducible, could you >>> please try using chrt to increase that kthread's priority? >> >> I've tried bumping all the rcu gp related threads before trinity starts, but >> it still didn't help - got the same hang. >> >> Also, it's always comes after that IRQ warning, and when it happens it doesn't >> look like the vm is doing anything else - the cpu usage (on the host) drops and >> it seems like it's just waiting. > > So you have CONFIG_PROVE_RCU_DELAY=y, right? Otherwise, I am at a loss to > explain why rcu_gp_init() is calling schedule_timeout_uninterruptible(). > Which is fair enough, as even if you do have CONFIG_PROVE_RCU_DELAY=y, > I am at a loss to explain why schedule_timeout_uninterruptible() doesn't > return after two jiffies. Indeed I do. > Ah, but why trust the stack trace? We certainly should not trust the > list of held locks, given that it shows two separate tasks holding > rcu_preempt_state.onoff_mutex!!! That would be bad... I think that the case here is that the GP thread is holding on to the onoff_mutex, and the rcu_cpu_notify thread is trying to acquire it. Since lockdep marks locks as held before they are actually acquired this is why you see 2 threads "holding" the lock. > But it is legitimate if the rcu_preempt_state.onoff_mutex is simply being > acquired and released in quick succession. Which seems unlikely, because > there are only so many CPUs to offline. Besides, the offlining has been > reportedly held up for 120 seconds. > >> btw, wouldn't the same thing happen even when the vm isn't going for a reboot >> if it was a priority issue? > > Indeed, one nagging concern is that the RCU grace-period kthreads might be > prevented from executing by a very heavy workload. I do have some ideas > on how to deal with that, but would rather see it really happen first. > Speculative engineering has its benefits, but... ;-) > > Does lockdep show anything? The lockdep spew I have is what I've attached at the bottom of the original report, it suggests that the problem indeed looks like what I've described above. Thanks, Sasha -- 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/