Re: next-20160517 - lockdep splat in pcie code
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 > -8<-8<-8<-8<-8<-8<-8<--8<-8<-- > > From: Mika Westerberg > 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: 0x8801be2aa8e8, .magic: , .owner: /-1, .owner_cpu: 0 > CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820 > 8801beb97be0 812cf42d > 8801be2aa8e8 8801beb97c00 8109ee58 8801be2aa8e8 > 8801be2aa8e8 8801beb97c30 8109efd9 8801be2aa8e8 > Call Trace: > [] dump_stack+0x4f/0x72 > [] spin_dump+0x78/0xc0 > [] do_raw_spin_lock+0xf9/0x150 > [] _raw_spin_lock_irq+0x20/0x30 > [] pm_runtime_no_callbacks+0x1e/0x40 > [] pcie_port_device_register+0x1fd/0x4e0 > [] pcie_portdrv_probe+0x38/0xa0 > [] local_pci_probe+0x45/0xa0 > [] ? pci_match_device+0xe0/0x110 > [] pci_device_probe+0xdb/0x130 > [] driver_probe_device+0x22c/0x440 > [] __driver_attach+0xd1/0xf0 > [] ? driver_probe_device+0x440/0x440 > [] bus_for_each_dev+0x64/0xa0 > [] driver_attach+0x1e/0x20 > [] bus_add_driver+0x1eb/0x280 > [] ? pcie_port_setup+0x7c/0x7c > [] driver_register+0x60/0xe0 > [] __pci_register_driver+0x60/0x70 > [] pcie_portdrv_init+0x63/0x75 > [] do_one_initcall+0xab/0x1c0 > [] kernel_init_freeable+0x153/0x1d9 > [] kernel_init+0xe/0x100 > [] ret_from_fork+0x22/0x40 > [] ? 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 > Suggested-by: Lukas Wunner > Signed-off-by: Mika Westerberg > --- > 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
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-1-gede618fce89c-dirty #276 > > > [1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 > > > 08/19/2015 > > > [1.806802] 0086 9200d6c8 88022ca23a90 > > > a83f99f3 > > > [1.806815] 880223727d40 88022ca23b00 > > > a80c1de1 > > > [1.806826] 0246 > > > 88022ca23ad8 > > > [1.806834] Call Trace: > > > [1.806845] [] dump_stack+0x68/0x95 > > > [1.806855] [] register_lock_class+0x541/0x550 > > > [1.806861] [] ? widen_string+0x3c/0xf0 > > > [1.806870] [] __lock_acquire+0x88/0x1260 > > > [1.806876] [] ? vsnprintf+0x36a/0x520 > > > [1.806886] [] ? kfree_const+0x21/0x30 > > > [1.806893] [] lock_acquire+0xb1/0x200 > > > [1.806904] [] ? pm_runtime_no_callbacks+0x1e/0x40 > > > [1.806915] [] _raw_spin_lock_irq+0x41/0x50 > > > [1.806923] [] ? pm_runtime_no_callbacks+0x1e/0x40 > > > [1.806932] [] pm_runtime_no_callbacks+0x1e/0x40 > > > [1.806942] [] pcie_port_device_register+0x226/0x560 > > > [1.806950] [] 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 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: 0x8801be2aa8e8, .magic: , .owner: /-1, .owner_cpu: 0 CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.6.0+ #820 8801beb97be0 812cf42d 8801be2aa8e8 8801beb97c00 8109ee58 8801be2aa8e8 8801be2aa8e8 8801beb97c30 8109efd9 8801be2aa8e8 Call Trace: [] dump_stack+0x4f/0x72 [] spin_dump+0x78/0xc0 [] do_raw_spin_lock+0xf9/0x150 [] _raw_spin_lock_irq+0x20/0x30 [] pm_runtime_no_callbacks+0x1e/0x40 [] pcie_port_device_register+0x1fd/0x4e0 [] pcie_portdrv_probe+0x38/0xa0 [] local_pci_probe+0x45/0xa0 [] ? pci_match_device+0xe0/0x110 [] pci_device_probe+0xdb/0x130 [] driver_probe_device+0x22c/0x440 [] __driver_attach+0xd1/0xf0 [] ? driver_probe_device+0x440/0x440 [] bus_for_each_dev+0x64/0xa0 [] driver_attach+0x1e/0x20 [] bus_add_driver+0x1eb/0x280 [] ? pcie_port_setup+0x7c/0x7c [] driver_register+0x60/0xe0 [] __pci_register_driver+0x60/0x70 [] pcie_portdrv_init+0x63/0x75 [] do_one_initcall+0xab/0x1c0 [] kernel_init_freeable+0x153/0x1d9 [] kernel_init+0xe/0x100 [] ret_from_fork+0x22/0x40 [] ? rest_init+0x90/0x90 Fix this by calling pm_runtime_no_callbacks() after device_register() just like other buses, like I2
Re: next-20160517 - lockdep splat in pcie code
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-1-gede618fce89c-dirty #276 > > [1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 > > 08/19/2015 > > [1.806802] 0086 9200d6c8 88022ca23a90 > > a83f99f3 > > [1.806815] 880223727d40 88022ca23b00 > > a80c1de1 > > [1.806826] 0246 > > 88022ca23ad8 > > [1.806834] Call Trace: > > [1.806845] [] dump_stack+0x68/0x95 > > [1.806855] [] register_lock_class+0x541/0x550 > > [1.806861] [] ? widen_string+0x3c/0xf0 > > [1.806870] [] __lock_acquire+0x88/0x1260 > > [1.806876] [] ? vsnprintf+0x36a/0x520 > > [1.806886] [] ? kfree_const+0x21/0x30 > > [1.806893] [] lock_acquire+0xb1/0x200 > > [1.806904] [] ? pm_runtime_no_callbacks+0x1e/0x40 > > [1.806915] [] _raw_spin_lock_irq+0x41/0x50 > > [1.806923] [] ? pm_runtime_no_callbacks+0x1e/0x40 > > [1.806932] [] pm_runtime_no_callbacks+0x1e/0x40 > > [1.806942] [] pcie_port_device_register+0x226/0x560 > > [1.806950] [] 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
[+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-1-gede618fce89c-dirty #276 > [1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 > 08/19/2015 > [1.806802] 0086 9200d6c8 88022ca23a90 > a83f99f3 > [1.806815] 880223727d40 88022ca23b00 > a80c1de1 > [1.806826] 0246 > 88022ca23ad8 > [1.806834] Call Trace: > [1.806845] [] dump_stack+0x68/0x95 > [1.806855] [] register_lock_class+0x541/0x550 > [1.806861] [] ? widen_string+0x3c/0xf0 > [1.806870] [] __lock_acquire+0x88/0x1260 > [1.806876] [] ? vsnprintf+0x36a/0x520 > [1.806886] [] ? kfree_const+0x21/0x30 > [1.806893] [] lock_acquire+0xb1/0x200 > [1.806904] [] ? pm_runtime_no_callbacks+0x1e/0x40 > [1.806915] [] _raw_spin_lock_irq+0x41/0x50 > [1.806923] [] ? pm_runtime_no_callbacks+0x1e/0x40 > [1.806932] [] pm_runtime_no_callbacks+0x1e/0x40 > [1.806942] [] pcie_port_device_register+0x226/0x560 > [1.806950] [] 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.
next-20160517 - lockdep splat in pcie code
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-1-gede618fce89c-dirty #276 [1.806794] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015 [1.806802] 0086 9200d6c8 88022ca23a90 a83f99f3 [1.806815] 880223727d40 88022ca23b00 a80c1de1 [1.806826] 0246 88022ca23ad8 [1.806834] Call Trace: [1.806845] [] dump_stack+0x68/0x95 [1.806855] [] register_lock_class+0x541/0x550 [1.806861] [] ? widen_string+0x3c/0xf0 [1.806870] [] __lock_acquire+0x88/0x1260 [1.806876] [] ? vsnprintf+0x36a/0x520 [1.806886] [] ? kfree_const+0x21/0x30 [1.806893] [] lock_acquire+0xb1/0x200 [1.806904] [] ? pm_runtime_no_callbacks+0x1e/0x40 [1.806915] [] _raw_spin_lock_irq+0x41/0x50 [1.806923] [] ? pm_runtime_no_callbacks+0x1e/0x40 [1.806932] [] pm_runtime_no_callbacks+0x1e/0x40 [1.806942] [] pcie_port_device_register+0x226/0x560 [1.806950] [] pcie_portdrv_probe+0x32/0xa0 [1.806959] [] pci_device_probe+0x90/0x100 [1.806969] [] driver_probe_device+0x1c0/0x310 [1.806977] [] __driver_attach+0x9f/0xb0 [1.806983] [] ? driver_probe_device+0x310/0x310 [1.806992] [] bus_for_each_dev+0x73/0xc0 [1.807000] [] driver_attach+0x1e/0x20 [1.807008] [] bus_add_driver+0x124/0x220 [1.807020] [] ? set_debug_rodata+0x12/0x12 [1.807029] [] driver_register+0x7d/0x100 [1.807039] [] ? pcie_port_setup+0x7c/0x7c [1.807045] [] __pci_register_driver+0x5d/0x60 [1.807054] [] pcie_portdrv_init+0x63/0x73 [1.807064] [] do_one_initcall+0x50/0x1b0 [1.807072] [] ? set_debug_rodata+0x12/0x12 [1.807080] [] kernel_init_freeable+0x1b3/0x240 [1.807089] [] kernel_init+0xe/0x100 [1.807095] [] ret_from_fork+0x1f/0x40 [1.807102] [] ? rest_init+0x140/0x140 [1.819159] efifb: probing for efifb pgpjtc5YGVRKU.pgp Description: PGP signature