From patchwork Fri Jul 27 05:35:09 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: "Huang, Ying" X-Patchwork-Id: 173559 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by ozlabs.org (Postfix) with ESMTP id 1174E2C0086 for ; Fri, 27 Jul 2012 15:35:18 +1000 (EST) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751860Ab2G0FfO (ORCPT ); Fri, 27 Jul 2012 01:35:14 -0400 Received: from mga09.intel.com ([134.134.136.24]:48947 "EHLO mga09.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751305Ab2G0FfM convert rfc822-to-8bit (ORCPT ); Fri, 27 Jul 2012 01:35:12 -0400 Received: from orsmga001.jf.intel.com ([10.7.209.18]) by orsmga102.jf.intel.com with ESMTP; 26 Jul 2012 22:35:11 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="4.67,352,1309762800"; d="scan'208";a="172067467" Received: from yhuang-dev.sh.intel.com (HELO [10.239.13.28]) ([10.239.13.28]) by orsmga001.jf.intel.com with ESMTP; 26 Jul 2012 22:35:10 -0700 Message-ID: <1343367309.3874.21.camel@yhuang-dev> Subject: Re: bisected regression, v3.5 -> next-20120724: PCI PM causes USB hotplug failure From: Huang Ying To: =?ISO-8859-1?Q?Bj=F8rn?= Mork Cc: huang ying , "Rafael J. Wysocki" , Zheng Yan , Bjorn Helgaas , linux-pci@vger.kernel.org, linux-usb@vger.kernel.org, Alan Stern Date: Fri, 27 Jul 2012 13:35:09 +0800 In-Reply-To: <87k3xqyfm3.fsf@nemi.mork.no> References: <87r4s0opck.fsf@nemi.mork.no> <87pq7ko532.fsf@nemi.mork.no> <1343190864.10311.26.camel@yhuang-dev> <87k3xskvqq.fsf@nemi.mork.no> <874now7xi8.fsf@nemi.mork.no> <1343292851.3874.12.camel@yhuang-dev> <87k3xqyfm3.fsf@nemi.mork.no> X-Mailer: Evolution 3.4.3-1 Mime-Version: 1.0 Sender: linux-pci-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pci@vger.kernel.org On Thu, 2012-07-26 at 12:35 +0200, Bjørn Mork wrote: > Huang Ying writes: > > > Do you have time to try the below patch? > > Sure. Looks OK wrt the USB problems, but may cause problems with the > PCIe WiFi card. Unless those are related to other changes in -next. > > Anyway, for I applied your patch on top of next-20120724 for > consistency (still without Rafael print fix, so we get the D4 below). > This results in different stats for the uhci_hcd and ehci_hcd: > > > Jul 26 12:13:42 nemi kernel: [ 72.820305] uhci_hcd 0000:00:1a.2: power state changed by ACPI to D2 > Jul 26 12:13:42 nemi kernel: [ 72.835101] uhci_hcd 0000:00:1d.0: power state changed by ACPI to D2 > Jul 26 12:13:44 nemi kernel: [ 74.808770] uhci_hcd 0000:00:1a.0: power state changed by ACPI to D2 > Jul 26 12:13:44 nemi kernel: [ 74.840293] ehci_hcd 0000:00:1d.7: power state changed by ACPI to D4 > Jul 26 12:13:44 nemi kernel: [ 74.840326] ehci_hcd 0000:00:1a.7: power state changed by ACPI to D4 > > I assume that is expected, based on the lspci output I posted earlier. > Overall I get a nice mix of allowed/disallowed: > > > > nemi:/home/bjorn# grep . /sys/bus/pci/devices/*/d3cold_allowed > /sys/bus/pci/devices/0000:00:00.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:02.0/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:02.1/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:03.0/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:19.0/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:1a.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1a.1/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1a.2/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1a.7/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:1b.0/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:1c.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1c.1/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1d.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1d.1/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1d.2/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1d.7/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:1e.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1f.0/d3cold_allowed:0 > /sys/bus/pci/devices/0000:00:1f.2/d3cold_allowed:1 > /sys/bus/pci/devices/0000:00:1f.3/d3cold_allowed:0 > /sys/bus/pci/devices/0000:03:00.0/d3cold_allowed:1 > > > USB hotplugging seems to work fine with this. But attempting to > unload/reload the wifi drivers resulted in this: > > > > > Jul 26 12:20:43 nemi kernel: [ 493.812266] iwlwifi 0000:03:00.0: Refused to change power state, currently in D3 I think this is because the parent bridge (PCIe port) is in lower power state. So write to PM registers of child device takes no effect. > Jul 26 12:20:43 nemi kernel: [ 493.812331] iwlwifi 0000:03:00.0: pci_resource_len = 0x00002000 > Jul 26 12:20:43 nemi kernel: [ 493.812335] iwlwifi 0000:03:00.0: pci_resource_base = ffffc900055a4000 > Jul 26 12:20:43 nemi kernel: [ 493.812339] iwlwifi 0000:03:00.0: HW Revision ID = 0x0 > Jul 26 12:20:43 nemi kernel: [ 493.812350] iwlwifi 0000:03:00.0: pci_enable_msi failed(0Xffffffea) > Jul 26 12:20:43 nemi kernel: [ 493.812377] driver: '0000:03:00.0': driver_bound: bound to device 'iwlwifi' > Jul 26 12:20:43 nemi kernel: [ 493.812385] bus: 'pci': really_probe: bound device 0000:03:00.0 to driver iwlwifi > Jul 26 12:20:43 nemi kernel: [ 493.813634] iwldvm: Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree: > Jul 26 12:20:43 nemi kernel: [ 493.813637] iwldvm: Copyright(c) 2003-2012 Intel Corporation > Jul 26 12:20:43 nemi kernel: [ 493.813912] device: '0000:03:00.0': device_add > Jul 26 12:20:43 nemi kernel: [ 493.813939] PM: Adding info for No Bus:0000:03:00.0 > Jul 26 12:20:43 nemi kernel: [ 493.813947] firmware 0000:03:00.0: firmware: requesting iwlwifi-5000-5.ucode > Jul 26 12:20:43 nemi kernel: [ 493.827551] PM: Removing info for No Bus:0000:03:00.0 > Jul 26 12:20:43 nemi kernel: [ 493.827615] iwlwifi 0000:03:00.0: loaded firmware version 8.83.5.1 build 33692 > Jul 26 12:20:43 nemi kernel: [ 493.828170] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUG disabled > Jul 26 12:20:43 nemi kernel: [ 493.828175] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEBUGFS disabled > Jul 26 12:20:43 nemi kernel: [ 493.828178] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TRACING disabled > Jul 26 12:20:43 nemi kernel: [ 493.828182] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE disabled > Jul 26 12:20:43 nemi kernel: [ 493.828185] iwlwifi 0000:03:00.0: CONFIG_IWLWIFI_P2P disabled > Jul 26 12:20:43 nemi kernel: [ 493.828190] iwlwifi 0000:03:00.0: Detected Intel(R) Ultimate N WiFi Link 5300 AGN, REV=0xFFFFFFFF > Jul 26 12:20:43 nemi kernel: [ 493.828218] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S > Jul 26 12:20:43 nemi kernel: [ 493.832013] ------------[ cut here ]------------ > Jul 26 12:20:43 nemi kernel: [ 493.832013] WARNING: at drivers/net/wireless/iwlwifi/iwl-io.c:150 iwl_grab_nic_access+0x47/0x54 [iwlwifi]() > Jul 26 12:20:43 nemi kernel: [ 493.832013] Hardware name: 2776LEG > Jul 26 12:20:43 nemi kernel: [ 493.832013] Timeout waiting for hardware access (CSR_GP_CNTRL 0xffffffff) > Jul 26 12:20:43 nemi kernel: [ 493.832013] Modules linked in: iwldvm iwlwifi mac80211 cfg80211 cpufreq_userspace cpufreq_stats cpufreq_conservative cpufreq_powersave xt_multiport xt_hl ip6table_filter iptable_filter ip_tables ip6_tables x_tables rfcomm bnep binfmt_misc fuse nfsd nfs lockd fscache auth_rpcgss nfs_acl sunrpc 8021q garp stp llc tun ext2 loop snd_hda_codec_conexant snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss snd_pcm thinkpad_acpi snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device arc4 snd i915 coretemp kvm_intel qcserial drm_kms_helper usb_wwan acpi_cpufreq drm psmouse lpc_ich i2c_algo_bit soundcore usbserial qmi_wwan usbnet mii cdc_wdm kvm microcode btusb evdev bluetooth i2c_i801 serio_raw mfd_core rfkill mei snd_page_alloc crc16 i2c_core battery nvram ac video wmi mperf processor button ext3 mbcache jbd sha256_generic ablk_helper cryptd aes_x86_64 aes_generic cbc dm_crypt dm_mod nbd sd_mod crc_t10dif sr_mod cdrom uhci_hcd ahci libahci libata ehci_hc > Jul 26 12:20:43 nemi kernel: d scsi_mod thermal thermal_sys usbcore usb_common e1000e [last unloaded: cfg80211] > Jul 26 12:20:43 nemi kernel: [ 493.832013] Pid: 200, comm: kworker/0:2 Not tainted 3.5.0-rc2-next-20120724+ #23 > Jul 26 12:20:43 nemi kernel: [ 493.832013] Call Trace: > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? warn_slowpath_common+0x78/0x8c > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? warn_slowpath_fmt+0x45/0x4a > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_grab_nic_access+0x47/0x54 [iwlwifi] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_write_prph+0x29/0x56 [iwlwifi] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_apm_init+0x13a/0x16b [iwlwifi] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_trans_pcie_start_hw+0x101/0x15b [iwlwifi] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_op_mode_dvm_start+0x246/0x96a [iwldvm] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? iwl_ucode_callback+0x9e5/0xad8 [iwlwifi] > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? _request_firmware_prepare+0x1e2/0x1e2 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? request_firmware_work_func+0xaf/0xe4 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? process_one_work+0x1ff/0x311 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? worker_thread+0x1fb/0x2fb > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? process_one_work+0x311/0x311 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? process_one_work+0x311/0x311 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? kthread+0x81/0x89 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? kernel_thread_helper+0x4/0x10 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? kthread_freezable_should_stop+0x53/0x53 > Jul 26 12:20:43 nemi kernel: [ 493.832013] [] ? gs_change+0x13/0x13 > Jul 26 12:20:43 nemi kernel: [ 493.832013] ---[ end trace fcaaf916dd43b7ca ]--- > Jul 26 12:20:43 nemi kernel: [ 493.864785] iwlwifi 0000:03:00.0: bad EEPROM/OTP signature, type=OTP, EEPROM_GP=0x00000007 > Jul 26 12:20:43 nemi kernel: [ 493.864791] iwlwifi 0000:03:00.0: EEPROM not found, EEPROM_GP=0xffffffff > Jul 26 12:20:43 nemi kernel: [ 493.864795] iwlwifi 0000:03:00.0: Unable to init EEPROM > > > That does not look good... > > The bridge and WiFi devices power status at this point is: > > bjorn@nemi:~$ grep . /sys/bus/pci/devices/0000:00:1c.1/power/* > /sys/bus/pci/devices/0000:00:1c.1/power/async:enabled > grep: /sys/bus/pci/devices/0000:00:1c.1/power/autosuspend_delay_ms: Input/output error > /sys/bus/pci/devices/0000:00:1c.1/power/control:auto > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_active_kids:0 > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_active_time:390576 > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_enabled:enabled > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:suspended > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_suspended_time:697004 > /sys/bus/pci/devices/0000:00:1c.1/power/runtime_usage:0 > /sys/bus/pci/devices/0000:00:1c.1/power/wakeup:disabled > > bjorn@nemi:~$ grep . /sys/bus/pci/devices/0000:03:00.0/power/* > /sys/bus/pci/devices/0000:03:00.0/power/async:enabled > grep: /sys/bus/pci/devices/0000:03:00.0/power/autosuspend_delay_ms: Input/output error > /sys/bus/pci/devices/0000:03:00.0/power/control:auto > /sys/bus/pci/devices/0000:03:00.0/power/runtime_active_kids:0 > /sys/bus/pci/devices/0000:03:00.0/power/runtime_active_time:0 > /sys/bus/pci/devices/0000:03:00.0/power/runtime_enabled:disabled > /sys/bus/pci/devices/0000:03:00.0/power/runtime_status:unsupported > /sys/bus/pci/devices/0000:03:00.0/power/runtime_suspended_time:70220 > /sys/bus/pci/devices/0000:03:00.0/power/runtime_usage:0 > /sys/bus/pci/devices/0000:03:00.0/power/wakeup:disabled > > > > I don't really understand the last one. How can suspended_time > 0 when > status is unsupported and autosuspend is disabled? Do you have time to try the following patch? Best Regards, Huang Ying --- drivers/pci/pci-driver.c | 6 ++++++ 1 file changed, 6 insertions(+) -- To unsubscribe from this list: send the line "unsubscribe linux-pci" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html --- a/drivers/pci/pci-driver.c +++ b/drivers/pci/pci-driver.c @@ -280,8 +280,12 @@ static long local_pci_probe(void *_ddi) { struct drv_dev_and_id *ddi = _ddi; struct device *dev = &ddi->dev->dev; + struct device *parent = dev->parent; int rc; + /* The parent bridge must be in active state when probing */ + if (parent) + pm_runtime_get_sync(parent); /* Unbound PCI devices are always set to disabled and suspended. * During probe, the device is set to enabled and active and the * usage count is incremented. If the driver supports runtime PM, @@ -298,6 +302,8 @@ static long local_pci_probe(void *_ddi) pm_runtime_set_suspended(dev); pm_runtime_put_noidle(dev); } + if (parent) + pm_runtime_put(parent); return rc; }