From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753106AbcLGObs (ORCPT ); Wed, 7 Dec 2016 09:31:48 -0500 Received: from foss.arm.com ([217.140.101.70]:38692 "EHLO foss.arm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752632AbcLGObq (ORCPT ); Wed, 7 Dec 2016 09:31:46 -0500 Date: Wed, 7 Dec 2016 14:30:59 +0000 From: Mark Rutland To: linux-kernel@vger.kernel.org Cc: Peter Zijlstra , Ingo Molnar , Arnaldo Carvalho de Melo , Thomas Gleixner , Sebastian Andrzej Siewior , jeremy.linton@arm.com Subject: Re: Perf hotplug lockup in v4.9-rc8 Message-ID: <20161207143058.GC25605@leverpostej> References: <20161207135217.GA25605@leverpostej> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20161207135217.GA25605@leverpostej> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Wed, Dec 07, 2016 at 01:52:17PM +0000, Mark Rutland wrote: > Hi all > > Jeremy noticed a kernel lockup on arm64 when the perf tool was used in > parallel with hotplug, which I've reproduced on arm64 and x86(-64) with > v4.9-rc8. In both cases I'm using defconfig; I've tried enabling lockdep > but it was silent for arm64 and x86. > > I haven't yet tested earlier kernels and I'm not sure how long this has > been around for; I'm currently building a v4.8 defconfig to compare > with. In the meantime, info dump below. On v4.8 it hangs on x86, but my SSH session survived. Log below; I'll give v4.7 a go... [ 111.155981] sysrq: SysRq : Show Blocked State [ 111.156971] task PC stack pid father [ 111.156971] randomhotplug.s D ffff8801b4bafc80 13296 3597 3596 0x00000000 [ 111.156971] ffff8801b4bafc80 ffff8801b4bafc58 0000000000000246 ffffffff8201d540 [ 111.156971] ffff8801a7881880 ffff8801b4bb0000 0000000000000079 0000000000000002 [ 111.156971] 0000000000000002 0000000000000000 ffff8801b4bafc98 ffffffff81a752d7 [ 111.156971] Call Trace: [ 111.156971] [] schedule+0x37/0x90 [ 111.156971] [] cpu_hotplug_begin+0xaf/0xc0 [ 111.156971] [] ? __cpuhp_setup_state+0x210/0x210 [ 111.156971] [] ? prepare_to_wait_event+0x100/0x100 [ 111.156971] [] _cpu_up+0x2d/0xc0 [ 111.156971] [] do_cpu_up+0x5f/0x80 [ 111.156971] [] cpu_up+0xe/0x10 [ 111.156971] [] cpu_subsys_online+0x37/0x80 [ 111.156971] [] device_online+0x5c/0x80 [ 111.156971] [] online_store+0x6a/0x70 [ 111.156971] [] dev_attr_store+0x13/0x20 [ 111.156971] [] sysfs_kf_write+0x3f/0x50 [ 111.156971] [] kernfs_fop_write+0x13f/0x1d0 [ 111.156971] [] __vfs_write+0x23/0x120 [ 111.156971] [] ? percpu_down_read+0x57/0x90 [ 111.156971] [] ? __sb_start_write+0xc5/0xe0 [ 111.156971] [] ? __sb_start_write+0xc5/0xe0 [ 111.156971] [] vfs_write+0xb0/0x1b0 [ 111.156971] [] SyS_write+0x44/0xa0 [ 111.156971] [] entry_SYSCALL_64_fastpath+0x18/0xa8 [ 134.865008] INFO: rcu_sched self-detected stall on CPU[ 134.866024] INFO: rcu_sched detected stalls on CPUs/tasks: [ 134.866028] 1-...: (26000 ticks this GP) idle=163/140000000000001/0 softirq=13624/13624 fqs=6461 [ 134.866028] (detected by 0, t=26002 jiffies, g=13692, c=13691, q=422) [ 134.866031] Task dump for CPU 1: [ 134.866032] perf R running task 14392 6398 3677 0x00000008 [ 134.866038] ffff8801a7807c00 ffff8801a7807c00 ffff8801af66e800 ffff8801a7807c08 [ 134.866040] ffff8801a4553df0 ffff8801b4059880 0000000000000001 0000000000000001 [ 134.866042] 0000000000000000 0000000000000000 ffff8801b2cac980 0000000000000006 [ 134.866045] Call Trace: [ 134.866050] [] ? _raw_spin_unlock_irq+0x29/0x40 [ 134.866053] [] ? perf_install_in_context+0x7f/0x160 [ 134.866055] [] ? __perf_event_enable+0x140/0x140 [ 134.866056] [] ? SYSC_perf_event_open+0x510/0xf10 [ 134.866058] [] ? SyS_perf_event_open+0x9/0x10 [ 134.866059] [] ? entry_SYSCALL_64_fastpath+0x18/0xa8 [ 134.865009] [ 134.865009] 1-...: (26000 ticks this GP) idle=163/140000000000001/0 softirq=13624/13624 fqs=6486 [ 134.865009] (t=26111 jiffies g=13692 c=13691 q=422) [ 134.865009] Task dump for CPU 1: [ 134.865009] perf R running task 14392 6398 3677 0x00000008 [ 134.865009] 0000000000000e5d ffff8801b7403ca8 ffffffff810900d6 ffffffff8108fff7 [ 134.865009] 0000000000000001 0000000000000001 0000000000000086 ffff8801b7403cc0 [ 134.865009] ffffffff81093134 ffffffff82059a80 ffff8801b7403cf0 ffffffff811545aa [ 134.865009] Call Trace: [ 134.865009] [] sched_show_task+0x156/0x260 [ 134.865009] [] ? sched_show_task+0x77/0x260 [ 134.865009] [] dump_cpu_task+0x34/0x40 [ 134.865009] [] rcu_dump_cpu_stacks+0x88/0xc4 [ 134.865009] [] rcu_check_callbacks+0x8a7/0xa00 [ 134.865009] [] ? __acct_update_integrals+0x2b/0xb0 [ 134.865009] [] ? tick_sched_do_timer+0x30/0x30 [ 134.865009] [] update_process_times+0x2a/0x50 [ 134.865009] [] tick_sched_handle.isra.15+0x20/0x60 [ 134.865009] [] tick_sched_timer+0x38/0x70 [ 134.865009] [] __hrtimer_run_queues+0xef/0x510 [ 134.865009] [] hrtimer_interrupt+0xb2/0x1d0 [ 134.865009] [] hpet_interrupt_handler+0x11/0x30 [ 134.865009] [] __handle_irq_event_percpu+0x37/0x330 [ 134.865009] [] handle_irq_event_percpu+0x1e/0x50 [ 134.865009] [] handle_irq_event+0x34/0x60 [ 134.865009] [] handle_edge_irq+0x87/0x140 [ 134.865009] [] handle_irq+0xa6/0x130 [ 134.865009] [] do_IRQ+0x5e/0x120 [ 134.865009] [] common_interrupt+0x89/0x89 [ 134.865009] [] ? _raw_spin_unlock_irq+0x29/0x40 [ 134.865009] [] perf_install_in_context+0x7f/0x160 [ 134.865009] [] ? __perf_event_enable+0x140/0x140 [ 134.865009] [] SYSC_perf_event_open+0x510/0xf10 [ 134.865009] [] SyS_perf_event_open+0x9/0x10 [ 134.865009] [] entry_SYSCALL_64_fastpath+0x18/0xa8 [ 160.688129] NMI watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [perf:6398] [ 160.689009] Modules linked in: [ 160.689009] irq event stamp: 196860054 [ 160.689009] hardirqs last enabled at (196860053): [] _raw_spin_unlock_irq+0x27/0x40 [ 160.689009] hardirqs last disabled at (196860054): [] common_interrupt+0x84/0x89 [ 160.689009] softirqs last enabled at (196859662): [] __do_softirq+0x30d/0x470 [ 160.689009] softirqs last disabled at (196859655): [] irq_exit+0x97/0xa0 [ 160.689009] CPU: 1 PID: 6398 Comm: perf Not tainted 4.8.0 #3 [ 160.689009] Hardware name: LENOVO 7484A3G/LENOVO, BIOS 5CKT54AUS 09/07/2009 [ 160.689009] task: ffff8801b2cac980 task.stack: ffff8801a4550000 [ 160.689009] RIP: 0010:[] [] _raw_spin_unlock_irq+0x29/0x40 [ 160.689009] RSP: 0018:ffff8801a4553df0 EFLAGS: 00000206 [ 160.689009] RAX: ffff8801b2cac980 RBX: ffff8801b4059880 RCX: 0000000000000006 [ 160.689009] RDX: 0000000000004d60 RSI: ffff8801b2cad220 RDI: ffff8801b2cac980 [ 160.689009] RBP: ffff8801a4553df0 R08: 0000000000000000 R09: 0000000000000000 [ 160.689009] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8801a7807c08 [ 160.689009] R13: ffff8801af66e800 R14: ffff8801a7807c00 R15: ffff8801a7807c00 [ 160.689009] FS: 00007f5cb7301740(0000) GS:ffff8801b7400000(0000) knlGS:0000000000000000 [ 160.689009] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 160.689009] CR2: 00007f95f49e8000 CR3: 00000001a7b9a000 CR4: 00000000000406e0 [ 160.689009] Stack: [ 160.689009] ffff8801a4553e40 ffffffff81141c1f 0000000000000000 ffffffff81148ed0 [ 160.689009] ffff8801af66e800 ffff8801fffffffa ffff8801b4059880 ffff8801af66e93c [ 160.689009] ffff8801a7807c50 0000000000000003 ffff8801a4553f38 ffffffff8114bf40 [ 160.689009] Call Trace: [ 160.689009] [] perf_install_in_context+0x7f/0x160 [ 160.689009] [] ? __perf_event_enable+0x140/0x140 [ 160.689009] [] SYSC_perf_event_open+0x510/0xf10 [ 160.689009] [] SyS_perf_event_open+0x9/0x10 [ 160.689009] [] entry_SYSCALL_64_fastpath+0x18/0xa8 [ 160.689009] Code: 00 00 55 be 01 00 00 00 48 89 e5 53 48 89 fb 48 8b 55 08 48 8d 7f 18 e8 e6 31 63 ff 48 89 df e8 2e 85 63 ff e8 e9 0d 63 ff fb 5b <65> ff 0d 78 17 59 7e 5d c3 66 66 66 66 66 2e 0f 1f 84 00 00 00 Thanks, Mark.