Re: hotplug lockdep splat (tip)

[Mike Galbraith <efault@gmx.de>]

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@worktop.programming.kicks-ass.net
> > 
> > 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