next-20160517 - lockdep splat in pcie code

next-20160517 - lockdep splat in pcie code

[Valdis Kletnieks]

[-- Attachment #1: Type: text/plain, Size: 2871 bytes --]

Seen during boot on next-20160517. This apparently sneaked into the tree
sometime after -0502 (probably after -0512 but I can't prove it at the moment)

[    1.806765] INFO: trying to register non-static key.
[    1.806772] the code is fine but needs lockdep annotation.
[    1.806777] turning off the locking correctness validator.
[    1.806786] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.6.0-next-20160517-00001-gede618fce89c-dirty #276
[    1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015
[    1.806802]  0000000000000086 000000009200d6c8 ffff88022ca23a90 ffffffffa83f99f3
[    1.806815]  0000000000000000 ffff880223727d40 ffff88022ca23b00 ffffffffa80c1de1
[    1.806826]  0000000000000246 0000000000000000 ffffffffffffffff ffff88022ca23ad8
[    1.806834] Call Trace:
[    1.806845]  [<ffffffffa83f99f3>] dump_stack+0x68/0x95
[    1.806855]  [<ffffffffa80c1de1>] register_lock_class+0x541/0x550
[    1.806861]  [<ffffffffa8404b6c>] ? widen_string+0x3c/0xf0
[    1.806870]  [<ffffffffa80c4108>] __lock_acquire+0x88/0x1260
[    1.806876]  [<ffffffffa840751a>] ? vsnprintf+0x36a/0x520
[    1.806886]  [<ffffffffa81bdfc1>] ? kfree_const+0x21/0x30
[    1.806893]  [<ffffffffa80c56d1>] lock_acquire+0xb1/0x200
[    1.806904]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
[    1.806915]  [<ffffffffa8a07831>] _raw_spin_lock_irq+0x41/0x50
[    1.806923]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
[    1.806932]  [<ffffffffa852874e>] pm_runtime_no_callbacks+0x1e/0x40
[    1.806942]  [<ffffffffa844fe36>] pcie_port_device_register+0x226/0x560
[    1.806950]  [<ffffffffa8450542>] pcie_portdrv_probe+0x32/0xa0
[    1.806959]  [<ffffffffa84423e0>] pci_device_probe+0x90/0x100
[    1.806969]  [<ffffffffa851e390>] driver_probe_device+0x1c0/0x310
[    1.806977]  [<ffffffffa851e57f>] __driver_attach+0x9f/0xb0
[    1.806983]  [<ffffffffa851e4e0>] ? driver_probe_device+0x310/0x310
[    1.806992]  [<ffffffffa851bf53>] bus_for_each_dev+0x73/0xc0
[    1.807000]  [<ffffffffa851dafe>] driver_attach+0x1e/0x20
[    1.807008]  [<ffffffffa851d614>] bus_add_driver+0x124/0x220
[    1.807020]  [<ffffffffa91d88a9>] ? set_debug_rodata+0x12/0x12
[    1.807029]  [<ffffffffa851eaed>] driver_register+0x7d/0x100
[    1.807039]  [<ffffffffa92105f2>] ? pcie_port_setup+0x7c/0x7c
[    1.807045]  [<ffffffffa84417dd>] __pci_register_driver+0x5d/0x60
[    1.807054]  [<ffffffffa9210655>] pcie_portdrv_init+0x63/0x73
[    1.807064]  [<ffffffffa8000410>] do_one_initcall+0x50/0x1b0
[    1.807072]  [<ffffffffa91d88a9>] ? set_debug_rodata+0x12/0x12
[    1.807080]  [<ffffffffa91d921d>] kernel_init_freeable+0x1b3/0x240
[    1.807089]  [<ffffffffa89fe1ae>] kernel_init+0xe/0x100
[    1.807095]  [<ffffffffa8a0867f>] ret_from_fork+0x1f/0x40
[    1.807102]  [<ffffffffa89fe1a0>] ? rest_init+0x140/0x140
[    1.819159] efifb: probing for efifb


[-- Attachment #2: Type: application/pgp-signature, Size: 848 bytes --]

Re: next-20160517 - lockdep splat in pcie code

[Bjorn Helgaas]

[+cc Lukas, Mika]

On Tue, May 17, 2016 at 02:36:02PM -0400, Valdis Kletnieks wrote:
> Seen during boot on next-20160517. This apparently sneaked into the tree
> sometime after -0502 (probably after -0512 but I can't prove it at the moment)
> 
> [    1.806765] INFO: trying to register non-static key.
> [    1.806772] the code is fine but needs lockdep annotation.
> [    1.806777] turning off the locking correctness validator.
> [    1.806786] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.6.0-next-20160517-00001-gede618fce89c-dirty #276
> [    1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015
> [    1.806802]  0000000000000086 000000009200d6c8 ffff88022ca23a90 ffffffffa83f99f3
> [    1.806815]  0000000000000000 ffff880223727d40 ffff88022ca23b00 ffffffffa80c1de1
> [    1.806826]  0000000000000246 0000000000000000 ffffffffffffffff ffff88022ca23ad8
> [    1.806834] Call Trace:
> [    1.806845]  [<ffffffffa83f99f3>] dump_stack+0x68/0x95
> [    1.806855]  [<ffffffffa80c1de1>] register_lock_class+0x541/0x550
> [    1.806861]  [<ffffffffa8404b6c>] ? widen_string+0x3c/0xf0
> [    1.806870]  [<ffffffffa80c4108>] __lock_acquire+0x88/0x1260
> [    1.806876]  [<ffffffffa840751a>] ? vsnprintf+0x36a/0x520
> [    1.806886]  [<ffffffffa81bdfc1>] ? kfree_const+0x21/0x30
> [    1.806893]  [<ffffffffa80c56d1>] lock_acquire+0xb1/0x200
> [    1.806904]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> [    1.806915]  [<ffffffffa8a07831>] _raw_spin_lock_irq+0x41/0x50
> [    1.806923]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> [    1.806932]  [<ffffffffa852874e>] pm_runtime_no_callbacks+0x1e/0x40
> [    1.806942]  [<ffffffffa844fe36>] pcie_port_device_register+0x226/0x560
> [    1.806950]  [<ffffffffa8450542>] pcie_portdrv_probe+0x32/0xa0

Probably introduced by this:

http://git.kernel.org/cgit/linux/kernel/git/helgaas/pci.git/commit/?id=0195d2813547

I dropped the pci/pm branch for now.

Re: next-20160517 - lockdep splat in pcie code

[Lukas Wunner]

Hi,

On Tue, May 17, 2016 at 02:37:42PM -0500, Bjorn Helgaas wrote:
> [+cc Lukas, Mika]
> On Tue, May 17, 2016 at 02:36:02PM -0400, Valdis Kletnieks wrote:
> > Seen during boot on next-20160517. This apparently sneaked into the tree
> > sometime after -0502 (probably after -0512 but I can't prove it at the moment)
> > 
> > [    1.806765] INFO: trying to register non-static key.
> > [    1.806772] the code is fine but needs lockdep annotation.
> > [    1.806777] turning off the locking correctness validator.
> > [    1.806786] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.6.0-next-20160517-00001-gede618fce89c-dirty #276
> > [    1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015
> > [    1.806802]  0000000000000086 000000009200d6c8 ffff88022ca23a90 ffffffffa83f99f3
> > [    1.806815]  0000000000000000 ffff880223727d40 ffff88022ca23b00 ffffffffa80c1de1
> > [    1.806826]  0000000000000246 0000000000000000 ffffffffffffffff ffff88022ca23ad8
> > [    1.806834] Call Trace:
> > [    1.806845]  [<ffffffffa83f99f3>] dump_stack+0x68/0x95
> > [    1.806855]  [<ffffffffa80c1de1>] register_lock_class+0x541/0x550
> > [    1.806861]  [<ffffffffa8404b6c>] ? widen_string+0x3c/0xf0
> > [    1.806870]  [<ffffffffa80c4108>] __lock_acquire+0x88/0x1260
> > [    1.806876]  [<ffffffffa840751a>] ? vsnprintf+0x36a/0x520
> > [    1.806886]  [<ffffffffa81bdfc1>] ? kfree_const+0x21/0x30
> > [    1.806893]  [<ffffffffa80c56d1>] lock_acquire+0xb1/0x200
> > [    1.806904]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> > [    1.806915]  [<ffffffffa8a07831>] _raw_spin_lock_irq+0x41/0x50
> > [    1.806923]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> > [    1.806932]  [<ffffffffa852874e>] pm_runtime_no_callbacks+0x1e/0x40
> > [    1.806942]  [<ffffffffa844fe36>] pcie_port_device_register+0x226/0x560
> > [    1.806950]  [<ffffffffa8450542>] pcie_portdrv_probe+0x32/0xa0
> 
> Probably introduced by this:
> 
> http://git.kernel.org/cgit/linux/kernel/git/helgaas/pci.git/commit/?id=0195d2813547
> 
> I dropped the pci/pm branch for now.

Okay this is caused by pm_runtime_no_callbacks() acquiring dev->power.lock
before spin_lock_init() has been called. The spinlock is initialized in
device_pm_init_common(), which is called from device_pm_init(), which is
called from device_initialize(), which is the first half of
device_register().

The solution is to either
(1) move the call to pm_runtime_no_callbacks() after the call to
    device_register() or
(2) replace the call to device_register() with calls to device_initialize()
    and device_add(), then move the call to pm_runtime_no_callbacks()
    in-between.

I can barely keep my eyes open right now, I'll look at this with a fresh
pair of eyeballs tomorrow and cook up, test and submit a fixup patch
unless Mika or someone else has already done it until then.

Thank you Valdis for spotting this.

Best regards,

Lukas

Re: next-20160517 - lockdep splat in pcie code

[Mika Westerberg]

On Wed, May 18, 2016 at 12:12:48AM +0200, Lukas Wunner wrote:
> Hi,
> 
> On Tue, May 17, 2016 at 02:37:42PM -0500, Bjorn Helgaas wrote:
> > [+cc Lukas, Mika]
> > On Tue, May 17, 2016 at 02:36:02PM -0400, Valdis Kletnieks wrote:
> > > Seen during boot on next-20160517. This apparently sneaked into the tree
> > > sometime after -0502 (probably after -0512 but I can't prove it at the moment)
> > > 
> > > [    1.806765] INFO: trying to register non-static key.
> > > [    1.806772] the code is fine but needs lockdep annotation.
> > > [    1.806777] turning off the locking correctness validator.
> > > [    1.806786] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.6.0-next-20160517-00001-gede618fce89c-dirty #276
> > > [    1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015
> > > [    1.806802]  0000000000000086 000000009200d6c8 ffff88022ca23a90 ffffffffa83f99f3
> > > [    1.806815]  0000000000000000 ffff880223727d40 ffff88022ca23b00 ffffffffa80c1de1
> > > [    1.806826]  0000000000000246 0000000000000000 ffffffffffffffff ffff88022ca23ad8
> > > [    1.806834] Call Trace:
> > > [    1.806845]  [<ffffffffa83f99f3>] dump_stack+0x68/0x95
> > > [    1.806855]  [<ffffffffa80c1de1>] register_lock_class+0x541/0x550
> > > [    1.806861]  [<ffffffffa8404b6c>] ? widen_string+0x3c/0xf0
> > > [    1.806870]  [<ffffffffa80c4108>] __lock_acquire+0x88/0x1260
> > > [    1.806876]  [<ffffffffa840751a>] ? vsnprintf+0x36a/0x520
> > > [    1.806886]  [<ffffffffa81bdfc1>] ? kfree_const+0x21/0x30
> > > [    1.806893]  [<ffffffffa80c56d1>] lock_acquire+0xb1/0x200
> > > [    1.806904]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> > > [    1.806915]  [<ffffffffa8a07831>] _raw_spin_lock_irq+0x41/0x50
> > > [    1.806923]  [<ffffffffa852874e>] ? pm_runtime_no_callbacks+0x1e/0x40
> > > [    1.806932]  [<ffffffffa852874e>] pm_runtime_no_callbacks+0x1e/0x40
> > > [    1.806942]  [<ffffffffa844fe36>] pcie_port_device_register+0x226/0x560
> > > [    1.806950]  [<ffffffffa8450542>] pcie_portdrv_probe+0x32/0xa0
> > 
> > Probably introduced by this:
> > 
> > http://git.kernel.org/cgit/linux/kernel/git/helgaas/pci.git/commit/?id=0195d2813547
> > 
> > I dropped the pci/pm branch for now.

For some reason I did not have lock debugging enabled in my .config so I
have not seen this in my testing. Sorry about that.

> Okay this is caused by pm_runtime_no_callbacks() acquiring dev->power.lock
> before spin_lock_init() has been called. The spinlock is initialized in
> device_pm_init_common(), which is called from device_pm_init(), which is
> called from device_initialize(), which is the first half of
> device_register().
> 
> The solution is to either
> (1) move the call to pm_runtime_no_callbacks() after the call to
>     device_register() or

This sounds like the right thing to do.

> (2) replace the call to device_register() with calls to device_initialize()
>     and device_add(), then move the call to pm_runtime_no_callbacks()
>     in-between.
> 
> I can barely keep my eyes open right now, I'll look at this with a fresh
> pair of eyeballs tomorrow and cook up, test and submit a fixup patch
> unless Mika or someone else has already done it until then.

The patch following your suggestion is below. Thanks for looking at the
issue.

Valdis,

Can you check if the patch fixes the issue?

-----8<-----8<-----8<-----8<-----8<-----8<-----8<------8<-----8<------

From: Mika Westerberg <mika.westerberg@linux.intel.com>
Date: Wed, 18 May 2016 11:35:09 +0300
Subject: [PATCH] PCI: pcie: Call pm_runtime_no_callbacks() after device is registered

Commit 0195d2813547 ("PCI: Add runtime PM support for PCIe ports") added
call to pm_runtime_no_callbacks() for each port service device to prevent
them exposing unnecessary runtime PM sysfs files. However, that function
tries to acquire dev->power.lock which is not yet initialized.

This triggers following splat:

 BUG: spinlock bad magic on CPU#0, swapper/0/1
  lock: 0xffff8801be2aa8e8, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
 CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820
  0000000000000000 ffff8801beb97be0 ffffffff812cf42d 0000000000000000
  ffff8801be2aa8e8 ffff8801beb97c00 ffffffff8109ee58 ffff8801be2aa8e8
  ffff8801be2aa8e8 ffff8801beb97c30 ffffffff8109efd9 ffff8801be2aa8e8
 Call Trace:
  [<ffffffff812cf42d>] dump_stack+0x4f/0x72
  [<ffffffff8109ee58>] spin_dump+0x78/0xc0
  [<ffffffff8109efd9>] do_raw_spin_lock+0xf9/0x150
  [<ffffffff81674e10>] _raw_spin_lock_irq+0x20/0x30
  [<ffffffff813d738e>] pm_runtime_no_callbacks+0x1e/0x40
  [<ffffffff81322cad>] pcie_port_device_register+0x1fd/0x4e0
  [<ffffffff813232f8>] pcie_portdrv_probe+0x38/0xa0
  [<ffffffff81314fb5>] local_pci_probe+0x45/0xa0
  [<ffffffff81315fe0>] ? pci_match_device+0xe0/0x110
  [<ffffffff813163ab>] pci_device_probe+0xdb/0x130
  [<ffffffff813ccefc>] driver_probe_device+0x22c/0x440
  [<ffffffff813cd1e1>] __driver_attach+0xd1/0xf0
  [<ffffffff813cd110>] ? driver_probe_device+0x440/0x440
  [<ffffffff813caab4>] bus_for_each_dev+0x64/0xa0
  [<ffffffff813cc60e>] driver_attach+0x1e/0x20
  [<ffffffff813cc0cb>] bus_add_driver+0x1eb/0x280
  [<ffffffff81d36cdc>] ? pcie_port_setup+0x7c/0x7c
  [<ffffffff813cdb90>] driver_register+0x60/0xe0
  [<ffffffff813148e0>] __pci_register_driver+0x60/0x70
  [<ffffffff81d36d3f>] pcie_portdrv_init+0x63/0x75
  [<ffffffff810003db>] do_one_initcall+0xab/0x1c0
  [<ffffffff81cff083>] kernel_init_freeable+0x153/0x1d9
  [<ffffffff8166dfce>] kernel_init+0xe/0x100
  [<ffffffff81675612>] ret_from_fork+0x22/0x40
  [<ffffffff8166dfc0>] ? rest_init+0x90/0x90

Fix this by calling pm_runtime_no_callbacks() after device_register() just
like other buses, like I2C is doing already.

Reported-by: Valdis Kletnieks <Valdis.Kletnieks@vt.edu>
Suggested-by: Lukas Wunner <lukas@wunner.de>
Signed-off-by: Mika Westerberg <mika.westerberg@linux.intel.com>
---
 drivers/pci/pcie/portdrv_core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/drivers/pci/pcie/portdrv_core.c b/drivers/pci/pcie/portdrv_core.c
index 65b1a624826b..97927dfbbf5f 100644
--- a/drivers/pci/pcie/portdrv_core.c
+++ b/drivers/pci/pcie/portdrv_core.c
@@ -344,7 +344,6 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
 		     get_descriptor_id(pci_pcie_type(pdev), service));
 	device->parent = &pdev->dev;
 	device_enable_async_suspend(device);
-	pm_runtime_no_callbacks(device);
 
 	retval = device_register(device);
 	if (retval) {
@@ -352,6 +351,8 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
 		return retval;
 	}
 
+	pm_runtime_no_callbacks(device);
+
 	return 0;
 }
 
-- 
2.8.1

Re: next-20160517 - lockdep splat in pcie code

[Valdis.Kletnieks]

On Wed, 18 May 2016 11:54:59 +0300, Mika Westerberg said:

> Can you check if the patch fixes the issue?

Tested, no complaints at boot, and everything seems to be working.

Feel free to add this to the patch and send it upstream:

Tested-By: Valdis Kletnieks <valdis.kletnieks@vt.edu>

> -----8<-----8<-----8<-----8<-----8<-----8<-----8<------8<-----8<------
>
> From: Mika Westerberg <mika.westerberg@linux.intel.com>
> Date: Wed, 18 May 2016 11:35:09 +0300
> Subject: [PATCH] PCI: pcie: Call pm_runtime_no_callbacks() after device is registered
>
> Commit 0195d2813547 ("PCI: Add runtime PM support for PCIe ports") added
> call to pm_runtime_no_callbacks() for each port service device to prevent
> them exposing unnecessary runtime PM sysfs files. However, that function
> tries to acquire dev->power.lock which is not yet initialized.
>
> This triggers following splat:
>
>  BUG: spinlock bad magic on CPU#0, swapper/0/1
>   lock: 0xffff8801be2aa8e8, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
>  CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820
>   0000000000000000 ffff8801beb97be0 ffffffff812cf42d 0000000000000000
>   ffff8801be2aa8e8 ffff8801beb97c00 ffffffff8109ee58 ffff8801be2aa8e8
>   ffff8801be2aa8e8 ffff8801beb97c30 ffffffff8109efd9 ffff8801be2aa8e8
>  Call Trace:
>   [<ffffffff812cf42d>] dump_stack+0x4f/0x72
>   [<ffffffff8109ee58>] spin_dump+0x78/0xc0
>   [<ffffffff8109efd9>] do_raw_spin_lock+0xf9/0x150
>   [<ffffffff81674e10>] _raw_spin_lock_irq+0x20/0x30
>   [<ffffffff813d738e>] pm_runtime_no_callbacks+0x1e/0x40
>   [<ffffffff81322cad>] pcie_port_device_register+0x1fd/0x4e0
>   [<ffffffff813232f8>] pcie_portdrv_probe+0x38/0xa0
>   [<ffffffff81314fb5>] local_pci_probe+0x45/0xa0
>   [<ffffffff81315fe0>] ? pci_match_device+0xe0/0x110
>   [<ffffffff813163ab>] pci_device_probe+0xdb/0x130
>   [<ffffffff813ccefc>] driver_probe_device+0x22c/0x440
>   [<ffffffff813cd1e1>] __driver_attach+0xd1/0xf0
>   [<ffffffff813cd110>] ? driver_probe_device+0x440/0x440
>   [<ffffffff813caab4>] bus_for_each_dev+0x64/0xa0
>   [<ffffffff813cc60e>] driver_attach+0x1e/0x20
>   [<ffffffff813cc0cb>] bus_add_driver+0x1eb/0x280
>   [<ffffffff81d36cdc>] ? pcie_port_setup+0x7c/0x7c
>   [<ffffffff813cdb90>] driver_register+0x60/0xe0
>   [<ffffffff813148e0>] __pci_register_driver+0x60/0x70
>   [<ffffffff81d36d3f>] pcie_portdrv_init+0x63/0x75
>   [<ffffffff810003db>] do_one_initcall+0xab/0x1c0
>   [<ffffffff81cff083>] kernel_init_freeable+0x153/0x1d9
>   [<ffffffff8166dfce>] kernel_init+0xe/0x100
>   [<ffffffff81675612>] ret_from_fork+0x22/0x40
>   [<ffffffff8166dfc0>] ? rest_init+0x90/0x90
>
> Fix this by calling pm_runtime_no_callbacks() after device_register() just
> like other buses, like I2C is doing already.
>
> Reported-by: Valdis Kletnieks <Valdis.Kletnieks@vt.edu>
> Suggested-by: Lukas Wunner <lukas@wunner.de>
> Signed-off-by: Mika Westerberg <mika.westerberg@linux.intel.com>
> ---
>  drivers/pci/pcie/portdrv_core.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
>
> diff --git a/drivers/pci/pcie/portdrv_core.c b/drivers/pci/pcie/portdrv_core.c
> index 65b1a624826b..97927dfbbf5f 100644
> --- a/drivers/pci/pcie/portdrv_core.c
> +++ b/drivers/pci/pcie/portdrv_core.c
> @@ -344,7 +344,6 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
>  		     get_descriptor_id(pci_pcie_type(pdev), service));
>  	device->parent = &pdev->dev;
>  	device_enable_async_suspend(device);
> -	pm_runtime_no_callbacks(device);
>  
>  	retval = device_register(device);
>  	if (retval) {
> @@ -352,6 +351,8 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
>  		return retval;
>  	}
>  
> +	pm_runtime_no_callbacks(device);
> +
>  	return 0;
>  }
>  
> -- 
> 2.8.1
>
>

[PATCH] PCI: pcie: Call pm_runtime_no_callbacks() after device is registered

[Mika Westerberg]

Commit 0195d2813547 ("PCI: Add runtime PM support for PCIe ports") added
call to pm_runtime_no_callbacks() for each port service device to prevent
them exposing unnecessary runtime PM sysfs files. However, that function
tries to acquire dev->power.lock which is not yet initialized.

This triggers following splat:

 BUG: spinlock bad magic on CPU#0, swapper/0/1
  lock: 0xffff8801be2aa8e8, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
 CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820
  0000000000000000 ffff8801beb97be0 ffffffff812cf42d 0000000000000000
  ffff8801be2aa8e8 ffff8801beb97c00 ffffffff8109ee58 ffff8801be2aa8e8
  ffff8801be2aa8e8 ffff8801beb97c30 ffffffff8109efd9 ffff8801be2aa8e8
 Call Trace:
  [<ffffffff812cf42d>] dump_stack+0x4f/0x72
  [<ffffffff8109ee58>] spin_dump+0x78/0xc0
  [<ffffffff8109efd9>] do_raw_spin_lock+0xf9/0x150
  [<ffffffff81674e10>] _raw_spin_lock_irq+0x20/0x30
  [<ffffffff813d738e>] pm_runtime_no_callbacks+0x1e/0x40
  [<ffffffff81322cad>] pcie_port_device_register+0x1fd/0x4e0
  [<ffffffff813232f8>] pcie_portdrv_probe+0x38/0xa0
  [<ffffffff81314fb5>] local_pci_probe+0x45/0xa0
  [<ffffffff81315fe0>] ? pci_match_device+0xe0/0x110
  [<ffffffff813163ab>] pci_device_probe+0xdb/0x130
  [<ffffffff813ccefc>] driver_probe_device+0x22c/0x440
  [<ffffffff813cd1e1>] __driver_attach+0xd1/0xf0
  [<ffffffff813cd110>] ? driver_probe_device+0x440/0x440
  [<ffffffff813caab4>] bus_for_each_dev+0x64/0xa0
  [<ffffffff813cc60e>] driver_attach+0x1e/0x20
  [<ffffffff813cc0cb>] bus_add_driver+0x1eb/0x280
  [<ffffffff81d36cdc>] ? pcie_port_setup+0x7c/0x7c
  [<ffffffff813cdb90>] driver_register+0x60/0xe0
  [<ffffffff813148e0>] __pci_register_driver+0x60/0x70
  [<ffffffff81d36d3f>] pcie_portdrv_init+0x63/0x75
  [<ffffffff810003db>] do_one_initcall+0xab/0x1c0
  [<ffffffff81cff083>] kernel_init_freeable+0x153/0x1d9
  [<ffffffff8166dfce>] kernel_init+0xe/0x100
  [<ffffffff81675612>] ret_from_fork+0x22/0x40
  [<ffffffff8166dfc0>] ? rest_init+0x90/0x90

Fix this by calling pm_runtime_no_callbacks() after device_register() just
like other buses, like I2C is doing already.

Reported-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
Tested-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
Suggested-by: Lukas Wunner <lukas@wunner.de>
Signed-off-by: Mika Westerberg <mika.westerberg@linux.intel.com>
---
 drivers/pci/pcie/portdrv_core.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/drivers/pci/pcie/portdrv_core.c b/drivers/pci/pcie/portdrv_core.c
index 65b1a624826b..97927dfbbf5f 100644
--- a/drivers/pci/pcie/portdrv_core.c
+++ b/drivers/pci/pcie/portdrv_core.c
@@ -344,7 +344,6 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
 		     get_descriptor_id(pci_pcie_type(pdev), service));
 	device->parent = &pdev->dev;
 	device_enable_async_suspend(device);
-	pm_runtime_no_callbacks(device);
 
 	retval = device_register(device);
 	if (retval) {
@@ -352,6 +351,8 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
 		return retval;
 	}
 
+	pm_runtime_no_callbacks(device);
+
 	return 0;
 }
 
-- 
2.8.1

Re: [PATCH] PCI: pcie: Call pm_runtime_no_callbacks() after device is registered

[Bjorn Helgaas]

On Mon, May 23, 2016 at 11:11:55AM +0300, Mika Westerberg wrote:
> Commit 0195d2813547 ("PCI: Add runtime PM support for PCIe ports") added
> call to pm_runtime_no_callbacks() for each port service device to prevent
> them exposing unnecessary runtime PM sysfs files. However, that function
> tries to acquire dev->power.lock which is not yet initialized.
> 
> This triggers following splat:
> 
>  BUG: spinlock bad magic on CPU#0, swapper/0/1
>   lock: 0xffff8801be2aa8e8, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
>  CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820
>   0000000000000000 ffff8801beb97be0 ffffffff812cf42d 0000000000000000
>   ffff8801be2aa8e8 ffff8801beb97c00 ffffffff8109ee58 ffff8801be2aa8e8
>   ffff8801be2aa8e8 ffff8801beb97c30 ffffffff8109efd9 ffff8801be2aa8e8
>  Call Trace:
>   [<ffffffff812cf42d>] dump_stack+0x4f/0x72
>   [<ffffffff8109ee58>] spin_dump+0x78/0xc0
>   [<ffffffff8109efd9>] do_raw_spin_lock+0xf9/0x150
>   [<ffffffff81674e10>] _raw_spin_lock_irq+0x20/0x30
>   [<ffffffff813d738e>] pm_runtime_no_callbacks+0x1e/0x40
>   [<ffffffff81322cad>] pcie_port_device_register+0x1fd/0x4e0
>   [<ffffffff813232f8>] pcie_portdrv_probe+0x38/0xa0
>   [<ffffffff81314fb5>] local_pci_probe+0x45/0xa0
>   [<ffffffff81315fe0>] ? pci_match_device+0xe0/0x110
>   [<ffffffff813163ab>] pci_device_probe+0xdb/0x130
>   [<ffffffff813ccefc>] driver_probe_device+0x22c/0x440
>   [<ffffffff813cd1e1>] __driver_attach+0xd1/0xf0
>   [<ffffffff813cd110>] ? driver_probe_device+0x440/0x440
>   [<ffffffff813caab4>] bus_for_each_dev+0x64/0xa0
>   [<ffffffff813cc60e>] driver_attach+0x1e/0x20
>   [<ffffffff813cc0cb>] bus_add_driver+0x1eb/0x280
>   [<ffffffff81d36cdc>] ? pcie_port_setup+0x7c/0x7c
>   [<ffffffff813cdb90>] driver_register+0x60/0xe0
>   [<ffffffff813148e0>] __pci_register_driver+0x60/0x70
>   [<ffffffff81d36d3f>] pcie_portdrv_init+0x63/0x75
>   [<ffffffff810003db>] do_one_initcall+0xab/0x1c0
>   [<ffffffff81cff083>] kernel_init_freeable+0x153/0x1d9
>   [<ffffffff8166dfce>] kernel_init+0xe/0x100
>   [<ffffffff81675612>] ret_from_fork+0x22/0x40
>   [<ffffffff8166dfc0>] ? rest_init+0x90/0x90
> 
> Fix this by calling pm_runtime_no_callbacks() after device_register() just
> like other buses, like I2C is doing already.
> 
> Reported-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> Tested-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> Suggested-by: Lukas Wunner <lukas@wunner.de>
> Signed-off-by: Mika Westerberg <mika.westerberg@linux.intel.com>

I think this is a bugfix for "PCI: Add runtime PM support for PCIe
ports", so I folded this into that patch since it hasn't been merged
yet.  Is that the right place for it?

> ---
>  drivers/pci/pcie/portdrv_core.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/pci/pcie/portdrv_core.c b/drivers/pci/pcie/portdrv_core.c
> index 65b1a624826b..97927dfbbf5f 100644
> --- a/drivers/pci/pcie/portdrv_core.c
> +++ b/drivers/pci/pcie/portdrv_core.c
> @@ -344,7 +344,6 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
>  		     get_descriptor_id(pci_pcie_type(pdev), service));
>  	device->parent = &pdev->dev;
>  	device_enable_async_suspend(device);
> -	pm_runtime_no_callbacks(device);
>  
>  	retval = device_register(device);
>  	if (retval) {
> @@ -352,6 +351,8 @@ static int pcie_device_init(struct pci_dev *pdev, int service, int irq)
>  		return retval;
>  	}
>  
> +	pm_runtime_no_callbacks(device);
> +
>  	return 0;
>  }
>  
> -- 
> 2.8.1
> 

Re: [PATCH] PCI: pcie: Call pm_runtime_no_callbacks() after device is registered

[Mika Westerberg]

On Mon, May 23, 2016 at 02:55:00PM -0500, Bjorn Helgaas wrote:
> On Mon, May 23, 2016 at 11:11:55AM +0300, Mika Westerberg wrote:
> > Commit 0195d2813547 ("PCI: Add runtime PM support for PCIe ports") added
> > call to pm_runtime_no_callbacks() for each port service device to prevent
> > them exposing unnecessary runtime PM sysfs files. However, that function
> > tries to acquire dev->power.lock which is not yet initialized.
> > 
> > This triggers following splat:
> > 
> >  BUG: spinlock bad magic on CPU#0, swapper/0/1
> >   lock: 0xffff8801be2aa8e8, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
> >  CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820
> >   0000000000000000 ffff8801beb97be0 ffffffff812cf42d 0000000000000000
> >   ffff8801be2aa8e8 ffff8801beb97c00 ffffffff8109ee58 ffff8801be2aa8e8
> >   ffff8801be2aa8e8 ffff8801beb97c30 ffffffff8109efd9 ffff8801be2aa8e8
> >  Call Trace:
> >   [<ffffffff812cf42d>] dump_stack+0x4f/0x72
> >   [<ffffffff8109ee58>] spin_dump+0x78/0xc0
> >   [<ffffffff8109efd9>] do_raw_spin_lock+0xf9/0x150
> >   [<ffffffff81674e10>] _raw_spin_lock_irq+0x20/0x30
> >   [<ffffffff813d738e>] pm_runtime_no_callbacks+0x1e/0x40
> >   [<ffffffff81322cad>] pcie_port_device_register+0x1fd/0x4e0
> >   [<ffffffff813232f8>] pcie_portdrv_probe+0x38/0xa0
> >   [<ffffffff81314fb5>] local_pci_probe+0x45/0xa0
> >   [<ffffffff81315fe0>] ? pci_match_device+0xe0/0x110
> >   [<ffffffff813163ab>] pci_device_probe+0xdb/0x130
> >   [<ffffffff813ccefc>] driver_probe_device+0x22c/0x440
> >   [<ffffffff813cd1e1>] __driver_attach+0xd1/0xf0
> >   [<ffffffff813cd110>] ? driver_probe_device+0x440/0x440
> >   [<ffffffff813caab4>] bus_for_each_dev+0x64/0xa0
> >   [<ffffffff813cc60e>] driver_attach+0x1e/0x20
> >   [<ffffffff813cc0cb>] bus_add_driver+0x1eb/0x280
> >   [<ffffffff81d36cdc>] ? pcie_port_setup+0x7c/0x7c
> >   [<ffffffff813cdb90>] driver_register+0x60/0xe0
> >   [<ffffffff813148e0>] __pci_register_driver+0x60/0x70
> >   [<ffffffff81d36d3f>] pcie_portdrv_init+0x63/0x75
> >   [<ffffffff810003db>] do_one_initcall+0xab/0x1c0
> >   [<ffffffff81cff083>] kernel_init_freeable+0x153/0x1d9
> >   [<ffffffff8166dfce>] kernel_init+0xe/0x100
> >   [<ffffffff81675612>] ret_from_fork+0x22/0x40
> >   [<ffffffff8166dfc0>] ? rest_init+0x90/0x90
> > 
> > Fix this by calling pm_runtime_no_callbacks() after device_register() just
> > like other buses, like I2C is doing already.
> > 
> > Reported-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> > Tested-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> > Suggested-by: Lukas Wunner <lukas@wunner.de>
> > Signed-off-by: Mika Westerberg <mika.westerberg@linux.intel.com>
> 
> I think this is a bugfix for "PCI: Add runtime PM support for PCIe
> ports", so I folded this into that patch since it hasn't been merged
> yet.  Is that the right place for it?

Yes, that's right. Thanks!