lockdep splat in CPU hotplug

lockdep splat in CPU hotplug

[Jiri Kosina]

Hi,

I am seeing the lockdep report below when resuming from suspend-to-disk 
with current Linus' tree (c2661b80609).

The reason for CCing Ingo and Peter is that I can't make any sense of one 
of the stacktraces lockdep is providing.

Please have a look at the very first stacktrace in the dump, where lockdep 
is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
the case at all.

What am I missing?

Thanks.


 ======================================================
 [ INFO: possible circular locking dependency detected ]
 3.18.0-rc1-00069-gc2661b8 #1 Not tainted
 -------------------------------------------------------
 do_s2disk/2367 is trying to acquire lock:
  (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
 
but task is already holding lock:
  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
 
which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

-> #1 (cpu_hotplug.lock#2){+.+.+.}:
        [<ffffffff81099fac>] lock_acquire+0xac/0x130
        [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
        [<ffffffff81491892>] cpuidle_pause+0x12/0x30
        [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
        [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
        [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
        [<ffffffff810a1248>] hibernate+0x168/0x210
        [<ffffffff8109e9b4>] state_store+0xe4/0xf0
        [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
        [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
        [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
        [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
        [<ffffffff811a7da4>] SyS_write+0x44/0xb0
        [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
 
-> #0 (cpuidle_lock){+.+.+.}:
        [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
        [<ffffffff81099fac>] lock_acquire+0xac/0x130
        [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
        [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
        [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
        [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
        [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
        [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
        [<ffffffff810521ce>] cpu_notify+0x1e/0x40
        [<ffffffff810524a8>] _cpu_up+0x148/0x160
        [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
        [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
        [<ffffffff810a1248>] hibernate+0x168/0x210
        [<ffffffff8109e9b4>] state_store+0xe4/0xf0
        [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
        [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
        [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
        [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
        [<ffffffff811a7da4>] SyS_write+0x44/0xb0
        [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
 
other info that might help us debug this:

  Possible unsafe locking scenario:

        CPU0                    CPU1
        ----                    ----
   lock(cpu_hotplug.lock#2);
                                lock(cpuidle_lock);
                                lock(cpu_hotplug.lock#2);
   lock(cpuidle_lock);
 
 *** DEADLOCK ***

 8 locks held by do_s2disk/2367:
  #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff811a7443>] vfs_write+0x1b3/0x1f0
  #1:  (&of->mutex){+.+.+.}, at: [<ffffffff8121e25b>] kernfs_fop_write+0xbb/0x170
  #2:  (s_active#188){.+.+.+}, at: [<ffffffff8121e263>] kernfs_fop_write+0xc3/0x170
  #3:  (pm_mutex){+.+.+.}, at: [<ffffffff810a112e>] hibernate+0x4e/0x210
  #4:  (device_hotplug_lock){+.+.+.}, at: [<ffffffff813f1b52>] lock_device_hotplug+0x12/0x20
  #5:  (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff815a7aef>] enable_nonboot_cpus+0x1f/0x1d0
  #6:  (cpu_hotplug.lock){++++++}, at: [<ffffffff810522a0>] cpu_hotplug_begin+0x0/0x80
  #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
 
stack backtrace:
 CPU: 1 PID: 2367 Comm: do_s2disk Not tainted 3.18.0-rc1-00069-g4da0564 #1
 Hardware name: LENOVO 7470BN2/7470BN2, BIOS 6DET38WW (2.02 ) 12/19/2008
  ffffffff823e4330 ffff8800789e7a48 ffffffff815b6754 0000000000001a69
  ffffffff823e4330 ffff8800789e7a98 ffffffff815b078b ffff8800741a5510
  ffff8800789e7af8 ffff8800741a5ea8 5a024e919538010b ffff8800741a5ea8
 Call Trace:
  [<ffffffff815b6754>] dump_stack+0x4e/0x68
  [<ffffffff815b078b>] print_circular_bug+0x203/0x214
  [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
  [<ffffffff8109766d>] ? trace_hardirqs_on_caller+0xfd/0x1c0
  [<ffffffff81099fac>] lock_acquire+0xac/0x130
  [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
  [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
  [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
  [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
  [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
  [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
  [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
  [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
  [<ffffffff810521ce>] cpu_notify+0x1e/0x40
  [<ffffffff810524a8>] _cpu_up+0x148/0x160
  [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
  [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
  [<ffffffff810a1248>] hibernate+0x168/0x210
  [<ffffffff8109e9b4>] state_store+0xe4/0xf0
  [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
  [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
  [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
  [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
  [<ffffffff815be87b>] ? sysret_check+0x1b/0x56
  [<ffffffff811a7da4>] SyS_write+0x44/0xb0
  [<ffffffff815be856>] system_call_fastpath+0x16/0x1b

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Steven Rostedt]

On Tue, Oct 21, 2014 at 01:09:04PM +0200, Jiri Kosina wrote:
> Hi,
> 
> I am seeing the lockdep report below when resuming from suspend-to-disk 
> with current Linus' tree (c2661b80609).
> 
> The reason for CCing Ingo and Peter is that I can't make any sense of one 
> of the stacktraces lockdep is providing.
> 
> Please have a look at the very first stacktrace in the dump, where lockdep 
> is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> the case at all.
> 
> What am I missing?
> 


> 
> -> #1 (cpu_hotplug.lock#2){+.+.+.}:
>         [<ffffffff81099fac>] lock_acquire+0xac/0x130
>         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
>         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
>         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
>         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
>         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
>         [<ffffffff810a1248>] hibernate+0x168/0x210
>         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
>         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
>         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
>         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
>         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
>         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
>         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b

Yeah, this backtrace looks totally bogus. Unless there's some magic going on
with grabbing the get_online_cpus here?

Could you send your config. Maybe it has to do with some debug magic?

-- Steve

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 1442 bytes --]

On Tue, 21 Oct 2014, Steven Rostedt wrote:

> > Please have a look at the very first stacktrace in the dump, where lockdep 
> > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > the case at all.
> > 
> > What am I missing?
> > 
> 
> > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> 
> Yeah, this backtrace looks totally bogus. Unless there's some magic going on
> with grabbing the get_online_cpus here?
> 
> Could you send your config. Maybe it has to do with some debug magic?

.config attached.

-- 
Jiri Kosina
SUSE Labs

[-- Attachment #2: Type: APPLICATION/x-config, Size: 107878 bytes --]

Re: lockdep splat in CPU hotplug

[Dave Jones]

On Tue, Oct 21, 2014 at 01:09:04PM +0200, Jiri Kosina wrote:
 > Hi,
 > 
 > I am seeing the lockdep report below when resuming from suspend-to-disk 
 > with current Linus' tree (c2661b80609).
 > 
 > The reason for CCing Ingo and Peter is that I can't make any sense of one 
 > of the stacktraces lockdep is providing.
 > 
 > Please have a look at the very first stacktrace in the dump, where lockdep 
 > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
 > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
 > the case at all.

Could inlining be confusing the trace here ?

You can get from cpuidle_pause to cpuidle_uninstall_idle_handler -> synchronize_rcu
 -> synchronize_sched -> synchronize_sched_expedited which
does a try_get_online_cpus which will take the cpu_hotplug.lock

	Dave

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Tue, 21 Oct 2014, Dave Jones wrote:

>  > I am seeing the lockdep report below when resuming from suspend-to-disk 
>  > with current Linus' tree (c2661b80609).
>  > 
>  > The reason for CCing Ingo and Peter is that I can't make any sense of one 
>  > of the stacktraces lockdep is providing.
>  > 
>  > Please have a look at the very first stacktrace in the dump, where lockdep 
>  > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
>  > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
>  > the case at all.
> 
> Could inlining be confusing the trace here ?
> 
> You can get from cpuidle_pause to cpuidle_uninstall_idle_handler -> synchronize_rcu
>  -> synchronize_sched -> synchronize_sched_expedited which
> does a try_get_online_cpus which will take the cpu_hotplug.lock

Looks like this indeed is something that lockdep *should* report (*), 
although I would be suprised that stack unwinder would be so confused by 
this -- there is no way for synchronize_sched_expedited() to be inlined 
all the way to cpuidle_pause().

(*) there are multiple places where cpu_hotplug.lock -> cpuidle_lock lock 
    dependency is assumed. The patch that Dave pointed out adds 
    cpuidle_lock -> cpu_hotplug.lock dependency.

Still not clear whether this is what's happening here ... anyway, adding 
Paul to CC.

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Tue, Oct 21, 2014 at 05:21:21PM +0200, Jiri Kosina wrote:
> On Tue, 21 Oct 2014, Dave Jones wrote:
> 
> >  > I am seeing the lockdep report below when resuming from suspend-to-disk 
> >  > with current Linus' tree (c2661b80609).
> >  > 
> >  > The reason for CCing Ingo and Peter is that I can't make any sense of one 
> >  > of the stacktraces lockdep is providing.
> >  > 
> >  > Please have a look at the very first stacktrace in the dump, where lockdep 
> >  > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> >  > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> >  > the case at all.
> > 
> > Could inlining be confusing the trace here ?
> > 
> > You can get from cpuidle_pause to cpuidle_uninstall_idle_handler -> synchronize_rcu
> >  -> synchronize_sched -> synchronize_sched_expedited which
> > does a try_get_online_cpus which will take the cpu_hotplug.lock
> 
> Looks like this indeed is something that lockdep *should* report (*), 
> although I would be suprised that stack unwinder would be so confused by 
> this -- there is no way for synchronize_sched_expedited() to be inlined 
> all the way to cpuidle_pause().

I think that if synchronize_sched_expedited() was in fact called, it
had already returned by the time we hit this problem.  But I must confess
that I am not seeing how cpuidle_uninstall_idle_handler() gets to
synchronize_rcu().

> (*) there are multiple places where cpu_hotplug.lock -> cpuidle_lock lock 
>     dependency is assumed. The patch that Dave pointed out adds 
>     cpuidle_lock -> cpu_hotplug.lock dependency.
> 
> Still not clear whether this is what's happening here ... anyway, adding 
> Paul to CC.

Hmmm...

Both cpuidle_pause() and cpuidle_pause_and_lock() acquire cpuidle_lock,
and are at the top of both stacks.  Which was the original confusion.  ;-)

							Thanx, Paul

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Tue, 21 Oct 2014, Paul E. McKenney wrote:

> > Looks like this indeed is something that lockdep *should* report (*), 
> > although I would be suprised that stack unwinder would be so confused 
> > by this -- there is no way for synchronize_sched_expedited() to be 
> > inlined all the way to cpuidle_pause().
> 
> I think that if synchronize_sched_expedited() was in fact called, it
> had already returned by the time we hit this problem.  But I must confess
> that I am not seeing how cpuidle_uninstall_idle_handler() gets to
> synchronize_rcu().

Umm, it directly calls it? :-)

	void cpuidle_uninstall_idle_handler(void)
	{
		if (enabled_devices) {
			initialized = 0;
			wake_up_all_idle_cpus();
		}

		/*
		 * Make sure external observers (such as the scheduler)
		 * are done looking at pointed idle states.
		 */
		synchronize_rcu();
	}


> > (*) there are multiple places where cpu_hotplug.lock -> cpuidle_lock lock 
> >     dependency is assumed. The patch that Dave pointed out adds 
> >     cpuidle_lock -> cpu_hotplug.lock dependency.
> > 
> > Still not clear whether this is what's happening here ... anyway, adding 
> > Paul to CC.
> 
> Hmmm...
> 
> Both cpuidle_pause() and cpuidle_pause_and_lock() acquire cpuidle_lock,
> and are at the top of both stacks.  Which was the original confusion.  ;-)

Yup, they are, but lockdep is complaining about cpuidle_pause() acquiring 
cpu_hotplug.lock ...

Thanks,

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Tue, Oct 21, 2014 at 06:04:52PM +0200, Jiri Kosina wrote:
> On Tue, 21 Oct 2014, Paul E. McKenney wrote:
> 
> > > Looks like this indeed is something that lockdep *should* report (*), 
> > > although I would be suprised that stack unwinder would be so confused 
> > > by this -- there is no way for synchronize_sched_expedited() to be 
> > > inlined all the way to cpuidle_pause().
> > 
> > I think that if synchronize_sched_expedited() was in fact called, it
> > had already returned by the time we hit this problem.  But I must confess
> > that I am not seeing how cpuidle_uninstall_idle_handler() gets to
> > synchronize_rcu().
> 
> Umm, it directly calls it? :-)
> 
> 	void cpuidle_uninstall_idle_handler(void)
> 	{
> 		if (enabled_devices) {
> 			initialized = 0;
> 			wake_up_all_idle_cpus();
> 		}
> 
> 		/*
> 		 * Make sure external observers (such as the scheduler)
> 		 * are done looking at pointed idle states.
> 		 */
> 		synchronize_rcu();
> 	}

Ah, it would help if I did "git checkout linus/master" after updating,
wouldn't it now?

> > > (*) there are multiple places where cpu_hotplug.lock -> cpuidle_lock lock 
> > >     dependency is assumed. The patch that Dave pointed out adds 
> > >     cpuidle_lock -> cpu_hotplug.lock dependency.
> > > 
> > > Still not clear whether this is what's happening here ... anyway, adding 
> > > Paul to CC.
> > 
> > Hmmm...
> > 
> > Both cpuidle_pause() and cpuidle_pause_and_lock() acquire cpuidle_lock,
> > and are at the top of both stacks.  Which was the original confusion.  ;-)
> 
> Yup, they are, but lockdep is complaining about cpuidle_pause() acquiring 
> cpu_hotplug.lock ...

If it was attempting to acquire it via synchronize_sched_expedited(),
the attempt would fail and synchronize_sched_expedited() would fall
back to synchronize_sched()'s normal grace-period mechanism.  (Not to
synchronize_sched() itself, of course, as that would be infinite
recursion.)

So I believe that something else is going on here.

							Thanx, Paul

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Tue, 21 Oct 2014, Jiri Kosina wrote:

> Hi,
> 
> I am seeing the lockdep report below when resuming from suspend-to-disk 
> with current Linus' tree (c2661b80609).
> 
> The reason for CCing Ingo and Peter is that I can't make any sense of one 
> of the stacktraces lockdep is providing.
> 
> Please have a look at the very first stacktrace in the dump, where lockdep 
> is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> the case at all.
> 
> What am I missing?

Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle 
states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state 
info when choosing the "idlest" cpu") which depends on it makes the splat 
go away.

Just for the sake of testing the hypothesis, I did just the minimal change 
below on top of current Linus' tree, and it also makes the splat go away 
(of course it's totally incorrect thing to do by itself alone):

diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
index 125150d..d31e04c 100644
--- a/drivers/cpuidle/cpuidle.c
+++ b/drivers/cpuidle/cpuidle.c
@@ -225,12 +225,6 @@ void cpuidle_uninstall_idle_handler(void)
 		initialized = 0;
 		wake_up_all_idle_cpus();
 	}
-
-	/*
-	 * Make sure external observers (such as the scheduler)
-	 * are done looking at pointed idle states.
-	 */
-	synchronize_rcu();
 }
 
 /**

So indeed 442bf3aaf55a is guilty.

Paul was stating yesterday that it can't be the try_get_online_cpus() in 
synchronize_sched_expedited(), as it's doing only trylock. There are 
however more places where synchronize_sched_expedited() is acquiring 
cpu_hotplug.lock unconditionally by calling put_online_cpus(), so the race 
seems real.

Adding people involved in 442bf3aaf55a to CC.

Still, the lockdep stacktrace is bogus and didn't really help 
understanding this. Any idea why it's wrong?

>  ======================================================
>  [ INFO: possible circular locking dependency detected ]
>  3.18.0-rc1-00069-gc2661b8 #1 Not tainted
>  -------------------------------------------------------
>  do_s2disk/2367 is trying to acquire lock:
>   (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
>  
> but task is already holding lock:
>   (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
>  
> which lock already depends on the new lock.
> 
> the existing dependency chain (in reverse order) is:
> 
> -> #1 (cpu_hotplug.lock#2){+.+.+.}:
>         [<ffffffff81099fac>] lock_acquire+0xac/0x130
>         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
>         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
>         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
>         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
>         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
>         [<ffffffff810a1248>] hibernate+0x168/0x210
>         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
>         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
>         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
>         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
>         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
>         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
>         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
>  
> -> #0 (cpuidle_lock){+.+.+.}:
>         [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
>         [<ffffffff81099fac>] lock_acquire+0xac/0x130
>         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
>         [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
>         [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
>         [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
>         [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
>         [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
>         [<ffffffff810521ce>] cpu_notify+0x1e/0x40
>         [<ffffffff810524a8>] _cpu_up+0x148/0x160
>         [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
>         [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
>         [<ffffffff810a1248>] hibernate+0x168/0x210
>         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
>         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
>         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
>         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
>         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
>         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
>         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
>  
> other info that might help us debug this:
> 
>   Possible unsafe locking scenario:
> 
>         CPU0                    CPU1
>         ----                    ----
>    lock(cpu_hotplug.lock#2);
>                                 lock(cpuidle_lock);
>                                 lock(cpu_hotplug.lock#2);
>    lock(cpuidle_lock);
>  
>  *** DEADLOCK ***
> 
>  8 locks held by do_s2disk/2367:
>   #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff811a7443>] vfs_write+0x1b3/0x1f0
>   #1:  (&of->mutex){+.+.+.}, at: [<ffffffff8121e25b>] kernfs_fop_write+0xbb/0x170
>   #2:  (s_active#188){.+.+.+}, at: [<ffffffff8121e263>] kernfs_fop_write+0xc3/0x170
>   #3:  (pm_mutex){+.+.+.}, at: [<ffffffff810a112e>] hibernate+0x4e/0x210
>   #4:  (device_hotplug_lock){+.+.+.}, at: [<ffffffff813f1b52>] lock_device_hotplug+0x12/0x20
>   #5:  (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff815a7aef>] enable_nonboot_cpus+0x1f/0x1d0
>   #6:  (cpu_hotplug.lock){++++++}, at: [<ffffffff810522a0>] cpu_hotplug_begin+0x0/0x80
>   #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
>  
> stack backtrace:
>  CPU: 1 PID: 2367 Comm: do_s2disk Not tainted 3.18.0-rc1-00069-g4da0564 #1
>  Hardware name: LENOVO 7470BN2/7470BN2, BIOS 6DET38WW (2.02 ) 12/19/2008
>   ffffffff823e4330 ffff8800789e7a48 ffffffff815b6754 0000000000001a69
>   ffffffff823e4330 ffff8800789e7a98 ffffffff815b078b ffff8800741a5510
>   ffff8800789e7af8 ffff8800741a5ea8 5a024e919538010b ffff8800741a5ea8
>  Call Trace:
>   [<ffffffff815b6754>] dump_stack+0x4e/0x68
>   [<ffffffff815b078b>] print_circular_bug+0x203/0x214
>   [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
>   [<ffffffff8109766d>] ? trace_hardirqs_on_caller+0xfd/0x1c0
>   [<ffffffff81099fac>] lock_acquire+0xac/0x130
>   [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
>   [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
>   [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
>   [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
>   [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
>   [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
>   [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
>   [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
>   [<ffffffff810521ce>] cpu_notify+0x1e/0x40
>   [<ffffffff810524a8>] _cpu_up+0x148/0x160
>   [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
>   [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
>   [<ffffffff810a1248>] hibernate+0x168/0x210
>   [<ffffffff8109e9b4>] state_store+0xe4/0xf0
>   [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
>   [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
>   [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
>   [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
>   [<ffffffff815be87b>] ? sysret_check+0x1b/0x56
>   [<ffffffff811a7da4>] SyS_write+0x44/0xb0
>   [<ffffffff815be856>] system_call_fastpath+0x16/0x1b

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Wed, 22 Oct 2014, Jiri Kosina wrote:

> Still, the lockdep stacktrace is bogus and didn't really help 
> understanding this. Any idea why it's wrong?
> 
> >  ======================================================
> >  [ INFO: possible circular locking dependency detected ]
> >  3.18.0-rc1-00069-gc2661b8 #1 Not tainted
> >  -------------------------------------------------------
> >  do_s2disk/2367 is trying to acquire lock:
> >   (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >  
> > but task is already holding lock:
> >   (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
> >  
> > which lock already depends on the new lock.
> > 
> > the existing dependency chain (in reverse order) is:
> > 
> > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30

And the report is clearly bogus here. See:

$ addr2line -a ffffffff81491892 -e vmlinux-3.18.0-rc1-00068-gc2661b8
0xffffffff81491892
/dev/shm/jikos/BUILD/kernel-3.18.0_rc1_00068_gc2661b8/drivers/cpuidle/cpuidle.c:262

where the corresponding lines are

	259	void cpuidle_pause(void)
	260	{
	261		mutex_lock(&cpuidle_lock);
	262		cpuidle_uninstall_idle_handler();
	263		mutex_unlock(&cpuidle_lock);
	264	}

i.e. the RIP saved on stack clearly indicates that we are currently inside 
cpuidle_uninstall_idle_handler().

So it's clearly the case that part of the stack (which would probably 
point to synchronize_rcu_expedited()) is missing for some reason.

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Daniel Lezcano]

On 10/22/2014 11:53 AM, Jiri Kosina wrote:
> On Tue, 21 Oct 2014, Jiri Kosina wrote:
>
>> Hi,
>>
>> I am seeing the lockdep report below when resuming from suspend-to-disk
>> with current Linus' tree (c2661b80609).
>>
>> The reason for CCing Ingo and Peter is that I can't make any sense of one
>> of the stacktraces lockdep is providing.
>>
>> Please have a look at the very first stacktrace in the dump, where lockdep
>> is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems
>> to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not
>> the case at all.
>>
>> What am I missing?
>
> Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle
> states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state
> info when choosing the "idlest" cpu") which depends on it makes the splat
> go away.

Are you able to reproduce it by offlining the cpu and onlining it again ?

-- 
  <http://www.linaro.org/> Linaro.org │ Open source software for ARM SoCs

Follow Linaro:  <http://www.facebook.com/pages/Linaro> Facebook |
<http://twitter.com/#!/linaroorg> Twitter |
<http://www.linaro.org/linaro-blog/> Blog

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Wed, 22 Oct 2014, Daniel Lezcano wrote:

> > > I am seeing the lockdep report below when resuming from suspend-to-disk
> > > with current Linus' tree (c2661b80609).
> > > 
> > > The reason for CCing Ingo and Peter is that I can't make any sense of one
> > > of the stacktraces lockdep is providing.
> > > 
> > > Please have a look at the very first stacktrace in the dump, where lockdep
> > > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems
> > > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not
> > > the case at all.
> > > 
> > > What am I missing?
> > 
> > Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle
> > states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state
> > info when choosing the "idlest" cpu") which depends on it makes the splat
> > go away.
> 
> Are you able to reproduce it by offlining the cpu and onlining it again ?

No, that doesn't trigger it (please note that all the relevant stacktraces 
from lockdep are going through hibernation).

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Wed, Oct 22, 2014 at 11:53:49AM +0200, Jiri Kosina wrote:
> On Tue, 21 Oct 2014, Jiri Kosina wrote:
> 
> > Hi,
> > 
> > I am seeing the lockdep report below when resuming from suspend-to-disk 
> > with current Linus' tree (c2661b80609).
> > 
> > The reason for CCing Ingo and Peter is that I can't make any sense of one 
> > of the stacktraces lockdep is providing.
> > 
> > Please have a look at the very first stacktrace in the dump, where lockdep 
> > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > the case at all.
> > 
> > What am I missing?
> 
> Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle 
> states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state 
> info when choosing the "idlest" cpu") which depends on it makes the splat 
> go away.
> 
> Just for the sake of testing the hypothesis, I did just the minimal change 
> below on top of current Linus' tree, and it also makes the splat go away 
> (of course it's totally incorrect thing to do by itself alone):
> 
> diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
> index 125150d..d31e04c 100644
> --- a/drivers/cpuidle/cpuidle.c
> +++ b/drivers/cpuidle/cpuidle.c
> @@ -225,12 +225,6 @@ void cpuidle_uninstall_idle_handler(void)
>  		initialized = 0;
>  		wake_up_all_idle_cpus();
>  	}
> -
> -	/*
> -	 * Make sure external observers (such as the scheduler)
> -	 * are done looking at pointed idle states.
> -	 */
> -	synchronize_rcu();
>  }
> 
>  /**
> 
> So indeed 442bf3aaf55a is guilty.
> 
> Paul was stating yesterday that it can't be the try_get_online_cpus() in 
> synchronize_sched_expedited(), as it's doing only trylock. There are 
> however more places where synchronize_sched_expedited() is acquiring 
> cpu_hotplug.lock unconditionally by calling put_online_cpus(), so the race 
> seems real.

Gah!  So I only half-eliminated the deadlock between
synchronize_sched_expedited() and CPU hotplug.  Back to the drawing
board...

							Thanx, Paul

> Adding people involved in 442bf3aaf55a to CC.
> 
> Still, the lockdep stacktrace is bogus and didn't really help 
> understanding this. Any idea why it's wrong?
> 
> >  ======================================================
> >  [ INFO: possible circular locking dependency detected ]
> >  3.18.0-rc1-00069-gc2661b8 #1 Not tainted
> >  -------------------------------------------------------
> >  do_s2disk/2367 is trying to acquire lock:
> >   (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >  
> > but task is already holding lock:
> >   (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
> >  
> > which lock already depends on the new lock.
> > 
> > the existing dependency chain (in reverse order) is:
> > 
> > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> >  
> > -> #0 (cpuidle_lock){+.+.+.}:
> >         [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >         [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
> >         [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
> >         [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
> >         [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
> >         [<ffffffff810521ce>] cpu_notify+0x1e/0x40
> >         [<ffffffff810524a8>] _cpu_up+0x148/0x160
> >         [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
> >         [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> >  
> > other info that might help us debug this:
> > 
> >   Possible unsafe locking scenario:
> > 
> >         CPU0                    CPU1
> >         ----                    ----
> >    lock(cpu_hotplug.lock#2);
> >                                 lock(cpuidle_lock);
> >                                 lock(cpu_hotplug.lock#2);
> >    lock(cpuidle_lock);
> >  
> >  *** DEADLOCK ***
> > 
> >  8 locks held by do_s2disk/2367:
> >   #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff811a7443>] vfs_write+0x1b3/0x1f0
> >   #1:  (&of->mutex){+.+.+.}, at: [<ffffffff8121e25b>] kernfs_fop_write+0xbb/0x170
> >   #2:  (s_active#188){.+.+.+}, at: [<ffffffff8121e263>] kernfs_fop_write+0xc3/0x170
> >   #3:  (pm_mutex){+.+.+.}, at: [<ffffffff810a112e>] hibernate+0x4e/0x210
> >   #4:  (device_hotplug_lock){+.+.+.}, at: [<ffffffff813f1b52>] lock_device_hotplug+0x12/0x20
> >   #5:  (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff815a7aef>] enable_nonboot_cpus+0x1f/0x1d0
> >   #6:  (cpu_hotplug.lock){++++++}, at: [<ffffffff810522a0>] cpu_hotplug_begin+0x0/0x80
> >   #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
> >  
> > stack backtrace:
> >  CPU: 1 PID: 2367 Comm: do_s2disk Not tainted 3.18.0-rc1-00069-g4da0564 #1
> >  Hardware name: LENOVO 7470BN2/7470BN2, BIOS 6DET38WW (2.02 ) 12/19/2008
> >   ffffffff823e4330 ffff8800789e7a48 ffffffff815b6754 0000000000001a69
> >   ffffffff823e4330 ffff8800789e7a98 ffffffff815b078b ffff8800741a5510
> >   ffff8800789e7af8 ffff8800741a5ea8 5a024e919538010b ffff8800741a5ea8
> >  Call Trace:
> >   [<ffffffff815b6754>] dump_stack+0x4e/0x68
> >   [<ffffffff815b078b>] print_circular_bug+0x203/0x214
> >   [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
> >   [<ffffffff8109766d>] ? trace_hardirqs_on_caller+0xfd/0x1c0
> >   [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >   [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
> >   [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >   [<ffffffff814916c2>] ? cpuidle_pause_and_lock+0x12/0x20
> >   [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >   [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
> >   [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
> >   [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
> >   [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
> >   [<ffffffff810521ce>] cpu_notify+0x1e/0x40
> >   [<ffffffff810524a8>] _cpu_up+0x148/0x160
> >   [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
> >   [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
> >   [<ffffffff810a1248>] hibernate+0x168/0x210
> >   [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >   [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >   [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >   [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >   [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >   [<ffffffff815be87b>] ? sysret_check+0x1b/0x56
> >   [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >   [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> 
> -- 
> Jiri Kosina
> SUSE Labs
> 

Re: lockdep splat in CPU hotplug

[Daniel Lezcano]

On 10/22/2014 04:36 PM, Jiri Kosina wrote:
> On Wed, 22 Oct 2014, Daniel Lezcano wrote:
>
>>>> I am seeing the lockdep report below when resuming from suspend-to-disk
>>>> with current Linus' tree (c2661b80609).
>>>>
>>>> The reason for CCing Ingo and Peter is that I can't make any sense of one
>>>> of the stacktraces lockdep is providing.
>>>>
>>>> Please have a look at the very first stacktrace in the dump, where lockdep
>>>> is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems
>>>> to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not
>>>> the case at all.
>>>>
>>>> What am I missing?
>>>
>>> Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle
>>> states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state
>>> info when choosing the "idlest" cpu") which depends on it makes the splat
>>> go away.
>>
>> Are you able to reproduce it by offlining the cpu and onlining it again ?
>
> No, that doesn't trigger it (please note that all the relevant stacktraces
> from lockdep are going through hibernation).

Ok, thanks.


-- 
  <http://www.linaro.org/> Linaro.org │ Open source software for ARM SoCs

Follow Linaro:  <http://www.facebook.com/pages/Linaro> Facebook |
<http://twitter.com/#!/linaroorg> Twitter |
<http://www.linaro.org/linaro-blog/> Blog

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Wed, Oct 22, 2014 at 07:38:37AM -0700, Paul E. McKenney wrote:
> On Wed, Oct 22, 2014 at 11:53:49AM +0200, Jiri Kosina wrote:
> > On Tue, 21 Oct 2014, Jiri Kosina wrote:
> > 
> > > Hi,
> > > 
> > > I am seeing the lockdep report below when resuming from suspend-to-disk 
> > > with current Linus' tree (c2661b80609).
> > > 
> > > The reason for CCing Ingo and Peter is that I can't make any sense of one 
> > > of the stacktraces lockdep is providing.
> > > 
> > > Please have a look at the very first stacktrace in the dump, where lockdep 
> > > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > > the case at all.
> > > 
> > > What am I missing?
> > 
> > Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle 
> > states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state 
> > info when choosing the "idlest" cpu") which depends on it makes the splat 
> > go away.
> > 
> > Just for the sake of testing the hypothesis, I did just the minimal change 
> > below on top of current Linus' tree, and it also makes the splat go away 
> > (of course it's totally incorrect thing to do by itself alone):
> > 
> > diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
> > index 125150d..d31e04c 100644
> > --- a/drivers/cpuidle/cpuidle.c
> > +++ b/drivers/cpuidle/cpuidle.c
> > @@ -225,12 +225,6 @@ void cpuidle_uninstall_idle_handler(void)
> >  		initialized = 0;
> >  		wake_up_all_idle_cpus();
> >  	}
> > -
> > -	/*
> > -	 * Make sure external observers (such as the scheduler)
> > -	 * are done looking at pointed idle states.
> > -	 */
> > -	synchronize_rcu();
> >  }
> > 
> >  /**
> > 
> > So indeed 442bf3aaf55a is guilty.
> > 
> > Paul was stating yesterday that it can't be the try_get_online_cpus() in 
> > synchronize_sched_expedited(), as it's doing only trylock. There are 
> > however more places where synchronize_sched_expedited() is acquiring 
> > cpu_hotplug.lock unconditionally by calling put_online_cpus(), so the race 
> > seems real.
> 
> Gah!  So I only half-eliminated the deadlock between
> synchronize_sched_expedited() and CPU hotplug.  Back to the drawing
> board...

Please see below for an untested alleged fix.

							Thanx, Paul

------------------------------------------------------------------------

diff --git a/kernel/cpu.c b/kernel/cpu.c
index 356450f09c1f..8589b94b005a 100644
--- a/kernel/cpu.c
+++ b/kernel/cpu.c
@@ -64,6 +64,8 @@ static struct {
 	 * an ongoing cpu hotplug operation.
 	 */
 	int refcount;
+	/* And allows lockless put_online_cpus(). */
+	atomic_t puts_pending;
 
 #ifdef CONFIG_DEBUG_LOCK_ALLOC
 	struct lockdep_map dep_map;
@@ -113,7 +115,10 @@ void put_online_cpus(void)
 {
 	if (cpu_hotplug.active_writer == current)
 		return;
-	mutex_lock(&cpu_hotplug.lock);
+	if (!mutex_trylock(&cpu_hotplug.lock)) {
+		atomic_inc(&cpu_hotplug.puts_pending);
+		return;
+	}
 
 	if (WARN_ON(!cpu_hotplug.refcount))
 		cpu_hotplug.refcount++; /* try to fix things up */
@@ -155,6 +160,12 @@ void cpu_hotplug_begin(void)
 	cpuhp_lock_acquire();
 	for (;;) {
 		mutex_lock(&cpu_hotplug.lock);
+		if (atomic_read(&cpu_hotplug.puts_pending)) {
+			int delta;
+
+			delta = atomic_xchg(&cpu_hotplug.puts_pending, 0);
+			cpu_hotplug.refcount -= delta;
+		}
 		if (likely(!cpu_hotplug.refcount))
 			break;
 		__set_current_state(TASK_UNINTERRUPTIBLE);

Re: lockdep splat in CPU hotplug

[Steven Rostedt]

On Wed, 22 Oct 2014 11:53:49 +0200 (CEST)
Jiri Kosina <jkosina@suse.cz> wrote:


> Still, the lockdep stacktrace is bogus and didn't really help 
> understanding this. Any idea why it's wrong?

Could possibly be from a tail call?

> 
> >  ======================================================
> >  [ INFO: possible circular locking dependency detected ]
> >  3.18.0-rc1-00069-gc2661b8 #1 Not tainted
> >  -------------------------------------------------------
> >  do_s2disk/2367 is trying to acquire lock:
> >   (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >  
> > but task is already holding lock:
> >   (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
> >  
> > which lock already depends on the new lock.
> > 
> > the existing dependency chain (in reverse order) is:
> > 
> > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30

Where exactly does that address point to?

-- Steve

> >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> >  
> > -> #0 (cpuidle_lock){+.+.+.}:
> >         [<ffffffff81099433>] __lock_acquire+0x1a03/0x1e30
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> >         [<ffffffffc02e184c>] acpi_processor_hotplug+0x45/0x8a [processor]
> >         [<ffffffffc02df25a>] acpi_cpu_soft_notify+0xad/0xe3 [processor]
> >         [<ffffffff81071393>] notifier_call_chain+0x53/0xa0
> >         [<ffffffff810713e9>] __raw_notifier_call_chain+0x9/0x10
> >         [<ffffffff810521ce>] cpu_notify+0x1e/0x40
> >         [<ffffffff810524a8>] _cpu_up+0x148/0x160
> >         [<ffffffff815a7b99>] enable_nonboot_cpus+0xc9/0x1d0
> >         [<ffffffff810a0955>] hibernation_snapshot+0x265/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> >  

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Wed, 22 Oct 2014, Steven Rostedt wrote:

> > Still, the lockdep stacktrace is bogus and didn't really help 
> > understanding this. Any idea why it's wrong?
> 
> Could possibly be from a tail call?

Doesn't seem so:

(gdb) disassemble cpuidle_pause
Dump of assembler code for function cpuidle_pause:
   0xffffffff81491880 <+0>:     push   %rbp
   0xffffffff81491881 <+1>:     xor    %esi,%esi
   0xffffffff81491883 <+3>:     mov    $0xffffffff81a9eb20,%rdi
   0xffffffff8149188a <+10>:    mov    %rsp,%rbp
   0xffffffff8149188d <+13>:    callq  0xffffffff815b9ed0 <mutex_lock_nested>
   0xffffffff81491892 <+18>:    callq  0xffffffff81491680 <cpuidle_uninstall_idle_handler>
   0xffffffff81491897 <+23>:    mov    $0xffffffff81a9eb20,%rdi
   0xffffffff8149189e <+30>:    callq  0xffffffff815bbe60 <mutex_unlock>
   0xffffffff814918a3 <+35>:    pop    %rbp
   0xffffffff814918a4 <+36>:    retq   
End of assembler dump.
(gdb) disassemble cpuidle_uninstall_idle_handler
Dump of assembler code for function cpuidle_uninstall_idle_handler:
   0xffffffff81491680 <+0>:     mov    0x159da32(%rip),%eax        # 0xffffffff82a2f0b8 <enabled_devices>
   0xffffffff81491686 <+6>:     push   %rbp
   0xffffffff81491687 <+7>:     mov    %rsp,%rbp
   0xffffffff8149168a <+10>:    test   %eax,%eax
   0xffffffff8149168c <+12>:    je     0xffffffff8149169d <cpuidle_uninstall_idle_handler+29>
   0xffffffff8149168e <+14>:    movl   $0x0,0x64794c(%rip)        # 0xffffffff81ad8fe4 <initialized>
   0xffffffff81491698 <+24>:    callq  0xffffffff810cf9b0 <wake_up_all_idle_cpus>
   0xffffffff8149169d <+29>:    callq  0xffffffff810b47b0 <synchronize_sched>
   0xffffffff814916a2 <+34>:    pop    %rbp
   0xffffffff814916a3 <+35>:    retq   
End of assembler dump.
(gdb) disassemble synchronize_sched
Dump of assembler code for function synchronize_sched:
   0xffffffff810b47b0 <+0>:     push   %rbp
   0xffffffff810b47b1 <+1>:     xor    %edx,%edx
   0xffffffff810b47b3 <+3>:     mov    $0xad5,%esi
   0xffffffff810b47b8 <+8>:     mov    $0xffffffff817fad6d,%rdi
   0xffffffff810b47bf <+15>:    mov    %rsp,%rbp
   0xffffffff810b47c2 <+18>:    callq  0xffffffff81075900 <__might_sleep>
   0xffffffff810b47c7 <+23>:    incl   %gs:0xbaa0
   0xffffffff810b47cf <+31>:    mov    0x5587b2(%rip),%rdi        # 0xffffffff8160cf88 <cpu_online_mask>
   0xffffffff810b47d6 <+38>:    mov    $0x200,%esi
   0xffffffff810b47db <+43>:    callq  0xffffffff8130e710 <__bitmap_weight>
   0xffffffff810b47e0 <+48>:    decl   %gs:0xbaa0
   0xffffffff810b47e8 <+56>:    cmp    $0x1,%eax
   0xffffffff810b47eb <+59>:    jbe    0xffffffff810b4803 <synchronize_sched+83>
   0xffffffff810b47ed <+61>:    mov    0xbdf97d(%rip),%eax        # 0xffffffff81c94170 <rcu_expedited>
   0xffffffff810b47f3 <+67>:    test   %eax,%eax
   0xffffffff810b47f5 <+69>:    jne    0xffffffff810b4808 <synchronize_sched+88>
   0xffffffff810b47f7 <+71>:    mov    $0xffffffff810b3d80,%rdi
   0xffffffff810b47fe <+78>:    callq  0xffffffff810b1b00 <wait_rcu_gp>
   0xffffffff810b4803 <+83>:    pop    %rbp
   0xffffffff810b4804 <+84>:    retq   
   0xffffffff810b4805 <+85>:    nopl   (%rax)
   0xffffffff810b4808 <+88>:    callq  0xffffffff810b4820 <synchronize_sched_expedited>
   0xffffffff810b480d <+93>:    pop    %rbp
   0xffffffff810b480e <+94>:    xchg   %ax,%ax
   0xffffffff810b4810 <+96>:    retq   

> > >  ======================================================
> > >  [ INFO: possible circular locking dependency detected ]
> > >  3.18.0-rc1-00069-gc2661b8 #1 Not tainted
> > >  -------------------------------------------------------
> > >  do_s2disk/2367 is trying to acquire lock:
> > >   (cpuidle_lock){+.+.+.}, at: [<ffffffff814916c2>] cpuidle_pause_and_lock+0x12/0x20
> > >  
> > > but task is already holding lock:
> > >   (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810522ea>] cpu_hotplug_begin+0x4a/0x80
> > >  
> > > which lock already depends on the new lock.
> > > 
> > > the existing dependency chain (in reverse order) is:
> > > 
> > > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> > >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> > >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> > >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> 
> Where exactly does that address point to?

(gdb) disassemble cpuidle_pause
Dump of assembler code for function cpuidle_pause:
   0xffffffff81491880 <+0>:     push   %rbp
   0xffffffff81491881 <+1>:     xor    %esi,%esi
   0xffffffff81491883 <+3>:     mov    $0xffffffff81a9eb20,%rdi
   0xffffffff8149188a <+10>:    mov    %rsp,%rbp
   0xffffffff8149188d <+13>:    callq  0xffffffff815b9ed0 <mutex_lock_nested>
   0xffffffff81491892 <+18>:    callq  0xffffffff81491680 <cpuidle_uninstall_idle_handler>
   0xffffffff81491897 <+23>:    mov    $0xffffffff81a9eb20,%rdi
   0xffffffff8149189e <+30>:    callq  0xffffffff815bbe60 <mutex_unlock>
   0xffffffff814918a3 <+35>:    pop    %rbp
   0xffffffff814918a4 <+36>:    retq   

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Steven Rostedt]

On Tue, 21 Oct 2014 17:04:17 +0200 (CEST)
Jiri Kosina <jkosina@suse.cz> wrote:

> On Tue, 21 Oct 2014, Steven Rostedt wrote:
> 
> > > Please have a look at the very first stacktrace in the dump, where lockdep 
> > > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > > the case at all.
> > > 
> > > What am I missing?
> > > 
> > 
> > > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> > >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> > >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> > >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> > >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> > >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> > >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> > >         [<ffffffff810a1248>] hibernate+0x168/0x210
> > >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> > >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> > >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> > >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> > >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> > >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> > >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> > 
> > Yeah, this backtrace looks totally bogus. Unless there's some magic going on
> > with grabbing the get_online_cpus here?
> > 
> > Could you send your config. Maybe it has to do with some debug magic?
> 
> .config attached.
> 

Can you reproduce this all the time? I tried this config and pm-suspend
and pm-hibernate, and they both worked fine without a single lockdep
splat.

-- Steve

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Wed, 22 Oct 2014, Steven Rostedt wrote:

> > > > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> > > >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> > > >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> > > >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> > > >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> > > >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> > > >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> > > >         [<ffffffff810a1248>] hibernate+0x168/0x210
> > > >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> > > >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> > > >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> > > >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> > > >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> > > >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> > > >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b
> > > 
> > > Yeah, this backtrace looks totally bogus. Unless there's some magic going on
> > > with grabbing the get_online_cpus here?
> > > 
> > > Could you send your config. Maybe it has to do with some debug magic?
> > 
> > .config attached.
> > 
> 
> Can you reproduce this all the time? I tried this config and pm-suspend
> and pm-hibernate, and they both worked fine without a single lockdep
> splat.

Yes, it's 100% reliable for me.

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Borislav Petkov]

On Wed, Oct 22, 2014 at 08:40:21PM +0200, Jiri Kosina wrote:
> Yes, it's 100% reliable for me.

FWIW, I see that same splat here too, after a suspend-to-disk run:

...
[60077.352314] PM: Hibernation mode set to 'shutdown'
[60077.467384] PM: Syncing filesystems ... done.
[60077.479538] Freezing user space processes ... (elapsed 0.003 seconds) done.
[60077.490367] PM: Marking nosave pages: [mem 0x00000000-0x00000fff]
[60077.496504] PM: Marking nosave pages: [mem 0x0009e000-0x000fffff]
[60077.502622] PM: Marking nosave pages: [mem 0xba9b8000-0xbca4dfff]
[60077.508843] PM: Marking nosave pages: [mem 0xbca4f000-0xbcc54fff]
[60077.514962] PM: Marking nosave pages: [mem 0xbd083000-0xbd7f3fff]
[60077.521088] PM: Marking nosave pages: [mem 0xbd800000-0x100000fff]
[60077.527846] PM: Basic memory bitmaps created
[60077.532122] PM: Preallocating image memory... done (allocated 988772 pages)
[60078.526047] PM: Allocated 3955088 kbytes in 0.98 seconds (4035.80 MB/s)
[60078.532681] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[60078.545755] serial 00:06: disabled
[60078.546092] serial 00:06: System wakeup disabled by ACPI
[60080.973122] PM: freeze of devices complete after 2431.225 msecs
[60080.975511] PM: late freeze of devices complete after 2.206 msecs
[60080.980676] PM: noirq freeze of devices complete after 4.982 msecs
[60080.980877] Disabling non-boot CPUs ...
[60080.985500] smpboot: CPU 1 is now offline
[60080.990958] smpboot: CPU 2 is now offline
[60080.996340] smpboot: CPU 3 is now offline
[60081.003775] smpboot: CPU 4 is now offline
[60081.009236] smpboot: CPU 5 is now offline
[60081.017157] smpboot: CPU 6 is now offline
[60081.022512] smpboot: CPU 7 is now offline
[60081.025702] PM: Creating hibernation image:
[60082.243068] PM: Need to copy 1010324 pages
[60082.243219] PM: Normal pages needed: 1010324 + 1024, available pages: 3158476
[60081.301349] LVT offset 0 assigned for vector 0x400
[60081.302020] Enabling non-boot CPUs ...
[60081.302249] x86: Booting SMP configuration:
[60081.302378] smpboot: Booting Node 0 Processor 1 APIC 0x11
[60081.316879] 
[60081.316933] ======================================================
[60081.317119] [ INFO: possible circular locking dependency detected ]
[60081.317308] 3.18.0-rc1+ #1 Not tainted
[60081.317423] -------------------------------------------------------
[60081.317640] hib.sh/2232 is trying to acquire lock:
[60081.317786]  (cpuidle_lock){+.+.+.}, at: [<ffffffff814e3c67>] cpuidle_pause_and_lock+0x17/0x20
[60081.318070] 
[60081.318070] but task is already holding lock:
[60081.318247]  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810516c8>] cpu_hotplug_begin+0x58/0x90
[60081.318537] 
[60081.318537] which lock already depends on the new lock.
[60081.318537] 
[60081.318810] 
[60081.318810] the existing dependency chain (in reverse order) is:
[60081.319034] 
[60081.319034] -> #1 (cpu_hotplug.lock#2){+.+.+.}:
[60081.319206]        [<ffffffff8109f68d>] lock_acquire+0xdd/0x2d0
[60081.319391]        [<ffffffff81644d2e>] mutex_lock_nested+0x5e/0x410
[60081.319589]        [<ffffffff814e3e27>] cpuidle_pause+0x17/0x30
[60081.319774]        [<ffffffff813fda8e>] dpm_suspend_noirq+0x6e/0x640
[60081.319999]        [<ffffffff813fe6bf>] dpm_suspend_end+0x3f/0x90
[60081.320189]        [<ffffffff810a8f61>] hibernation_snapshot+0xe1/0x790
[60081.320394]        [<ffffffff810a9d5a>] hibernate+0x14a/0x1d0
[60081.320574]        [<ffffffff810a59c4>] state_store+0xe4/0xf0
[60081.320755]        [<ffffffff812f0f2f>] kobj_attr_store+0xf/0x20
[60081.320944]        [<ffffffff811fbce0>] sysfs_kf_write+0x50/0x70
[60081.321131]        [<ffffffff811fafe5>] kernfs_fop_write+0x105/0x190
[60081.321357]        [<ffffffff8118335d>] vfs_write+0xbd/0x1d0
[60081.321534]        [<ffffffff81183dc2>] SyS_write+0x52/0xc0
[60081.321709]        [<ffffffff816490d6>] system_call_fastpath+0x16/0x1b
[60081.321912] 
[60081.321912] -> #0 (cpuidle_lock){+.+.+.}:
[60081.322062]        [<ffffffff8109e9a4>] __lock_acquire+0x2034/0x2410
[60081.322259]        [<ffffffff8109f68d>] lock_acquire+0xdd/0x2d0
[60081.322472]        [<ffffffff81644d2e>] mutex_lock_nested+0x5e/0x410
[60081.322669]        [<ffffffff814e3c67>] cpuidle_pause_and_lock+0x17/0x20
[60081.322877]        [<ffffffff8138032c>] acpi_processor_hotplug+0x4f/0x8d
[60081.323085]        [<ffffffff8137e512>] acpi_cpu_soft_notify+0xb2/0xe8
[60081.323287]        [<ffffffff81076255>] notifier_call_chain+0x55/0xb0
[60081.323487]        [<ffffffff810762be>] __raw_notifier_call_chain+0xe/0x10
[60081.323727]        [<ffffffff810515a3>] cpu_notify+0x23/0x40
[60081.323904]        [<ffffffff810518a0>] _cpu_up+0x160/0x170
[60081.324079]        [<ffffffff8163cda3>] enable_nonboot_cpus+0xf3/0x4b0
[60081.324282]        [<ffffffff810a9165>] hibernation_snapshot+0x2e5/0x790
[60081.324489]        [<ffffffff810a9d5a>] hibernate+0x14a/0x1d0
[60081.324669]        [<ffffffff810a59c4>] state_store+0xe4/0xf0
[60081.324878]        [<ffffffff812f0f2f>] kobj_attr_store+0xf/0x20
[60081.325066]        [<ffffffff811fbce0>] sysfs_kf_write+0x50/0x70
[60081.325253]        [<ffffffff811fafe5>] kernfs_fop_write+0x105/0x190
[60081.325450]        [<ffffffff8118335d>] vfs_write+0xbd/0x1d0
[60081.325627]        [<ffffffff81183dc2>] SyS_write+0x52/0xc0
[60081.325801]        [<ffffffff816490d6>] system_call_fastpath+0x16/0x1b
[60081.326032] 
[60081.326032] other info that might help us debug this:
[60081.326032] 
[60081.326272]  Possible unsafe locking scenario:
[60081.326272] 
[60081.326451]        CPU0                    CPU1
[60081.326589]        ----                    ----
[60081.326726]   lock(cpu_hotplug.lock#2);
[60081.326861]                                lock(cpuidle_lock);
[60081.327048]                                lock(cpu_hotplug.lock#2);
[60081.327284]   lock(cpuidle_lock);
[60081.327398] 
[60081.327398]  *** DEADLOCK ***
[60081.327398] 
[60081.327577] 8 locks held by hib.sh/2232:
[60081.327697]  #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff8118342b>] vfs_write+0x18b/0x1d0
[60081.327974]  #1:  (&of->mutex){+.+.+.}, at: [<ffffffff811fafb7>] kernfs_fop_write+0xd7/0x190
[60081.328255]  #2:  (s_active#141){.+.+.+}, at: [<ffffffff811fafc0>] kernfs_fop_write+0xe0/0x190
[60081.328575]  #3:  (pm_mutex){+.+.+.}, at: [<ffffffff810a9c4a>] hibernate+0x3a/0x1d0
[60081.328835]  #4:  (device_hotplug_lock){+.+.+.}, at: [<ffffffff813eeae7>] lock_device_hotplug+0x17/0x20
[60081.329145]  #5:  (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff8163ccdf>] enable_nonboot_cpus+0x2f/0x4b0
[60081.329456]  #6:  (cpu_hotplug.lock){++++++}, at: [<ffffffff81051675>] cpu_hotplug_begin+0x5/0x90
[60081.329779]  #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<ffffffff810516c8>] cpu_hotplug_begin+0x58/0x90
[60081.330085] 
[60081.330085] stack backtrace:
[60081.330220] CPU: 0 PID: 2232 Comm: hib.sh Not tainted 3.18.0-rc1+ #1
[60081.330411] Hardware name: To be filled by O.E.M. To be filled by O.E.M./M5A97 EVO R2.0, BIOS 1503 01/16/2013
[60081.330706]  ffffffff8242aa50 ffff880381fcf9f8 ffffffff81640239 0000000000000000
[60081.330980]  ffffffff8247aee0 ffff880381fcfa48 ffffffff8163f3e8 0000000000000008
[60081.331224]  ffff880381fcfaa8 ffff880381fcfa48 ffff88038d7e9c28 ffff88038d7e9530
[60081.331468] Call Trace:
[60081.331548]  [<ffffffff81640239>] dump_stack+0x4f/0x7c
[60081.331705]  [<ffffffff8163f3e8>] print_circular_bug+0x2b8/0x2c9
[60081.331888]  [<ffffffff8109e9a4>] __lock_acquire+0x2034/0x2410
[60081.332066]  [<ffffffff811758c9>] ? kfree+0xc9/0x3a0
[60081.332247]  [<ffffffff8109f68d>] lock_acquire+0xdd/0x2d0
[60081.332412]  [<ffffffff814e3c67>] ? cpuidle_pause_and_lock+0x17/0x20
[60081.332606]  [<ffffffff814e3c67>] ? cpuidle_pause_and_lock+0x17/0x20
[60081.332799]  [<ffffffff81644d2e>] mutex_lock_nested+0x5e/0x410
[60081.332976]  [<ffffffff814e3c67>] ? cpuidle_pause_and_lock+0x17/0x20
[60081.333169]  [<ffffffff81354c1d>] ? acpi_evaluate_integer+0x34/0x52
[60081.333387]  [<ffffffff814e3c67>] ? cpuidle_pause_and_lock+0x17/0x20
[60081.333580]  [<ffffffff814e3c67>] cpuidle_pause_and_lock+0x17/0x20
[60081.333767]  [<ffffffff8138032c>] acpi_processor_hotplug+0x4f/0x8d
[60081.333955]  [<ffffffff8137e512>] acpi_cpu_soft_notify+0xb2/0xe8
[60081.334137]  [<ffffffff81076255>] notifier_call_chain+0x55/0xb0
[60081.334316]  [<ffffffff810762be>] __raw_notifier_call_chain+0xe/0x10
[60081.334537]  [<ffffffff810515a3>] cpu_notify+0x23/0x40
[60081.334694]  [<ffffffff810518a0>] _cpu_up+0x160/0x170
[60081.334849]  [<ffffffff8163cda3>] enable_nonboot_cpus+0xf3/0x4b0
[60081.335031]  [<ffffffff810a9165>] hibernation_snapshot+0x2e5/0x790
[60081.335218]  [<ffffffff810a9d5a>] hibernate+0x14a/0x1d0
[60081.335378]  [<ffffffff810a59c4>] state_store+0xe4/0xf0
[60081.335537]  [<ffffffff812f0f2f>] kobj_attr_store+0xf/0x20
[60081.335704]  [<ffffffff811fbce0>] sysfs_kf_write+0x50/0x70
[60081.335900]  [<ffffffff811fafe5>] kernfs_fop_write+0x105/0x190
[60081.336077]  [<ffffffff8118335d>] vfs_write+0xbd/0x1d0
[60081.336234]  [<ffffffff81183dc2>] SyS_write+0x52/0xc0
[60081.336389]  [<ffffffff816490d6>] system_call_fastpath+0x16/0x1b
[60081.336850] CPU1 is up
[60081.336970] smpboot: Booting Node 0 Processor 2 APIC 0x12
[60081.350648] CPU2 is up
[60081.350761] smpboot: Booting Node 0 Processor 3 APIC 0x13
[60081.364940] CPU3 is up
[60081.365047] smpboot: Booting Node 0 Processor 4 APIC 0x14
[60081.378750] CPU4 is up
[60081.378862] smpboot: Booting Node 0 Processor 5 APIC 0x15
[60081.393019] CPU5 is up
[60081.393125] smpboot: Booting Node 0 Processor 6 APIC 0x16
[60081.406864] CPU6 is up
[60081.406974] smpboot: Booting Node 0 Processor 7 APIC 0x17
[60081.421176] CPU7 is up
[60081.444773] PM: noirq restore of devices complete after 14.013 msecs
[60081.446047] PM: early restore of devices complete after 1.020 msecs
[60081.653282] rtc_cmos 00:03: System wakeup disabled by ACPI
[60081.653687] snd_hda_intel 0000:01:00.1: irq 49 for MSI/MSI-X
[60081.654224] serial 00:06: activated
[60081.655162] [drm] enabling PCIE gen 2 link speeds, disable with radeon.pcie_gen2=0
...

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Wed, Oct 22, 2014 at 09:54:33AM -0700, Paul E. McKenney wrote:
> On Wed, Oct 22, 2014 at 07:38:37AM -0700, Paul E. McKenney wrote:
> > On Wed, Oct 22, 2014 at 11:53:49AM +0200, Jiri Kosina wrote:
> > > On Tue, 21 Oct 2014, Jiri Kosina wrote:
> > > 
> > > > Hi,
> > > > 
> > > > I am seeing the lockdep report below when resuming from suspend-to-disk 
> > > > with current Linus' tree (c2661b80609).
> > > > 
> > > > The reason for CCing Ingo and Peter is that I can't make any sense of one 
> > > > of the stacktraces lockdep is providing.
> > > > 
> > > > Please have a look at the very first stacktrace in the dump, where lockdep 
> > > > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > > > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > > > the case at all.
> > > > 
> > > > What am I missing?
> > > 
> > > Okay, reverting 442bf3aaf55a ("sched: Let the scheduler see CPU idle 
> > > states") and followup 83a0a96a5f26 ("sched/fair: Leverage the idle state 
> > > info when choosing the "idlest" cpu") which depends on it makes the splat 
> > > go away.
> > > 
> > > Just for the sake of testing the hypothesis, I did just the minimal change 
> > > below on top of current Linus' tree, and it also makes the splat go away 
> > > (of course it's totally incorrect thing to do by itself alone):
> > > 
> > > diff --git a/drivers/cpuidle/cpuidle.c b/drivers/cpuidle/cpuidle.c
> > > index 125150d..d31e04c 100644
> > > --- a/drivers/cpuidle/cpuidle.c
> > > +++ b/drivers/cpuidle/cpuidle.c
> > > @@ -225,12 +225,6 @@ void cpuidle_uninstall_idle_handler(void)
> > >  		initialized = 0;
> > >  		wake_up_all_idle_cpus();
> > >  	}
> > > -
> > > -	/*
> > > -	 * Make sure external observers (such as the scheduler)
> > > -	 * are done looking at pointed idle states.
> > > -	 */
> > > -	synchronize_rcu();
> > >  }
> > > 
> > >  /**
> > > 
> > > So indeed 442bf3aaf55a is guilty.
> > > 
> > > Paul was stating yesterday that it can't be the try_get_online_cpus() in 
> > > synchronize_sched_expedited(), as it's doing only trylock. There are 
> > > however more places where synchronize_sched_expedited() is acquiring 
> > > cpu_hotplug.lock unconditionally by calling put_online_cpus(), so the race 
> > > seems real.
> > 
> > Gah!  So I only half-eliminated the deadlock between
> > synchronize_sched_expedited() and CPU hotplug.  Back to the drawing
> > board...
> 
> Please see below for an untested alleged fix.

And that patch had a lockdep issue.  The following replacement patch
passes light rcutorture testing, but your mileage may vary.

							Thanx, Paul

------------------------------------------------------------------------

rcu: More on deadlock between CPU hotplug and expedited grace periods

Commit dd56af42bd82 (rcu: Eliminate deadlock between CPU hotplug and
expedited grace periods) was incomplete.  Although it did eliminate
deadlocks involving synchronize_sched_expedited()'s acquisition of
cpu_hotplug.lock via get_online_cpus(), it did nothing about the similar
deadlock involving acquisition of this same lock via put_online_cpus().
This deadlock became apparent with testing involving hibernation.

This commit therefore changes put_online_cpus() acquisition of this lock
to be conditional, and increments a new cpu_hotplug.puts_pending field
in case of acquisition failure.  Then cpu_hotplug_begin() checks for this
new field being non-zero, and applies any changes to cpu_hotplug.refcount.

Reported by: Jiri Kosina <jkosina@suse.cz>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/kernel/cpu.c b/kernel/cpu.c
index 356450f09c1f..90a3d017b90c 100644
--- a/kernel/cpu.c
+++ b/kernel/cpu.c
@@ -64,6 +64,8 @@ static struct {
 	 * an ongoing cpu hotplug operation.
 	 */
 	int refcount;
+	/* And allows lockless put_online_cpus(). */
+	atomic_t puts_pending;
 
 #ifdef CONFIG_DEBUG_LOCK_ALLOC
 	struct lockdep_map dep_map;
@@ -113,7 +115,11 @@ void put_online_cpus(void)
 {
 	if (cpu_hotplug.active_writer == current)
 		return;
-	mutex_lock(&cpu_hotplug.lock);
+	if (!mutex_trylock(&cpu_hotplug.lock)) {
+		atomic_inc(&cpu_hotplug.puts_pending);
+		cpuhp_lock_release();
+		return;
+	}
 
 	if (WARN_ON(!cpu_hotplug.refcount))
 		cpu_hotplug.refcount++; /* try to fix things up */
@@ -155,6 +161,12 @@ void cpu_hotplug_begin(void)
 	cpuhp_lock_acquire();
 	for (;;) {
 		mutex_lock(&cpu_hotplug.lock);
+		if (atomic_read(&cpu_hotplug.puts_pending)) {
+			int delta;
+
+			delta = atomic_xchg(&cpu_hotplug.puts_pending, 0);
+			cpu_hotplug.refcount -= delta;
+		}
 		if (likely(!cpu_hotplug.refcount))
 			break;
 		__set_current_state(TASK_UNINTERRUPTIBLE);

Re: lockdep splat in CPU hotplug

[Jiri Kosina]

On Wed, 22 Oct 2014, Paul E. McKenney wrote:

> rcu: More on deadlock between CPU hotplug and expedited grace periods
> 
> Commit dd56af42bd82 (rcu: Eliminate deadlock between CPU hotplug and
> expedited grace periods) was incomplete.  Although it did eliminate
> deadlocks involving synchronize_sched_expedited()'s acquisition of
> cpu_hotplug.lock via get_online_cpus(), it did nothing about the similar
> deadlock involving acquisition of this same lock via put_online_cpus().
> This deadlock became apparent with testing involving hibernation.
> 
> This commit therefore changes put_online_cpus() acquisition of this lock
> to be conditional, and increments a new cpu_hotplug.puts_pending field
> in case of acquisition failure.  Then cpu_hotplug_begin() checks for this
> new field being non-zero, and applies any changes to cpu_hotplug.refcount.
> 

Yes, this works. FWIW, please feel free to add 

	Reported-and-tested-by: Jiri Kosina <jkosina@suse.cz>

once merging it.

Why lockdep produced such an incomplete stacktrace still remains 
unexplained.

Thanks,

-- 
Jiri Kosina
SUSE Labs

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Wed, Oct 22, 2014 at 10:57:25PM +0200, Jiri Kosina wrote:
> On Wed, 22 Oct 2014, Paul E. McKenney wrote:
> 
> > rcu: More on deadlock between CPU hotplug and expedited grace periods
> > 
> > Commit dd56af42bd82 (rcu: Eliminate deadlock between CPU hotplug and
> > expedited grace periods) was incomplete.  Although it did eliminate
> > deadlocks involving synchronize_sched_expedited()'s acquisition of
> > cpu_hotplug.lock via get_online_cpus(), it did nothing about the similar
> > deadlock involving acquisition of this same lock via put_online_cpus().
> > This deadlock became apparent with testing involving hibernation.
> > 
> > This commit therefore changes put_online_cpus() acquisition of this lock
> > to be conditional, and increments a new cpu_hotplug.puts_pending field
> > in case of acquisition failure.  Then cpu_hotplug_begin() checks for this
> > new field being non-zero, and applies any changes to cpu_hotplug.refcount.
> > 
> 
> Yes, this works. FWIW, please feel free to add 
> 
> 	Reported-and-tested-by: Jiri Kosina <jkosina@suse.cz>
> 
> once merging it.

Done, and thank you for both the bug report and the testing!

> Why lockdep produced such an incomplete stacktrace still remains 
> unexplained.

On that, I must defer to people more familiar with stack frames.

							Thanx, Paul

> Thanks,
> 
> -- 
> Jiri Kosina
> SUSE Labs
> 

Re: lockdep splat in CPU hotplug

[Borislav Petkov]

On Wed, Oct 22, 2014 at 02:09:43PM -0700, Paul E. McKenney wrote:
> > Yes, this works. FWIW, please feel free to add 
> > 
> > 	Reported-and-tested-by: Jiri Kosina <jkosina@suse.cz>
> > 
> > once merging it.
> 
> Done, and thank you for both the bug report and the testing!

Works here too.

Tested-by: Borislav Petkov <bp@suse.de>

Thanks.

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: lockdep splat in CPU hotplug

[Paul E. McKenney]

On Thu, Oct 23, 2014 at 10:11:25AM +0200, Borislav Petkov wrote:
> On Wed, Oct 22, 2014 at 02:09:43PM -0700, Paul E. McKenney wrote:
> > > Yes, this works. FWIW, please feel free to add 
> > > 
> > > 	Reported-and-tested-by: Jiri Kosina <jkosina@suse.cz>
> > > 
> > > once merging it.
> > 
> > Done, and thank you for both the bug report and the testing!
> 
> Works here too.
> 
> Tested-by: Borislav Petkov <bp@suse.de>

Thank you as well, recorded!

							Thanx, Paul

Re: lockdep splat in CPU hotplug

[Peter Zijlstra]

On Wed, Oct 22, 2014 at 11:53:49AM +0200, Jiri Kosina wrote:
> > The reason for CCing Ingo and Peter is that I can't make any sense of one 
> > of the stacktraces lockdep is providing.
> > 
> > Please have a look at the very first stacktrace in the dump, where lockdep 
> > is trying to explain where cpu_hotplug.lock#2 has been acquired. It seems 
> > to imply that cpuidle_pause() is taking cpu_hotplug.lock, but that's not 
> > the case at all.
> > 
> > What am I missing?

> Still, the lockdep stacktrace is bogus and didn't really help 
> understanding this. Any idea why it's wrong?

> > -> #1 (cpu_hotplug.lock#2){+.+.+.}:
> >         [<ffffffff81099fac>] lock_acquire+0xac/0x130
> >         [<ffffffff815b9f2c>] mutex_lock_nested+0x5c/0x3b0
> >         [<ffffffff81491892>] cpuidle_pause+0x12/0x30
> >         [<ffffffff81402314>] dpm_suspend_noirq+0x44/0x340
> >         [<ffffffff81402958>] dpm_suspend_end+0x38/0x80
> >         [<ffffffff810a07bd>] hibernation_snapshot+0xcd/0x370
> >         [<ffffffff810a1248>] hibernate+0x168/0x210
> >         [<ffffffff8109e9b4>] state_store+0xe4/0xf0
> >         [<ffffffff813003ef>] kobj_attr_store+0xf/0x20
> >         [<ffffffff8121e9a3>] sysfs_kf_write+0x43/0x60
> >         [<ffffffff8121e287>] kernfs_fop_write+0xe7/0x170
> >         [<ffffffff811a7342>] vfs_write+0xb2/0x1f0
> >         [<ffffffff811a7da4>] SyS_write+0x44/0xb0
> >         [<ffffffff815be856>] system_call_fastpath+0x16/0x1b

Right, so I've seen it more often, and I'm not sure I can explain
either.

Lockdep uses save_stack_trace() with trace->skip=3, typically if you
get ->skip wrong you'd not even see the lock_acquire, so that can't be
it.

The only thing I can come up with is that for some reason the
intermediate entries are !reliable, save_stack_trace() skips those for
CONFIG_FRAME_POINTER=y, see
arch/x86/kernel/stacktrace.c:__save_stack_address().