Re: hotplug lockdep splat (tip)

[Mike Galbraith]

On Mon, 2017-09-04 at 16:23 +0200, Peter Zijlstra wrote:
> On Mon, Sep 04, 2017 at 09:55:02AM +0200, Peter Zijlstra wrote:
> > On Sun, Sep 03, 2017 at 08:59:35AM +0200, Mike Galbraith wrote:
> > > 
> > > [  126.626908] Unregister pv shared memory for cpu 1
> > > [  126.631041] 
> > > [  126.631269] ======================================================
> > > [  126.632442] WARNING: possible circular locking dependency detected
> > > [  126.633599] 4.13.0.g06260ca-tip-lockdep #2 Tainted: G            E  
> > > [  126.634380] ------------------------------------------------------
> > > [  126.635124] stress-cpu-hotp/3156 is trying to acquire lock:
> > > [  126.635804]  ((complete)&st->done){+.+.}, at: [<ffffffff8108d19a>] takedown_cpu+0x8a/0xf0
> > > [  126.636809] 
> > > [  126.636809] but task is already holding lock:
> > > [  126.637567]  (sparse_irq_lock){+.+.}, at: [<ffffffff81107ac7>] irq_lock_sparse+0x17/0x20
> > > [  126.638665] 
> > 
> > https://lkml.kernel.org/r/20170829193416.GC32112@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
> > 
> > I still need to write a coherent Changelog and comments for that :/
> 
> How's this?

[ÂÂ138.241466] ======================================================
[ÂÂ138.242014] WARNING: possible circular locking dependency detected
[ÂÂ138.242802] 4.13.0.g90abd70-tip-lockdep #6 Tainted: GÂÂÂÂÂÂÂÂÂÂÂÂEÂÂ
[ÂÂ138.243701] ------------------------------------------------------
[ÂÂ138.244540] cpuhp/0/12 is trying to acquire lock:
[ÂÂ138.245187]ÂÂ(cpuhp_state){+.+.}, at: [<ffffffff8108e50a>]
cpuhp_thread_fun+0x2a/0x160
[ÂÂ138.246312]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂbut now in release context of a crosslock acquired at
the following:
[ÂÂ138.247519]ÂÂ((complete)&st->done#3){+.+.}, at: [<ffffffff8108e77f>]
cpuhp_issue_call+0x13f/0x170
[ÂÂ138.248745]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂwhich lock already depends on the new lock.

[ÂÂ138.249861]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂthe existing dependency chain (in reverse order) is:
[ÂÂ138.250836]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ-> #2 ((complete)&st->done#3){+.+.}:
[ÂÂ138.251732]ÂÂÂÂÂÂÂÂ__lock_acquire+0x116a/0x11c0
[ÂÂ138.252339]ÂÂÂÂÂÂÂÂlock_acquire+0xbd/0x200
[ÂÂ138.252906]ÂÂÂÂÂÂÂÂwait_for_completion+0x53/0x1a0
[ÂÂ138.253587]ÂÂÂÂÂÂÂÂtakedown_cpu+0x8a/0xf0
[ÂÂ138.254194]ÂÂÂÂÂÂÂÂcpuhp_invoke_callback+0x1f6/0x830
[ÂÂ138.254906]ÂÂÂÂÂÂÂÂcpuhp_down_callbacks+0x42/0x80
[ÂÂ138.255586]ÂÂÂÂÂÂÂÂ_cpu_down+0x14d/0x180
[ÂÂ138.256179]ÂÂÂÂÂÂÂÂdo_cpu_down+0x3e/0x60
[ÂÂ138.256774]ÂÂÂÂÂÂÂÂcpu_down+0x10/0x20
[ÂÂ138.257295]ÂÂÂÂÂÂÂÂcpu_subsys_offline+0x14/0x20
[ÂÂ138.257973]ÂÂÂÂÂÂÂÂdevice_offline+0x8c/0xb0
[ÂÂ138.258548]ÂÂÂÂÂÂÂÂonline_store+0x40/0x80
[ÂÂ138.259094]ÂÂÂÂÂÂÂÂdev_attr_store+0x18/0x30
[ÂÂ138.259668]ÂÂÂÂÂÂÂÂsysfs_kf_write+0x44/0x60
[ÂÂ138.260213]ÂÂÂÂÂÂÂÂkernfs_fop_write+0x113/0x1a0
[ÂÂ138.260873]ÂÂÂÂÂÂÂÂ__vfs_write+0x28/0x150
[ÂÂ138.261447]ÂÂÂÂÂÂÂÂvfs_write+0xc7/0x1c0
[ÂÂ138.262009]ÂÂÂÂÂÂÂÂSyS_write+0x49/0xa0
[ÂÂ138.262535]ÂÂÂÂÂÂÂÂentry_SYSCALL_64_fastpath+0x1f/0xbe
[ÂÂ138.263276]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ-> #1 (sparse_irq_lock){+.+.}:
[ÂÂ138.264070]ÂÂÂÂÂÂÂÂ__lock_acquire+0x116a/0x11c0
[ÂÂ138.264731]ÂÂÂÂÂÂÂÂlock_acquire+0xbd/0x200
[ÂÂ138.265300]ÂÂÂÂÂÂÂÂ__mutex_lock+0x70/0x8e0
[ÂÂ138.265881]ÂÂÂÂÂÂÂÂmutex_lock_nested+0x1b/0x20
[ÂÂ138.266515]ÂÂÂÂÂÂÂÂirq_lock_sparse+0x17/0x20
[ÂÂ138.267127]ÂÂÂÂÂÂÂÂirq_affinity_online_cpu+0x18/0xd0
[ÂÂ138.267813]ÂÂÂÂÂÂÂÂcpuhp_invoke_callback+0x1f6/0x830
[ÂÂ138.268538]ÂÂÂÂÂÂÂÂcpuhp_up_callbacks+0x37/0xb0
[ÂÂ138.269174]ÂÂÂÂÂÂÂÂcpuhp_thread_fun+0x14f/0x160
[ÂÂ138.269829]ÂÂÂÂÂÂÂÂsmpboot_thread_fn+0x11a/0x1e0
[ÂÂ138.270490]ÂÂÂÂÂÂÂÂkthread+0x152/0x190
[ÂÂ138.271055]ÂÂÂÂÂÂÂÂret_from_fork+0x2a/0x40
[ÂÂ138.271661]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ-> #0 (cpuhp_state){+.+.}:
[ÂÂ138.272424]ÂÂÂÂÂÂÂÂcpuhp_thread_fun+0x54/0x160
[ÂÂ138.273104]ÂÂÂÂÂÂÂÂsmpboot_thread_fn+0x11a/0x1e0
[ÂÂ138.273816]ÂÂÂÂÂÂÂÂkthread+0x152/0x190
[ÂÂ138.274371]ÂÂÂÂÂÂÂÂret_from_fork+0x2a/0x40
[ÂÂ138.274958]ÂÂÂÂÂÂÂÂ0xffffffffffffffff
[ÂÂ138.275450]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂother info that might help us debug this:

[ÂÂ138.276552] Chain exists of:
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂcpuhp_state --> sparse_irq_lock --> (complete)&st-
>done#3

[ÂÂ138.278114]ÂÂPossible unsafe locking scenario by crosslock:

[ÂÂ138.279122]ÂÂÂÂÂÂÂÂCPU0ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂCPU1
[ÂÂ138.279777]ÂÂÂÂÂÂÂÂ----ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ----
[ÂÂ138.280418]ÂÂÂlock(sparse_irq_lock);
[ÂÂ138.280936]ÂÂÂlock((complete)&st->done#3);
[ÂÂ138.281511]ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂlock(cpuhp_state);
[ÂÂ138.282322]ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂunlock((complete)&st-
>done#3);
[ÂÂ138.283269]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ*** DEADLOCK ***

[ÂÂ138.284147] 1 lock held by cpuhp/0/12:
[ÂÂ138.284688]ÂÂ#0:ÂÂ(&x->wait#2){-...}, at: [<ffffffff810e1b5d>]
complete+0x1d/0x60
[ÂÂ138.285734]Â
ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂstack backtrace:
[ÂÂ138.286368] CPU: 0 PID: 12 Comm: cpuhp/0 Tainted:
GÂÂÂÂÂÂÂÂÂÂÂÂEÂÂÂ4.13.0.g90abd70-tip-lockdep #6
[ÂÂ138.287800] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.0.0-prebuilt.qemu-project.org 04/01/2014
[ÂÂ138.289324] Call Trace:
[ÂÂ138.289708]ÂÂdump_stack+0x85/0xc5
[ÂÂ138.290199]ÂÂprint_circular_bug+0x2e9/0x2f7
[ÂÂ138.290805]ÂÂcheck_prev_add+0x666/0x700
[ÂÂ138.291313]ÂÂ? print_bfs_bug+0x40/0x40
[ÂÂ138.291866]ÂÂ? trace_hardirqs_on+0xd/0x10
[ÂÂ138.292223]ÂÂlock_commit_crosslock+0x410/0x5a0
[ÂÂ138.292620]ÂÂcomplete+0x29/0x60
[ÂÂ138.292900]ÂÂcpuhp_thread_fun+0xa1/0x160
[ÂÂ138.293233]ÂÂ? cpuhp_thread_fun+0x2a/0x160
[ÂÂ138.293584]ÂÂsmpboot_thread_fn+0x11a/0x1e0
[ÂÂ138.293943]ÂÂkthread+0x152/0x190
[ÂÂ138.294221]ÂÂ? sort_range+0x30/0x30
[ÂÂ138.294521]ÂÂ? kthread_create_on_node+0x40/0x40
[ÂÂ138.294920]ÂÂ? kthread+0x10/0x190
[ÂÂ138.295203]ÂÂret_from_fork+0x2a/0x40