From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758975Ab3BLUqp (ORCPT ); Tue, 12 Feb 2013 15:46:45 -0500 Received: from hydra.sisk.pl ([212.160.235.94]:37607 "EHLO hydra.sisk.pl" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1758679Ab3BLUqm (ORCPT ); Tue, 12 Feb 2013 15:46:42 -0500 From: "Rafael J. Wysocki" To: Daniel J Blueman , Tejun Heo Cc: Bjorn Helgaas , Linux Kernel , Linux PCI , Yijing Wang Subject: Re: [3.8-rc7] PCI hotplug wakeup oops Date: Tue, 12 Feb 2013 21:53:08 +0100 Message-ID: <2437657.3PbvdpUqxu@vostro.rjw.lan> User-Agent: KMail/4.9.5 (Linux/3.8.0-rc7; KDE/4.9.5; x86_64; ; ) In-Reply-To: References: <1843565.7Y1sC8j6FG@vostro.rjw.lan> MIME-Version: 1.0 Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="utf-8" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tuesday, February 12, 2013 10:18:57 AM Daniel J Blueman wrote: > On 12 February 2013 03:49, Rafael J. Wysocki wrote: > > On Monday, February 11, 2013 08:27:49 PM Rafael J. Wysocki wrote: > >> On Monday, February 11, 2013 12:01:37 PM Bjorn Helgaas wrote: > >> > [+cc Rafael] > >> > > >> > On Mon, Feb 11, 2013 at 10:08 AM, Daniel J Blueman wrote: > >> > > On 11 February 2013 21:03, Daniel J Blueman wrote: > >> > >> With 3.8-rc7, when unplugging the Thunderbolt ethernet adapter (bus 0a > >> > >> [1]) on a Macbook Pro 10,1, we see the PCIe port correctly released: > >> > >> > >> > >> pciehp 0000:06:03.0:pcie24: Card not present on Slot(3) > >> > >> tg3 0000:0a:00.0: tg3_abort_hw timed out, TX_MODE_ENABLE will not > >> > >> clear MAC_TX_MODE=ffffffff > >> > >> tg3 0000:0a:00.0 eth0: No firmware running > >> > >> tg3 0000:0a:00.0 eth0: Link is down > >> > >> [sched_delayed] sched: RT throttling activated > >> > >> pcieport 0000:00:01.1: System wakeup enabled by ACPI > >> > >> pciehp 0000:09:00.0:pcie24: unloading service driver pciehp > >> > >> pci_bus 0000:0a: busn_res: [bus 0a] is released > >> > >> pci_bus 0000:09: busn_res: [bus 09-0a] is released > >> > >> > >> > >> After some activity later (eg I can reproduce this by switching to a > >> > >> text console and back), often we'll see an oops: > >> > >> > >> > >> Unable to handle kernel paging request at 0000000000001070 > >> > >> pci_pme_list_scan+0x3d/0xe0 > >> > >> Call Trace: > >> > >> process_one_work+0x193 > >> > >> ? process_one_work+0x131 > >> > >> ? pci_pme_wakeup+0x60 > >> > >> worker_thread+0x15d > >> > >> > >> > >> (gdb) list *(pci_pme_list_scan+0x3d) > >> > >> 0xffffffff8123f6dd is in pci_pme_list_scan (drivers/pci/pci.c:1556). > >> > >> 1551 /* > >> > >> 1552 * If bridge is in low power state, the > >> > >> 1553 * configuration space of subordinate devices > >> > >> 1554 * may be not accessible > >> > >> 1555 */ > >> > >> 1556 if (bridge && bridge->current_state != PCI_D0) > >> > >> 1557 continue; > >> > >> 1558 pci_pme_wakeup(pme_dev->dev, NULL); > >> > >> 1559 } else { > >> > >> 1560 list_del(&pme_dev->list); > >> > >> > >> > >> Since a panic in vsnprintf happens after the oops (hence I can't catch > >> > >> it with EFI pstore), it is almost certainly significant heap > >> > >> corruption; this would explain why pme_dev became null (the load has > >> > >> been ordered ahead). > >> > >> > >> > >> I'll see what I can find out with memory poisoning and list debugging. > >> > > > >> > > Enabling a bunch of related debugging, we see pme_dev is non-null and: > >> > > > >> > > BUG: Unable to handle NULL pointer dereference at > >> > > pci_bus_read_config_word+0x6c > >> > > PGD 26314c067 PUD 2633f9067 PMD 0 > >> > > Oops: 0000 [#1] SMP > >> > > pci_check_pme_status+0x4f > >> > > pci_pme_wakeup+0x21 > >> > > pci_pme_list_scan+0xd5 > >> > > process_one_work+0x1ca > >> > > ? process_one_work+0x160 > >> > > ? pci_pme_wakeup+0x60 > >> > > worker_thread+0x14e > >> > > > >> > > Anyway, it looks like the device being unplugged wasn't removed from > >> > > pci_pme_list as pci_pme_active(dev, false) wasn't called. > >> > > > >> > > From a quick review, I wasn't able to find the right place in the > >> > > call-chain which I only see releases the child busses and PCIe port > >> > > drivers. Anyone? > >> > > >> > It looks like drivers *add* devices to pci_pme_list when they use > >> > pci_enable_wake() or pci_wake_from_d3(). But many drivers never > >> > remove their devices, and I don't see any place where the core does it > >> > either. My guess is we need to remove it in pci_stop_dev() (we > >> > already do pcie_aspm_exit_link_state() there) or somewhere similar. > >> > >> Yes, we should call pci_pme_active(dev, false) somewhere in there I think. > >> It's fine to call that even if PME was not "active" before. > > > > Daniel, I wonder if the patch below helps? > > I had tried with the pci_pme_active call inside the is_added condition > (it'll always hold here); it resolves the issue, though it introduces > a new lockdep warning [1]. > > All said, I don't see any other way except for a patch to abstract the > list entry removal to avoid the unnecessary reads and writes (as it is > called for four devices here), though I don't see how that would alter > the locking behaviour and why we didn't see this lockdep warning > before. > > What do you think? This looks fishy, but I wonder if Tejun has any ideas. Tejun, can you please have a look at the call trace below? It looks like the workqueues code is involved heavily. Thanks, Rafael > --- [1] > > kworker/0:0/4 is trying to acquire lock: > (name){++++.+}, at: [] flush_workqueue+0x0/0x4d0 > > but task is already holding lock: > (name){++++.+}, at: [] process_one_work+0x160/0x4e0 > > other info that might help us debug this: > Possible unsafe locking scenario: > > CPU0 > ---- > lock(name); > lock(name); > > *** DEADLOCK *** > > May be due to missing lock nesting notation > > 4 locks held by kworker/0:0/4: > #0: (name){++++.+}, at: [] process_one_work+0x160/0x4e0 > #1: ((&info->work)#2){+.+.+.}, at: [] > process_one_work+0x160/0x4e0 > #2: (&__lockdep_no_validate__){......}, at: [] > device_release_driver+0x21/0x40 > #3: (&__lockdep_no_validate__){......}, at: [] > device_release_driver+0x21/0x40 > > stack backtrace: > Pid: 4, comm: kworker/0:0 Not tainted 3.8.0-rc7-ninja+ #21 > Call Trace: > [] validate_chain.isra.33+0xda3/0x1240 > [] ? print_shortest_lock_dependencies+0x1c0/0x1c0 > [] ? mark_lock+0x215/0x5d0 > [] ? debug_check_no_locks_freed+0x8f/0x160 > [] __lock_acquire+0x3ac/0xb30 > [] ? trace_hardirqs_on+0xd/0x10 > [] ? lockdep_init_map+0x9c/0x4d0 > [] lock_acquire+0x5a/0x70 > [] ? flush_workqueue_prep_cwqs+0x200/0x200 > [] flush_workqueue+0xe8/0x4d0 > [] ? flush_workqueue_prep_cwqs+0x200/0x200 > [] drain_workqueue+0x68/0x1f0 > [] destroy_workqueue+0x13/0x160 > [] pciehp_release_ctrl+0x3a/0x90 > [] pciehp_remove+0x25/0x30 > [] pcie_port_remove_service+0x52/0x70 > [] __device_release_driver+0x77/0xe0 > [] device_release_driver+0x29/0x40 > [] bus_remove_device+0xf1/0x140 > [] device_del+0x127/0x1c0 > [] ? resume_iter+0x40/0x40 > [] device_unregister+0x11/0x20 > [] remove_iter+0x35/0x40 > [] device_for_each_child+0x36/0x70 > [] pcie_port_device_remove+0x21/0x40 > [] pcie_portdrv_remove+0x28/0x50 > [] pci_device_remove+0x41/0xc0 > [] __device_release_driver+0x77/0xe0 > [] device_release_driver+0x29/0x40 > [] bus_remove_device+0xf1/0x140 > [] device_del+0x127/0x1c0 > [] device_unregister+0x11/0x20 > [] pci_stop_bus_device+0xb4/0xc0 > [] pci_stop_bus_device+0x35/0xc0 > [] pci_stop_and_remove_bus_device+0x11/0x20 > [] pciehp_unconfigure_device+0x91/0x190 > [] pciehp_disable_slot+0x71/0x220 > [] pciehp_power_thread+0xe6/0x110 > [] process_one_work+0x1ca/0x4e0 > [] ? process_one_work+0x160/0x4e0 > [] ? pciehp_disable_slot+0x220/0x220 > [] worker_thread+0x14e/0x3f0 > [] ? trace_hardirqs_on+0xd/0x10 > [] ? rescuer_thread+0x210/0x210 > [] kthread+0xd6/0xe0 > [] ? _raw_spin_unlock_irq+0x2b/0x50 > [] ? __init_kthread_worker+0x70/0x70 > [] ret_from_fork+0x7c/0xb0 > [] ? __init_kthread_worker+0x70/0x70 > -- I speak only for myself. Rafael J. Wysocki, Intel Open Source Technology Center.