diff mbox

3.9-rc1: pciehp and eSATA card SiI 3132, no XHCI

Message ID 51581170.30708@fold.natur.cuni.cz (mailing list archive)
State New, archived
Delegated to: Bjorn Helgaas
Headers show

Commit Message

Martin Mokrejs March 31, 2013, 10:35 a.m. UTC
Hi Ying,
  I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
and kmemleaks.
  I removed the coldbooted card, inserted it and ejected it.


  In brief, lspci reports changes but there are no changes in /proc/interrupts
related to

  19:          0          0   IO-APIC-fasteoi   sata_sil24


and no changes at all in /proc/iomem which I expected to happen during
hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).

All the runtime_status data were same after every tested step, so again,
no diffs to show but here are the values confirming laptop-mode-tools
enabled powersaving:

/sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1d.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1f.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1f.2/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1f.3/power/runtime_status:suspended
/sys/bus/pci/devices/0000:05:00.0/power/runtime_status:active
/sys/bus/pci/devices/0000:09:00.0/power/runtime_status:active
/sys/bus/pci/devices/0000:0b:00.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:11:00.0/power/runtime_status:active


  So, the only diffs I could provide are from lspci -vvv. They show
sata_sil24 was loaded that is confirmed by lsmod at the end of all
tests.




The comparison of the two hotremovals shows no diff.

I will provide the dmesg in a follow-up email. The acpidump you should have
already received yesteday.

Thank you,
Martin

Huang Ying wrote:
> On Fri, 2013-03-29 at 15:11 +0100, Martin Mokrejs wrote:
>> Hi Ying,
>>   thank you for the patch. Here are the results.
> 
> Thanks for your help! It appears my previous patch does not help
> much :(.  Can you try below patch?  I think this is mainly for hotplug
> but may be helpful for xhci dead port bug too.
> 
> Please test this patch with laptop-mode-tool installed and enabled.  And
> before/after test, please get PCI devices runtime status with:
> 
> grep . /sys/bus/pci/devices/*/power/runtime_status
> 
> And please give me the full dmesg for boot and incremental dmesg for
> operations.  Could you give me the ACPI dump for your machine?
> 
> Best Regards,
> Huang Ying
> 
>>From c0179956fb396fe68f2a237713c7592feea87d16 Mon Sep 17 00:00:00 2001
> From: Huang Ying <ying.huang@intel.com>
> Date: Fri, 8 Mar 2013 16:13:54 +0800
> Subject: [PATCH] pcie_hp_disable_rtpm
> 
> ---
>  drivers/pci/hotplug/pci_hotplug_core.c |    8 ++++++++
>  drivers/pci/pci-acpi.c                 |   15 +++++++++++++++
>  drivers/pci/pci.c                      |    1 +
>  drivers/pci/pcie/portdrv_pci.c         |   12 +++++++++---
>  drivers/pci/slot.c                     |   18 ++++++++++++++++++
>  include/acpi/acpi_bus.h                |    1 +
>  include/linux/pci.h                    |    1 +
>  7 files changed, 53 insertions(+), 3 deletions(-)
> 
> --- a/drivers/pci/hotplug/pci_hotplug_core.c
> +++ b/drivers/pci/hotplug/pci_hotplug_core.c
> @@ -39,6 +39,7 @@
>  #include <linux/mutex.h>
>  #include <linux/pci.h>
>  #include <linux/pci_hotplug.h>
> +#include <linux/pm_runtime.h>
>  #include <asm/uaccess.h>
>  #include "../pci.h"
>  
> @@ -473,6 +474,9 @@ int __pci_hp_register(struct hotplug_slo
>  	dbg("Added slot %s to the list\n", name);
>  out:
>  	mutex_unlock(&pci_hp_mutex);
> +	/* Bridge runtime PM state may be influenced by hotplug */
> +	pm_runtime_resume(&bus->self->dev);
> +	dev_info(&bus->self->dev, "hotplug slot added!\n");
>  	return result;
>  }
>  
> @@ -489,6 +493,7 @@ int pci_hp_deregister(struct hotplug_slo
>  {
>  	struct hotplug_slot *temp;
>  	struct pci_slot *slot;
> +	struct pci_bus *bus;
>  
>  	if (!hotplug)
>  		return -ENODEV;
> @@ -508,8 +513,11 @@ int pci_hp_deregister(struct hotplug_slo
>  
>  	hotplug->release(hotplug);
>  	slot->hotplug = NULL;
> +	bus = slot->bus;
>  	pci_destroy_slot(slot);
>  	mutex_unlock(&pci_hp_mutex);
> +	pm_runtime_resume(&bus->self->dev);
> +	dev_info(&bus->self->dev, "hotplug slot removed!\n");
>  
>  	return 0;
>  }
> --- a/drivers/pci/pcie/portdrv_pci.c
> +++ b/drivers/pci/pcie/portdrv_pci.c
> @@ -154,9 +154,15 @@ static int pcie_port_runtime_idle(struct
>  	 */
>  	pci_walk_bus(pdev->subordinate, pci_dev_pme_poll, &pme_poll);
>  	/* Delay for a short while to prevent too frequent suspend/resume */
> -	if (!pme_poll)
> -		pm_schedule_suspend(dev, 10);
> -	return -EBUSY;
> +	if (pme_poll)
> +		return -EBUSY;
> +	if (pci_bus_has_hotplug_slots(pdev->subordinate)) {
> +		dev_info(&pdev->dev, "ppri: has hotplug slots, do not suspend!\n");
> +		return -EBUSY;
> +	}
> +	dev_info(&pdev->dev, "ppri: will go suspend, is_hotplug_bridge: %d.\n",
> +		 pdev->is_hotplug_bridge);
> +	return pm_schedule_suspend(dev, 10);
>  }
>  #else
>  #define pcie_port_runtime_suspend	NULL
> --- a/drivers/pci/slot.c
> +++ b/drivers/pci/slot.c
> @@ -345,6 +345,24 @@ out:
>  }
>  EXPORT_SYMBOL_GPL(pci_renumber_slot);
>  
> +bool pci_bus_has_hotplug_slots(struct pci_bus *bus)
> +{
> +	struct pci_slot *slot;
> +	bool has_hotplug_slots = false;
> +
> +	down_read(&pci_bus_sem);
> +	list_for_each_entry(slot, &bus->slots, list) {
> +		if (slot->hotplug) {
> +			has_hotplug_slots = true;
> +			break;
> +		}
> +	}
> +	up_read(&pci_bus_sem);
> +
> +	return has_hotplug_slots;
> +}
> +EXPORT_SYMBOL_GPL(pci_bus_has_hotplug_slots);
> +
>  /**
>   * pci_destroy_slot - decrement refcount for physical PCI slot
>   * @slot: struct pci_slot to decrement
> --- a/include/linux/pci.h
> +++ b/include/linux/pci.h
> @@ -722,6 +722,7 @@ struct pci_slot *pci_create_slot(struct
>  void pci_destroy_slot(struct pci_slot *slot);
>  void pci_renumber_slot(struct pci_slot *slot, int slot_nr);
>  int pci_scan_slot(struct pci_bus *bus, int devfn);
> +bool pci_bus_has_hotplug_slots(struct pci_bus *bus);
>  struct pci_dev *pci_scan_single_device(struct pci_bus *bus, int devfn);
>  void pci_device_add(struct pci_dev *dev, struct pci_bus *bus);
>  unsigned int pci_scan_child_bus(struct pci_bus *bus);
> --- a/drivers/pci/pci-acpi.c
> +++ b/drivers/pci/pci-acpi.c
> @@ -43,10 +43,16 @@ static void pci_acpi_wake_bus(acpi_handl
>  static void pci_acpi_wake_dev(acpi_handle handle, u32 event, void *context)
>  {
>  	struct pci_dev *pci_dev = context;
> +	struct acpi_device *adev;
>  
>  	if (event != ACPI_NOTIFY_DEVICE_WAKE || !pci_dev)
>  		return;
>  
> +	if (!acpi_bus_get_device(handle, &adev)) {
> +		adev->wakeup.flags.run_wake_works = true;
> +		dev_info(&pci_dev->dev, "run wake works!\n");
> +	}
> +
>  	if (pci_dev->current_state == PCI_D3cold) {
>  		pci_wakeup_event(pci_dev);
>  		pm_runtime_resume(&pci_dev->dev);
> @@ -146,6 +152,15 @@ phys_addr_t acpi_pci_root_get_mcfg_addr(
>  static pci_power_t acpi_pci_choose_state(struct pci_dev *pdev)
>  {
>  	int acpi_state, d_max;
> +	acpi_handle handle = DEVICE_ACPI_HANDLE(&pdev->dev);
> +	struct acpi_device *adev;
> +
> +	if (pci_is_bridge(pdev) && !acpi_bus_get_device(handle, &adev)) {
> +		if (!adev->wakeup.flags.run_wake_works) {
> +			dev_info(&pdev->dev, "choose state, run wake not verified\n");
> +			return PCI_D0;
> +		}
> +	}
>  
>  	if (pdev->no_d3cold)
>  		d_max = ACPI_STATE_D3_HOT;
> --- a/include/acpi/acpi_bus.h
> +++ b/include/acpi/acpi_bus.h
> @@ -245,6 +245,7 @@ struct acpi_device_perf {
>  struct acpi_device_wakeup_flags {
>  	u8 valid:1;		/* Can successfully enable wakeup? */
>  	u8 run_wake:1;		/* Run-Wake GPE devices */
> +	u8 run_wake_works:1;	/* Run-Wake works for the device */
>  	u8 notifier_present:1;  /* Wake-up notify handler has been installed */
>  };
>  
> --- a/drivers/pci/pci.c
> +++ b/drivers/pci/pci.c
> @@ -1832,6 +1832,7 @@ int pci_finish_runtime_suspend(struct pc
>  	__pci_enable_wake(dev, target_state, true, pci_dev_run_wake(dev));
>  
>  	error = pci_set_power_state(dev, target_state);
> +	dev_info(&dev->dev, "pfrs: target: %d, %d\n", target_state, error);
>  
>  	if (error) {
>  		__pci_enable_wake(dev, target_state, true, false);
> 
> 
> --
> 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
> 
> 
--
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

Comments

Huang, Ying March 31, 2013, 2:12 p.m. UTC | #1
Hi, Martin,

Thanks for your testing!

On Sun, 2013-03-31 at 12:35 +0200, Martin Mokrejs wrote:
> Hi Ying,
>   I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
> when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
> enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
> and kmemleaks.
>   I removed the coldbooted card, inserted it and ejected it.
> 
> 
>   In brief, lspci reports changes but there are no changes in /proc/interrupts
> related to
> 
>   19:          0          0   IO-APIC-fasteoi   sata_sil24
> 
> 
> and no changes at all in /proc/iomem which I expected to happen during
> hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).
> 
> All the runtime_status data were same after every tested step, so again,
> no diffs to show but here are the values confirming laptop-mode-tools
> enabled powersaving:
> 
> /sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active

It appears that 1c.7 is identified successfully as an hotplug-able PCIe
port, and never put into suspended state.

And from your description below, it appears that hot-add and hot-remove
of the eSATA card works for you, doesn't it?

> /sys/bus/pci/devices/0000:00:1d.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:00:1f.0/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1f.2/power/runtime_status:active
> /sys/bus/pci/devices/0000:00:1f.3/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:05:00.0/power/runtime_status:active
> /sys/bus/pci/devices/0000:09:00.0/power/runtime_status:active
> /sys/bus/pci/devices/0000:0b:00.0/power/runtime_status:suspended
> /sys/bus/pci/devices/0000:11:00.0/power/runtime_status:active
> 
> 
>   So, the only diffs I could provide are from lspci -vvv. They show
> sata_sil24 was loaded that is confirmed by lsmod at the end of all
> tests.
> 
> --- lspci_vvv_initial.txt       2013-03-31 12:01:05.000000000 +0200
> +++ lspci_vvv_ejected.txt       2013-03-31 12:01:24.000000000 +0200
> @@ -293,7 +293,7 @@
>         I/O behind bridge: 0000c000-0000dfff
>         Memory behind bridge: f6c00000-f7cfffff
>         Prefetchable memory behind bridge: 00000000f0000000-00000000f10fffff
> -       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- <SERR- <PERR-
> +       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort+ <SERR- <PERR-
>         BridgeCtl: Parity- SERR- NoISA- VGA- MAbort- >Reset- FastB2B-
>                 PriDiscTmr- SecDiscTmr- DiscTmrStat- DiscTmrSERREn-
>         Capabilities: [40] Express (v2) Root Port (Slot+), MSI 00
> @@ -307,13 +307,13 @@
>                         ClockPM- Surprise- LLActRep+ BwNot-
>                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
>                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> -               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
> +               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
>                 SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
>                         Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
>                 SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
>                         Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
> -               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
> -                       Changed: MRL- PresDet- LinkState-
> +               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
> +                       Changed: MRL- PresDet- LinkState+
>                 RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
>                 RootCap: CRSVisible-
>                 RootSta: PME ReqID 0000, PMEStatus- PMEPending-
> @@ -521,39 +521,7 @@
>                 AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
>         Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
>  
> -11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
> -       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
> -       Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
> -       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> -       Latency: 0, Cache Line Size: 64 bytes
> -       Interrupt: pin A routed to IRQ 19
> -       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [size=128]
> -       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [size=16K]
> -       Region 4: I/O ports at c000 [size=128]
> -       Expansion ROM at f6c00000 [disabled] [size=512K]
> -       Capabilities: [54] Power Management version 2
> -               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
> -               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
> -       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
> -               Address: 0000000000000000  Data: 0000
> -       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
> -               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
> -                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
> -               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
> -                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
> -                       MaxPayload 128 bytes, MaxReadReq 4096 bytes
> -               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
> -               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
> -                       ClockPM- Surprise- LLActRep- BwNot-
> -               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
> -                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> -               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
> -       Capabilities: [100 v1] Advanced Error Reporting
> -               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
> -               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
> -               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
> -               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> -               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> -               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
> +11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
> +       !!! Unknown header type 7f
>         Kernel driver in use: sata_sil24
>  
> 
> The after a hotinsert I see:
> 
> --- lspci_vvv_ejected.txt       2013-03-31 12:01:24.000000000 +0200
> +++ lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
> @@ -307,12 +307,12 @@
>                         ClockPM- Surprise- LLActRep+ BwNot-
>                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
>                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> -               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
> +               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
>                 SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
>                         Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
>                 SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
>                         Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
> -               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
> +               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
>                         Changed: MRL- PresDet- LinkState+
>                 RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
>                 RootCap: CRSVisible-
> @@ -521,7 +521,38 @@
>                 AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
>         Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
>  
> -11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
> -       !!! Unknown header type 7f
> +11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
> +       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
> +       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
> +       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> +       Interrupt: pin A routed to IRQ 19
> +       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
> +       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
> +       Region 4: I/O ports at c000 [disabled] [size=128]
> +       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
> +       Capabilities: [54] Power Management version 2
> +               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
> +               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
> +       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
> +               Address: 0000000000000000  Data: 0000
> +       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
> +               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
> +                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
> +               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
> +                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
> +                       MaxPayload 128 bytes, MaxReadReq 512 bytes
> +               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
> +               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
> +                       ClockPM- Surprise- LLActRep- BwNot-
> +               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
> +                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> +               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
> +       Capabilities: [100 v1] Advanced Error Reporting
> +               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
> +               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
> +               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
> +               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> +               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> +               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
>         Kernel driver in use: sata_sil24
>  
> 
> 
> The last hotremoval caused:
> 
> --- lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
> +++ lspci_vvv_ejected_and_reinserted_ejected.txt        2013-03-31 12:03:16.000000000 +0200
> @@ -307,12 +307,12 @@
>                         ClockPM- Surprise- LLActRep+ BwNot-
>                 LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
>                         ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> -               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
> +               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
>                 SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
>                         Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
>                 SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
>                         Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
> -               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
> +               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
>                         Changed: MRL- PresDet- LinkState+
>                 RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
>                 RootCap: CRSVisible-
> @@ -521,38 +521,7 @@
>                 AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
>         Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
>  
> -11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
> -       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
> -       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
> -       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> -       Interrupt: pin A routed to IRQ 19
> -       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
> -       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
> -       Region 4: I/O ports at c000 [disabled] [size=128]
> -       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
> -       Capabilities: [54] Power Management version 2
> -               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
> -               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
> -       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
> -               Address: 0000000000000000  Data: 0000
> -       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
> -               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
> -                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
> -               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
> -                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
> -                       MaxPayload 128 bytes, MaxReadReq 512 bytes
> -               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
> -               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
> -                       ClockPM- Surprise- LLActRep- BwNot-
> -               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
> -                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
> -               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
> -       Capabilities: [100 v1] Advanced Error Reporting
> -               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
> -               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
> -               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
> -               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> -               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
> -               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
> +11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
> +       !!! Unknown header type 7f
>         Kernel driver in use: sata_sil24
>  
> 
> 
> 
> 
> Maybe I should, unlike in most previous reports, show a diff between a colplugged state
> and the hotinserted states:
> 
> --- lspci_vvv_initial.txt       2013-03-31 12:01:05.000000000 +0200
> +++ lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
> @@ -293,7 +293,7 @@
>         I/O behind bridge: 0000c000-0000dfff
>         Memory behind bridge: f6c00000-f7cfffff
>         Prefetchable memory behind bridge: 00000000f0000000-00000000f10fffff
> -       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- <SERR- <PERR-
> +       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort+ <SERR- <PERR-
>         BridgeCtl: Parity- SERR- NoISA- VGA- MAbort- >Reset- FastB2B-
>                 PriDiscTmr- SecDiscTmr- DiscTmrStat- DiscTmrSERREn-
>         Capabilities: [40] Express (v2) Root Port (Slot+), MSI 00
> @@ -313,7 +313,7 @@
>                 SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
>                         Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
>                 SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
> -                       Changed: MRL- PresDet- LinkState-
> +                       Changed: MRL- PresDet- LinkState+
>                 RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
>                 RootCap: CRSVisible-
>                 RootSta: PME ReqID 0000, PMEStatus- PMEPending-
> @@ -523,14 +523,13 @@
>  
>  11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
>         Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
> -       Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
> +       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
>         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> -       Latency: 0, Cache Line Size: 64 bytes
>         Interrupt: pin A routed to IRQ 19
> -       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [size=128]
> -       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [size=16K]
> -       Region 4: I/O ports at c000 [size=128]
> -       Expansion ROM at f6c00000 [disabled] [size=512K]
> +       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
> +       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
> +       Region 4: I/O ports at c000 [disabled] [size=128]
> +       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
>         Capabilities: [54] Power Management version 2
>                 Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
>                 Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
> @@ -541,7 +540,7 @@
>                         ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
>                 DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
>                         RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
> -                       MaxPayload 128 bytes, MaxReadReq 4096 bytes
> +                       MaxPayload 128 bytes, MaxReadReq 512 bytes
>                 DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
>                 LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
>                         ClockPM- Surprise- LLActRep- BwNot-
> 
> 
> 
> The comparison of the two hotremovals shows no diff.
> 
> I will provide the dmesg in a follow-up email.

Thanks!

> The acpidump you should have already received yesteday.

Yes.

Best Regards,
Huang Ying


--
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
Martin Mokrejs March 31, 2013, 3:04 p.m. UTC | #2
Hi Ying,
  
Huang Ying wrote:
> Hi, Martin,
> 
> Thanks for your testing!
> 
> On Sun, 2013-03-31 at 12:35 +0200, Martin Mokrejs wrote:
>> Hi Ying,
>>   I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
>> when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
>> enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
>> and kmemleaks.
>>   I removed the coldbooted card, inserted it and ejected it.
>>
>>
>>   In brief, lspci reports changes but there are no changes in /proc/interrupts
>> related to
>>
>>   19:          0          0   IO-APIC-fasteoi   sata_sil24
>>
>>
>> and no changes at all in /proc/iomem which I expected to happen during
>> hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).
>>
>> All the runtime_status data were same after every tested step, so again,
>> no diffs to show but here are the values confirming laptop-mode-tools
>> enabled powersaving:
>>
>> /sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
>> /sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
>> /sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
>> /sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
>> /sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
>> /sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
>> /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
>> /sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
>> /sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
>> /sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
> 
> It appears that 1c.7 is identified successfully as an hotplug-able PCIe
> port, and never put into suspended state.

Yes. Truly said, after I now went to test your previous two patches
on the 3.9-rc1 I confirm that the syslog logging is broken with all your
three patches. I fear we are hitting here, with the pciehp problems
not a powersaving issue but an upstream /proc or /sys files being outdated.
Otherwise I can't figure out why disabling in runtime laptop-mode-tools
and doing the "find /sys .... | while ... echo "on" > $f" trickery
does not help to get pciehp working. This would have fixed the acpiphp
at least on 3.8 kernel. I see that sata_sil24 is not loaded by itself
during hotinsert. It seems lspci reports at such times 0xff for the 11:00
eSATA card, /etc/iomem reports stale memory regions used by 11:00 while
/proc/interrupts says no IRQ is assigned to sata_sil24 (well, sata_sil24
is not loaded per lsmod, lspci would should report sata_sil24 also but
provided the 11:00 entry is broken and shows the 0xff it maybe cannot
report is sata_sil24 is loaded).

I will post a little more details as a proper answer to your other patch
where I managed to get yet another stacktrace, about the eSATA thought to
be D3 state. Physically the card was ejected and just a modprobe sata_sil24
caused the sata_sil24 to use some outdated data. I will dive now into
that. 



> 
> And from your description below, it appears that hot-add and hot-remove
> of the eSATA card works for you, doesn't it?

The PresDet works fine I think, yes. Sometimes I see in the lspci -vvv diffs:

-Control: I/O+ ... BusMaster+
+Control: I/O- ... BusMaster-

and sometimes 

-        Latency: 0, Cache Line Size: 64 bytes
+        Latency: 0

or even the Latency: line being gone completely from lspci -vvv output. Why is that?
I think debug checks and prints in kernel are necessary.


How do these related to /proc/interrupts not showing an IRQ for the 11:00 device?
Does that prevent automated sata_sil24 loading once the card is inserted? Would
you please add some extra debug prints and checks into the kernel?

Take also into consideration the "3.8.2: stale pci device info for a previously inserted express card"
for a list of chimeric entries reported by lspci. That could tell you which values
are being cached and invalid. Hopefully some checks could be done between values
read by lspci and those in /proc and /sys.



Do you already know why almost nothing is logged by kernel wen either of your
three patches (v1 sent on 03/29/13 08:41, v2 sent on 03/29/13 09:20, v3 sent on
03/30/13 11:54)?


I did not test the xHCI port behavior with any of your three patches because I have
disabled USB support in this kernel altogether for 3.9-rc1 tests. And I would like to stick
with that until we fix the pciehp issue. I stepped rather late into the big testing game,
I believe the pciehp bug we are facing was not working since 3.5/3.6, I don't think
the 3.9-rc1-based tests be much different from earlier kernels.

For a broader view, on the 3.8 series we will meanwhile hopefully get to a fix of the
PME# stuff. I think I reported quite a good number of potential problems yesterday.
After that, I will check how xHCI behaves on 3.9 but I believe the PME#-related fix from
3.8 will be also applicable to fixing 3.9 so the xHCI won't have problems there anymore.


Martin
--
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
Martin Mokrejs March 31, 2013, 11:17 p.m. UTC | #3
[ also +Len Brown -- would you please comment what the ACPI-related bug in BIOS
 could be causing? Should be the message be logged also under 3.8.3? It does
 NOT happen! ]

Hi Ying,
  I see the linux-pci throwed away the email dmesg and lspci attached.
For the sake of archives I am including here some ACPI-related stuff.

Martin Mokrejs wrote:
> Attaching the dmesg file from after all the tests. Effectively it covers
> only bootup messages but there is one of your debug messages:
> 
> [   15.941468] pcieport 0000:00:1c.0: ppri: will go suspend, is_hotplug_bridge: 0.
> 
> I am also attaching the full lspci -vvv output captured after the cold boot.
> I should have used 'diff -u50' to sow broader regions around the changes
> to make it clearer the diffs were all about 1c.7 and 11:00 only. From the
> full file you can get offset line numbers yourself to double check if necessary.

Am I right that your patches aimed to yield
'System wakeup disabled by ACPI' for all pci devices? Somehow, that did NOT happen
for 11:00, the card in the express card slot (it was inserted before cold boot).

[    1.590952] pci 0000:00:1a.0: System wakeup disabled by ACPI
[    1.593046] pci 0000:00:1b.0: System wakeup disabled by ACPI
[    1.594430] pci 0000:00:1c.0: System wakeup disabled by ACPI
[    1.595855] pci 0000:00:1c.1: System wakeup disabled by ACPI
[    1.597369] pci 0000:00:1c.3: System wakeup disabled by ACPI
[    1.598917] pci 0000:00:1c.4: System wakeup disabled by ACPI
[    1.602131] pci 0000:00:1c.7: System wakeup disabled by ACPI
[    1.624166] pci 0000:00:1d.0: System wakeup disabled by ACPI
[    1.630725] pci 0000:05:00.0: System wakeup disabled by ACPI
[    1.634536] pci 0000:09:00.0: System wakeup disabled by ACPI
[    1.636221] pci 0000:0b:00.0: System wakeup disabled by ACPI

This "issue" looks common to all your three patches.



Also, notably, there is on patched 3.9-rc1:

[    0.926322] ACPI: Added _OSI(Module Device)
[    0.926424] ACPI: Added _OSI(Processor Device)
[    0.926523] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.926625] ACPI: Added _OSI(Processor Aggregator Device)
[    0.932346] ACPI: EC: Look up EC in DSDT
[    0.942636] ACPI: Executed 1 blocks of module-level executable AML code
[    1.034418] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    1.088331] ACPI: SSDT 00000000dad51698 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.091493] ACPI: Dynamic OEM Table Load:
[    1.091496] ACPI: SSDT           (null) 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.123506] ACPI: SSDT 00000000dad52a98 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.128317] ACPI: Dynamic OEM Table Load:
[    1.128319] ACPI: SSDT           (null) 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.158678] ACPI: SSDT 00000000dad50d98 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.161258] ACPI: Dynamic OEM Table Load:
[    1.161260] ACPI: SSDT           (null) 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.190627] ACPI: Interpreter enabled
[    1.190722] ACPI: (supports S0 S1ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20130117/hwxface-568)
[    1.191110]  S3 S4 S5)
[    1.191195] ACPI: Using IOAPIC for interrupt routing
[    1.191763] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    1.519009] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    1.526115] acpi PNP0A08:00: Unable to request _OSC control (_OSC support mask: 0x19)


while 3.8.3 used to give:

[    1.057812] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    1.125133] ACPI: SSDT 00000000dad51698 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.128452] ACPI: Dynamic OEM Table Load:
[    1.128455] ACPI: SSDT           (null) 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.165751] ACPI: SSDT 00000000dad52a98 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.170762] ACPI: Dynamic OEM Table Load:
[    1.170764] ACPI: SSDT           (null) 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.210483] ACPI: SSDT 00000000dad50d98 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.213195] ACPI: Dynamic OEM Table Load:
[    1.213198] ACPI: SSDT           (null) 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.251508] ACPI: Interpreter enabled
[    1.251603] ACPI: (supports S0 S1 S3 S4 S5)
[    1.252290] ACPI: Using IOAPIC for interrupt routing
[    1.530836] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    1.539002] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    1.539115] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
[    1.552100] pci_root PNP0A08:00: Unable to request _OSC control (_OSC support mask: 0x19)

According to Google looks like the 'ACPI Exception: AE_NOT_FOUND' is pointing to a buggy BIOS
(this is Dell Vostro 3550, A11 BIOS version).
Looks 3.8 series just does not have new enough ACPI to print out the message to the user
doesn't it happen there? What is affected by the BIOS bug? :(




Piece of dmesg from your third patch (containing those 'ppri' debug prints) covering the ACPI
messages.

[    0.362558] PCI: MMCONFIG for domain 0000 [bus 00-3f] at [mem 0xf8000000-0xfbffffff] (base 0xf8000000)
[    0.362706] PCI: MMCONFIG at [mem 0xf8000000-0xfbffffff] reserved in E820
[    0.370241] PCI: Using configuration type 1 for base access
[    0.418113] bio: create slab <bio-0> at 0
[    0.585719] raid6: sse2x1    7608 MB/s
[    0.755953] raid6: sse2x2    9349 MB/s
[    0.926188] raid6: sse2x4   10667 MB/s
[    0.926190] raid6: using algorithm sse2x4 (10667 MB/s)
[    0.926191] raid6: using ssse3x2 recovery algorithm
[    0.926322] ACPI: Added _OSI(Module Device)
[    0.926424] ACPI: Added _OSI(Processor Device)
[    0.926523] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.926625] ACPI: Added _OSI(Processor Aggregator Device)
[    0.932346] ACPI: EC: Look up EC in DSDT
[    0.942636] ACPI: Executed 1 blocks of module-level executable AML code
[    1.034418] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    1.088331] ACPI: SSDT 00000000dad51698 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.091493] ACPI: Dynamic OEM Table Load:
[    1.091496] ACPI: SSDT           (null) 0064F (v01  PmRef  Cpu0Cst 00003001 INTL 20051117)
[    1.123506] ACPI: SSDT 00000000dad52a98 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.128317] ACPI: Dynamic OEM Table Load:
[    1.128319] ACPI: SSDT           (null) 00303 (v01  PmRef    ApIst 00003000 INTL 20051117)
[    1.158678] ACPI: SSDT 00000000dad50d98 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.161258] ACPI: Dynamic OEM Table Load:
[    1.161260] ACPI: SSDT           (null) 00119 (v01  PmRef    ApCst 00003000 INTL 20051117)
[    1.190627] ACPI: Interpreter enabled
[    1.190722] ACPI: (supports S0 S1ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20130117/hwxface-568)
[    1.191110]  S3 S4 S5)
[    1.191195] ACPI: Using IOAPIC for interrupt routing
[    1.191763] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    1.519009] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    1.526115] acpi PNP0A08:00: Unable to request _OSC control (_OSC support mask: 0x19)
[    1.542922] PCI host bridge to bus 0000:00
[    1.543024] pci_bus 0000:00: root bus resource [bus 00-3e]
[    1.543126] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7]
[    1.543227] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff]
[    1.543329] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff]
[    1.543432] pci_bus 0000:00: root bus resource [mem 0x000d0000-0x000d3fff]
[    1.543534] pci_bus 0000:00: root bus resource [mem 0x000d4000-0x000d7fff]
[    1.543636] pci_bus 0000:00: root bus resource [mem 0x000d8000-0x000dbfff]
[    1.543738] pci_bus 0000:00: root bus resource [mem 0x000dc000-0x000dffff]
[    1.543841] pci_bus 0000:00: root bus resource [mem 0x000e0000-0x000e3fff]
[    1.543943] pci_bus 0000:00: root bus resource [mem 0x000e4000-0x000e7fff]
[    1.544045] pci_bus 0000:00: root bus resource [mem 0xdfa00000-0xfeafffff]
[    1.544148] pci_bus 0000:00: root bus resource [mem 0xfed40000-0xfed44fff]
[    1.544251] pci_bus 0000:00: scanning bus
[    1.544290] pci 0000:00:00.0: [8086:0104] type 00 class 0x060000
[    1.544298] pci 0000:00:00.0: calling quirk_mmio_always_on+0x0/0xa
[    1.546226] pci 0000:00:02.0: [8086:0126] type 00 class 0x030000
[    1.546242] pci 0000:00:02.0: reg 10: [mem 0xf6800000-0xf6bfffff 64bit]
[    1.546251] pci 0000:00:02.0: reg 18: [mem 0xe0000000-0xefffffff 64bit pref]
[    1.546257] pci 0000:00:02.0: reg 20: [io  0xf000-0xf03f]
[    1.548073] pci 0000:00:16.0: [8086:1c3a] type 00 class 0x078000
[    1.548113] pci 0000:00:16.0: reg 10: [mem 0xf7f0a000-0xf7f0a00f 64bit]
[    1.548243] pci 0000:00:16.0: PME# supported from D0 D3hot D3cold
[    1.548269] pci 0000:00:16.0: PME# disabled
[    1.550203] pci 0000:00:1a.0: [8086:1c2d] type 00 class 0x0c0320
[    1.550239] pci 0000:00:1a.0: reg 10: [mem 0xf7f08000-0xf7f083ff]
[    1.550395] pci 0000:00:1a.0: PME# supported from D0 D3hot D3cold
[    1.550401] pci 0000:00:1a.0: PME# disabled
[    1.569774] pci 0000:00:1a.0: System wakeup disabled by ACPI
[    1.570451] pci 0000:00:1b.0: [8086:1c20] type 00 class 0x040300
[    1.570481] pci 0000:00:1b.0: reg 10: [mem 0xf7f00000-0xf7f03fff 64bit]
[    1.570627] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold
[    1.570633] pci 0000:00:1b.0: PME# disabled
[    1.571885] pci 0000:00:1b.0: System wakeup disabled by ACPI
[    1.572487] pci 0000:00:1c.0: [8086:1c10] type 01 class 0x060400
[    1.572559] pci 0000:00:1c.0: calling pci_fixup_transparent_bridge+0x0/0x1d
[    1.572645] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    1.572651] pci 0000:00:1c.0: PME# disabled
[    1.573280] pci 0000:00:1c.0: System wakeup disabled by ACPI
[    1.573868] pci 0000:00:1c.1: [8086:1c12] type 01 class 0x060400
[    1.573938] pci 0000:00:1c.1: calling pci_fixup_transparent_bridge+0x0/0x1d
[    1.574024] pci 0000:00:1c.1: PME# supported from D0 D3hot D3cold
[    1.574030] pci 0000:00:1c.1: PME# disabled
[    1.574701] pci 0000:00:1c.1: System wakeup disabled by ACPI
[    1.575303] pci 0000:00:1c.3: [8086:1c16] type 01 class 0x060400
[    1.575374] pci 0000:00:1c.3: calling pci_fixup_transparent_bridge+0x0/0x1d
[    1.575460] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold
[    1.575465] pci 0000:00:1c.3: PME# disabled
[    1.576220] pci 0000:00:1c.3: System wakeup disabled by ACPI
[    1.576821] pci 0000:00:1c.4: [8086:1c18] type 01 class 0x060400
[    1.576891] pci 0000:00:1c.4: calling pci_fixup_transparent_bridge+0x0/0x1d
[    1.576975] pci 0000:00:1c.4: PME# supported from D0 D3hot D3cold
[    1.576981] pci 0000:00:1c.4: PME# disabled
[    1.577772] pci 0000:00:1c.4: System wakeup disabled by ACPI
[    1.579703] pci 0000:00:1c.7: [8086:1c1e] type 01 class 0x060400
[    1.579773] pci 0000:00:1c.7: calling pci_fixup_transparent_bridge+0x0/0x1d
[    1.579856] pci 0000:00:1c.7: PME# supported from D0 D3hot D3cold
[    1.579862] pci 0000:00:1c.7: PME# disabled
[    1.580992] pci 0000:00:1c.7: System wakeup disabled by ACPI
[    1.581590] pci 0000:00:1d.0: [8086:1c26] type 00 class 0x0c0320
[    1.581625] pci 0000:00:1d.0: reg 10: [mem 0xf7f07000-0xf7f073ff]
[    1.581782] pci 0000:00:1d.0: PME# supported from D0 D3hot D3cold
[    1.581788] pci 0000:00:1d.0: PME# disabled
[    1.603022] pci 0000:00:1d.0: System wakeup disabled by ACPI
[    1.603663] pci 0000:00:1f.0: [8086:1c4b] type 00 class 0x060100
[    1.604394] pci 0000:00:1f.2: [8086:1c03] type 00 class 0x010601
[    1.604433] pci 0000:00:1f.2: reg 10: [io  0xf0b0-0xf0b7]
[    1.604448] pci 0000:00:1f.2: reg 14: [io  0xf0a0-0xf0a3]
[    1.604462] pci 0000:00:1f.2: reg 18: [io  0xf090-0xf097]
[    1.604476] pci 0000:00:1f.2: reg 1c: [io  0xf080-0xf083]
[    1.604491] pci 0000:00:1f.2: reg 20: [io  0xf060-0xf07f]
[    1.604507] pci 0000:00:1f.2: reg 24: [mem 0xf7f06000-0xf7f067ff]
[    1.604605] pci 0000:00:1f.2: PME# supported from D3hot
[    1.604612] pci 0000:00:1f.2: PME# disabled
[    1.606249] pci 0000:00:1f.3: [8086:1c22] type 00 class 0x0c0500
[    1.606278] pci 0000:00:1f.3: reg 10: [mem 0xf7f05000-0xf7f050ff 64bit]
[    1.606320] pci 0000:00:1f.3: reg 20: [io  0xf040-0xf05f]
[    1.607978] pci_bus 0000:00: fixups for bus
[    1.607983] pci 0000:00:1c.0: scanning [bus 03-04] behind bridge, pass 0
[    1.608424] pci_bus 0000:03: scanning bus
[    1.608427] pci_bus 0000:03: fixups for bus
[    1.608429] pci 0000:00:1c.0: PCI bridge to [bus 03-04]
[    1.608537] pci_bus 0000:03: bus scan returning with max=03
[    1.608543] pci 0000:00:1c.1: scanning [bus 05-06] behind bridge, pass 0
[    1.608980] pci_bus 0000:05: scanning bus
[    1.609031] pci 0000:05:00.0: [10ec:8168] type 00 class 0x020000
[    1.609059] pci 0000:05:00.0: reg 10: [io  0xe000-0xe0ff]
[    1.609108] pci 0000:05:00.0: reg 18: [mem 0xf1104000-0xf1104fff 64bit pref]
[    1.609138] pci 0000:05:00.0: reg 20: [mem 0xf1100000-0xf1103fff 64bit pref]
[    1.609278] pci 0000:05:00.0: supports D1 D2
[    1.609279] pci 0000:05:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    1.609286] pci 0000:05:00.0: PME# disabled
[    1.609558] pci 0000:05:00.0: System wakeup disabled by ACPI
[    1.610158] pci_bus 0000:05: fixups for bus
[    1.610160] pci 0000:00:1c.1: PCI bridge to [bus 05-06]
[    1.610257] pci 0000:00:1c.1:   bridge window [io  0xe000-0xefff]
[    1.610271] pci 0000:00:1c.1:   bridge window [mem 0xf1100000-0xf11fffff 64bit pref]
[    1.610272] pci_bus 0000:05: bus scan returning with max=05
[    1.610279] pci 0000:00:1c.3: scanning [bus 09-0a] behind bridge, pass 0
[    1.610711] pci_bus 0000:09: scanning bus
[    1.610993] pci 0000:09:00.0: [8086:008a] type 00 class 0x028000
[    1.611296] pci 0000:09:00.0: reg 10: [mem 0xf7e00000-0xf7e01fff 64bit]
[    1.612984] pci 0000:09:00.0: PME# supported from D0 D3hot D3cold
[    1.613035] pci 0000:09:00.0: PME# disabled
[    1.613422] pci 0000:09:00.0: System wakeup disabled by ACPI
[    1.614008] pci_bus 0000:09: fixups for bus
[    1.614010] pci 0000:00:1c.3: PCI bridge to [bus 09-0a]
[    1.614112] pci 0000:00:1c.3:   bridge window [mem 0xf7e00000-0xf7efffff]
[    1.614121] pci_bus 0000:09: bus scan returning with max=09
[    1.614127] pci 0000:00:1c.4: scanning [bus 0b-0c] behind bridge, pass 0
[    1.614556] pci_bus 0000:0b: scanning bus
[    1.614613] pci 0000:0b:00.0: [104c:8241] type 00 class 0x0c0330
[    1.614650] pci 0000:0b:00.0: reg 10: [mem 0xf7d00000-0xf7d0ffff 64bit]
[    1.614678] pci 0000:0b:00.0: reg 18: [mem 0xf7d10000-0xf7d11fff 64bit]
[    1.614842] pci 0000:0b:00.0: supports D1 D2
[    1.614844] pci 0000:0b:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    1.614851] pci 0000:0b:00.0: PME# disabled
[    1.615100] pci 0000:0b:00.0: System wakeup disabled by ACPI
[    1.615692] pci_bus 0000:0b: fixups for bus
[    1.615693] pci 0000:00:1c.4: PCI bridge to [bus 0b-0c]
[    1.615795] pci 0000:00:1c.4:   bridge window [mem 0xf7d00000-0xf7dfffff]
[    1.615804] pci_bus 0000:0b: bus scan returning with max=0b
[    1.615810] pci 0000:00:1c.7: scanning [bus 11-16] behind bridge, pass 0
[    1.616238] pci_bus 0000:11: scanning bus
[    1.616292] pci 0000:11:00.0: [1095:3132] type 00 class 0x018000
[    1.616334] pci 0000:11:00.0: reg 10: [mem 0xf6c84000-0xf6c8407f 64bit]
[    1.616367] pci 0000:11:00.0: reg 18: [mem 0xf6c80000-0xf6c83fff 64bit]
[    1.616389] pci 0000:11:00.0: reg 20: [io  0xc000-0xc07f]
[    1.616431] pci 0000:11:00.0: reg 30: [mem 0xf6c00000-0xf6c7ffff pref]
[    1.616546] pci 0000:11:00.0: supports D1 D2
[    1.617192] pci_bus 0000:11: fixups for bus
[    1.617193] pci 0000:00:1c.7: PCI bridge to [bus 11-16]
[    1.617292] pci 0000:00:1c.7:   bridge window [io  0xc000-0xdfff]
[    1.617297] pci 0000:00:1c.7:   bridge window [mem 0xf6c00000-0xf7cfffff]
[    1.617307] pci 0000:00:1c.7:   bridge window [mem 0xf0000000-0xf10fffff 64bit pref]
[    1.617308] pci_bus 0000:11: bus scan returning with max=11
[    1.617314] pci 0000:00:1c.0: scanning [bus 03-04] behind bridge, pass 1
[    1.617324] pci 0000:00:1c.1: scanning [bus 05-06] behind bridge, pass 1
[    1.617333] pci 0000:00:1c.3: scanning [bus 09-0a] behind bridge, pass 1
[    1.617342] pci 0000:00:1c.4: scanning [bus 0b-0c] behind bridge, pass 1
[    1.617351] pci 0000:00:1c.7: scanning [bus 11-16] behind bridge, pass 1
[    1.617358] pci_bus 0000:00: bus scan returning with max=16
[    1.617359] ACPI _OSC control for PCIe not granted, disabling ASPM
[    1.624464] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 10 *11 12 14 15)
[    1.626424] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 *5 6 10 11 12 14 15)
[    1.628384] ACPI: PCI Interrupt Link [LNKC] (IRQs *3 4 5 6 10 11 12 14 15)
[    1.630341] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 6 *10 11 12 14 15)
[    1.632286] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 6 10 11 12 14 15) *0, disabled.
[    1.634296] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 6 10 11 12 14 15) *0, disabled.
[    1.636320] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 *5 6 10 11 12 14 15)
[    1.638286] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 *5 6 10 11 12 14 15)
[    1.641066] ACPI: Enabled 4 GPEs in block 00 to 3F
[    1.641085] acpi root: \_SB_.PCI0 notify handler is installed
[    1.641253] Found 1 acpi root devices


You see, the 11:00 does not say: 'System wakeup disabled by ACPI'?

Len, if you wat to get acpidump and full dmesg I can send it to you directly. Custom
DSDT?


--
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
Rafael Wysocki April 1, 2013, 12:14 a.m. UTC | #4
On Monday, April 01, 2013 01:17:20 AM Martin Mokrejs wrote:
> [ also +Len Brown -- would you please comment what the ACPI-related bug in BIOS
>  could be causing? Should be the message be logged also under 3.8.3? It does
>  NOT happen! ]

What BIOS bug are you talking about?

Man, it is *so* *hard* to find useful information in your posting.  Can you
please try to be less chaotic?

Rafael
Huang, Ying April 1, 2013, 7:33 a.m. UTC | #5
On Sun, 2013-03-31 at 17:04 +0200, Martin Mokrejs wrote:
> Hi Ying,
>   
> Huang Ying wrote:
> > Hi, Martin,
> > 
> > Thanks for your testing!
> > 
> > On Sun, 2013-03-31 at 12:35 +0200, Martin Mokrejs wrote:
> >> Hi Ying,
> >>   I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
> >> when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
> >> enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
> >> and kmemleaks.
> >>   I removed the coldbooted card, inserted it and ejected it.
> >>
> >>
> >>   In brief, lspci reports changes but there are no changes in /proc/interrupts
> >> related to
> >>
> >>   19:          0          0   IO-APIC-fasteoi   sata_sil24
> >>
> >>
> >> and no changes at all in /proc/iomem which I expected to happen during
> >> hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).
> >>
> >> All the runtime_status data were same after every tested step, so again,
> >> no diffs to show but here are the values confirming laptop-mode-tools
> >> enabled powersaving:
> >>
> >> /sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
> >> /sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
> >> /sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
> >> /sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
> >> /sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
> >> /sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
> >> /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
> >> /sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
> >> /sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
> >> /sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
> > 
> > It appears that 1c.7 is identified successfully as an hotplug-able PCIe
> > port, and never put into suspended state.
> 
> Yes. Truly said, after I now went to test your previous two patches
> on the 3.9-rc1 I confirm that the syslog logging is broken with all your
> three patches. I fear we are hitting here, with the pciehp problems
> not a powersaving issue but an upstream /proc or /sys files being outdated.
> Otherwise I can't figure out why disabling in runtime laptop-mode-tools
> and doing the "find /sys .... | while ... echo "on" > $f" trickery
> does not help to get pciehp working. This would have fixed the acpiphp
> at least on 3.8 kernel. I see that sata_sil24 is not loaded by itself
> during hotinsert. It seems lspci reports at such times 0xff for the 11:00
> eSATA card, /etc/iomem reports stale memory regions used by 11:00 while
> /proc/interrupts says no IRQ is assigned to sata_sil24 (well, sata_sil24
> is not loaded per lsmod, lspci would should report sata_sil24 also but
> provided the 11:00 entry is broken and shows the 0xff it maybe cannot
> report is sata_sil24 is loaded).
> 
> I will post a little more details as a proper answer to your other patch
> where I managed to get yet another stacktrace, about the eSATA thought to
> be D3 state. Physically the card was ejected and just a modprobe sata_sil24
> caused the sata_sil24 to use some outdated data. I will dive now into
> that. 
> 
> 
> 
> > 
> > And from your description below, it appears that hot-add and hot-remove
> > of the eSATA card works for you, doesn't it?
> 
> The PresDet works fine I think, yes. Sometimes I see in the lspci -vvv diffs:
> 
> -Control: I/O+ ... BusMaster+
> +Control: I/O- ... BusMaster-

But after hot-insert, can you use your eSATA card?  It appears that it
is detected properly.

> and sometimes 
> 
> -        Latency: 0, Cache Line Size: 64 bytes
> +        Latency: 0
> 
> or even the Latency: line being gone completely from lspci -vvv output. Why is that?
> I think debug checks and prints in kernel are necessary.
> 
> 
> How do these related to /proc/interrupts not showing an IRQ for the 11:00 device?
> Does that prevent automated sata_sil24 loading once the card is inserted? Would
> you please add some extra debug prints and checks into the kernel?
> 
> Take also into consideration the "3.8.2: stale pci device info for a previously inserted express card"
> for a list of chimeric entries reported by lspci. That could tell you which values
> are being cached and invalid. Hopefully some checks could be done between values
> read by lspci and those in /proc and /sys.
> 
> 
> 
> Do you already know why almost nothing is logged by kernel wen either of your
> three patches (v1 sent on 03/29/13 08:41, v2 sent on 03/29/13 09:20, v3 sent on
> 03/30/13 11:54)?

No.  Don't know why.  unpatched upstream kernel can produce kernel log?

Best Regards,
Huang Ying

> I did not test the xHCI port behavior with any of your three patches because I have
> disabled USB support in this kernel altogether for 3.9-rc1 tests. And I would like to stick
> with that until we fix the pciehp issue. I stepped rather late into the big testing game,
> I believe the pciehp bug we are facing was not working since 3.5/3.6, I don't think
> the 3.9-rc1-based tests be much different from earlier kernels.
> 
> For a broader view, on the 3.8 series we will meanwhile hopefully get to a fix of the
> PME# stuff. I think I reported quite a good number of potential problems yesterday.
> After that, I will check how xHCI behaves on 3.9 but I believe the PME#-related fix from
> 3.8 will be also applicable to fixing 3.9 so the xHCI won't have problems there anymore.
> 
> 
> Martin


--
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
Martin Mokrejs April 1, 2013, 12:06 p.m. UTC | #6
Rafael J. Wysocki wrote:
> On Monday, April 01, 2013 01:17:20 AM Martin Mokrejs wrote:
>> [ also +Len Brown -- would you please comment what the ACPI-related bug in BIOS
>>  could be causing? Should be the message be logged also under 3.8.3? It does
>>  NOT happen! ]
> 
> What BIOS bug are you talking about?

ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20130117/hwxface-568)

> 
> Man, it is *so* *hard* to find useful information in your posting.  Can you
> please try to be less chaotic?

I am trying to do my best but testing 2 kernel versions, 3 patches, two functional issues:
1) XHCI port dead 2) express card hotplug
Don't be surprised there are multiple threads. Feel free to close the whole story
if you come up with a big debug patch covering whatever appeared like a potential
bug in my reports. Or where a bug seems to manifest. Just improve debug kernel info.
Then it will be easier I am sure. For me it is also not easy to test all of this.
Just comment my findings in the emails.

Martin
--
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
Martin Mokrejs April 1, 2013, 5:23 p.m. UTC | #7
Huang Ying wrote:
> On Sun, 2013-03-31 at 17:04 +0200, Martin Mokrejs wrote:
>> Hi Ying,
>>   
>> Huang Ying wrote:
>>> Hi, Martin,
>>>
>>> Thanks for your testing!
>>>
>>> On Sun, 2013-03-31 at 12:35 +0200, Martin Mokrejs wrote:
>>>> Hi Ying,
>>>>   I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
>>>> when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
>>>> enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
>>>> and kmemleaks.
>>>>   I removed the coldbooted card, inserted it and ejected it.
>>>>
>>>>
>>>>   In brief, lspci reports changes but there are no changes in /proc/interrupts
>>>> related to
>>>>
>>>>   19:          0          0   IO-APIC-fasteoi   sata_sil24
>>>>
>>>>
>>>> and no changes at all in /proc/iomem which I expected to happen during
>>>> hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).
>>>>
>>>> All the runtime_status data were same after every tested step, so again,
>>>> no diffs to show but here are the values confirming laptop-mode-tools
>>>> enabled powersaving:
>>>>
>>>> /sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
>>>> /sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
>>>> /sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
>>>> /sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
>>>> /sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
>>>> /sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
>>>> /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
>>>> /sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
>>>> /sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
>>>> /sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
>>>
>>> It appears that 1c.7 is identified successfully as an hotplug-able PCIe
>>> port, and never put into suspended state.
>>
>> Yes. Truly said, after I now went to test your previous two patches
>> on the 3.9-rc1 I confirm that the syslog logging is broken with all your
>> three patches. I fear we are hitting here, with the pciehp problems
>> not a powersaving issue but an upstream /proc or /sys files being outdated.
>> Otherwise I can't figure out why disabling in runtime laptop-mode-tools
>> and doing the "find /sys .... | while ... echo "on" > $f" trickery
>> does not help to get pciehp working. This would have fixed the acpiphp
>> at least on 3.8 kernel. I see that sata_sil24 is not loaded by itself
>> during hotinsert. It seems lspci reports at such times 0xff for the 11:00
>> eSATA card, /etc/iomem reports stale memory regions used by 11:00 while
>> /proc/interrupts says no IRQ is assigned to sata_sil24 (well, sata_sil24
>> is not loaded per lsmod, lspci would should report sata_sil24 also but
>> provided the 11:00 entry is broken and shows the 0xff it maybe cannot
>> report is sata_sil24 is loaded).
>>
>> I will post a little more details as a proper answer to your other patch
>> where I managed to get yet another stacktrace, about the eSATA thought to
>> be D3 state. Physically the card was ejected and just a modprobe sata_sil24
>> caused the sata_sil24 to use some outdated data. I will dive now into
>> that. 
>>
>>
>>
>>>
>>> And from your description below, it appears that hot-add and hot-remove
>>> of the eSATA card works for you, doesn't it?
>>
>> The PresDet works fine I think, yes. Sometimes I see in the lspci -vvv diffs:
>>
>> -Control: I/O+ ... BusMaster+
>> +Control: I/O- ... BusMaster-
> 
> But after hot-insert, can you use your eSATA card?  It appears that it
> is detected properly.

Can't say about the above two. But under pciehp what is broken is the hotremoval.
I think the rest is just a downstream consequence.

> 
>> and sometimes 
>>
>> -        Latency: 0, Cache Line Size: 64 bytes
>> +        Latency: 0

It seems to me that bridges in lspci output have 'Latency: 0' while end devices have
the Cache Line Size as well.

When the card is hot inserted after a previous hot removal and seems "dead" then
lspci says:
Control: I/O- Mem- BusMaster-
Interrupt: pin A routed to IRQ 19
and no 'Latency:' and no 'Cache Line Size:' are the output of the 11:00  device.

But please realize this is likely screwed because a previous eject of the card did not
fully release resources. When the slot was empty lspci reported 0xff and when it is
loaded it likely reports some crap. Unless the bug causing 'stale' data to be reported
(the 'Re: 3.8.2: stale pci device info for a previously inserted express card' thread)
I wonder what can we trust in this output.

>>
>> or even the Latency: line being gone completely from lspci -vvv output. Why is that?
>> I think debug checks and prints in kernel are necessary.
>>
>>
>> How do these related to /proc/interrupts not showing an IRQ for the 11:00 device?
>> Does that prevent automated sata_sil24 loading once the card is inserted? Would
>> you please add some extra debug prints and checks into the kernel?
>>
>> Take also into consideration the "3.8.2: stale pci device info for a previously inserted express card"
>> for a list of chimeric entries reported by lspci. That could tell you which values
>> are being cached and invalid. Hopefully some checks could be done between values
>> read by lspci and those in /proc and /sys.
>>
>>
>>
>> Do you already know why almost nothing is logged by kernel wen either of your
>> three patches (v1 sent on 03/29/13 08:41, v2 sent on 03/29/13 09:20, v3 sent on
>> 03/30/13 11:54)?
> 
> No.  Don't know why.  unpatched upstream kernel can produce kernel log?

OK, vanilla 3.9-rc1 also prints nothing to syslog relevant to hotplug (only pciehp
tested). Logging itself works, as I said, rmmod sata_sil24 is logged. So, sorry,
your patches did NOT break logging.

Martin


> 
> Best Regards,
> Huang Ying
> 
>> I did not test the xHCI port behavior with any of your three patches because I have
>> disabled USB support in this kernel altogether for 3.9-rc1 tests. And I would like to stick
>> with that until we fix the pciehp issue. I stepped rather late into the big testing game,
>> I believe the pciehp bug we are facing was not working since 3.5/3.6, I don't think
>> the 3.9-rc1-based tests be much different from earlier kernels.
>>
>> For a broader view, on the 3.8 series we will meanwhile hopefully get to a fix of the
>> PME# stuff. I think I reported quite a good number of potential problems yesterday.
>> After that, I will check how xHCI behaves on 3.9 but I believe the PME#-related fix from
>> 3.8 will be also applicable to fixing 3.9 so the xHCI won't have problems there anymore.
>>
>>
>> Martin
> 
> 
> 
--
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
Martin Mokrejs April 30, 2013, 9:09 p.m. UTC | #8
Hi,
  I went to test final 3.9 kernel and was almost ready to report no difference
in pciehp and *no hotplug functionality of either of my 3 express cards*. But ...
I also tested change from pcie_aspm=off to pcie_aspm=native and hot events started
to work!
So, I would like to ask you to review the code affected by both values aiming
to find an explanation. You have the collected data available and email archives
so I believe this should be easy now for you.

  If you want to compare with 3.9 kernel then I uploaded collected with pciehp
under 3.9 kernel to http://195.113.57.32/~mmokrejs/tmp/20130430.tar.bz2 .
The 3.8.8 data is acpiphp testing, so ignore it for this thread.

Thank you,
Martin

Martin Mokrejs wrote:
> Huang Ying wrote:
>> On Sun, 2013-03-31 at 17:04 +0200, Martin Mokrejs wrote:
>>> Hi Ying,
>>>   
>>> Huang Ying wrote:
>>>> Hi, Martin,
>>>>
>>>> Thanks for your testing!
>>>>
>>>> On Sun, 2013-03-31 at 12:35 +0200, Martin Mokrejs wrote:
>>>>> Hi Ying,
>>>>>   I have tested 4x your last patch. Somehow nothing gets logged to "dmesg"
>>>>> when I hotremove or hotinsert the coldbooted eSATA card. Logging works so
>>>>> enabling wifi via Fn+F2 is being logged. Also, eventual stacktraces
>>>>> and kmemleaks.
>>>>>   I removed the coldbooted card, inserted it and ejected it.
>>>>>
>>>>>
>>>>>   In brief, lspci reports changes but there are no changes in /proc/interrupts
>>>>> related to
>>>>>
>>>>>   19:          0          0   IO-APIC-fasteoi   sata_sil24
>>>>>
>>>>>
>>>>> and no changes at all in /proc/iomem which I expected to happen during
>>>>> hotremoval and hotinsert (something broken in 3.9-rc1 with your patch).
>>>>>
>>>>> All the runtime_status data were same after every tested step, so again,
>>>>> no diffs to show but here are the values confirming laptop-mode-tools
>>>>> enabled powersaving:
>>>>>
>>>>> /sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
>>>>> /sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
>>>>> /sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
>>>>> /sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:suspended
>>>>> /sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
>>>>> /sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
>>>>> /sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
>>>>> /sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
>>>>> /sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:active
>>>>> /sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
>>>>
>>>> It appears that 1c.7 is identified successfully as an hotplug-able PCIe
>>>> port, and never put into suspended state.
>>>
>>> Yes. Truly said, after I now went to test your previous two patches
>>> on the 3.9-rc1 I confirm that the syslog logging is broken with all your
>>> three patches. I fear we are hitting here, with the pciehp problems
>>> not a powersaving issue but an upstream /proc or /sys files being outdated.
>>> Otherwise I can't figure out why disabling in runtime laptop-mode-tools
>>> and doing the "find /sys .... | while ... echo "on" > $f" trickery
>>> does not help to get pciehp working. This would have fixed the acpiphp
>>> at least on 3.8 kernel. I see that sata_sil24 is not loaded by itself
>>> during hotinsert. It seems lspci reports at such times 0xff for the 11:00
>>> eSATA card, /etc/iomem reports stale memory regions used by 11:00 while
>>> /proc/interrupts says no IRQ is assigned to sata_sil24 (well, sata_sil24
>>> is not loaded per lsmod, lspci would should report sata_sil24 also but
>>> provided the 11:00 entry is broken and shows the 0xff it maybe cannot
>>> report is sata_sil24 is loaded).
>>>
>>> I will post a little more details as a proper answer to your other patch
>>> where I managed to get yet another stacktrace, about the eSATA thought to
>>> be D3 state. Physically the card was ejected and just a modprobe sata_sil24
>>> caused the sata_sil24 to use some outdated data. I will dive now into
>>> that. 
>>>
>>>
>>>
>>>>
>>>> And from your description below, it appears that hot-add and hot-remove
>>>> of the eSATA card works for you, doesn't it?
>>>
>>> The PresDet works fine I think, yes. Sometimes I see in the lspci -vvv diffs:
>>>
>>> -Control: I/O+ ... BusMaster+
>>> +Control: I/O- ... BusMaster-
>>
>> But after hot-insert, can you use your eSATA card?  It appears that it
>> is detected properly.
> 
> Can't say about the above two. But under pciehp what is broken is the hotremoval.
> I think the rest is just a downstream consequence.
> 
>>
>>> and sometimes 
>>>
>>> -        Latency: 0, Cache Line Size: 64 bytes
>>> +        Latency: 0
> 
> It seems to me that bridges in lspci output have 'Latency: 0' while end devices have
> the Cache Line Size as well.
> 
> When the card is hot inserted after a previous hot removal and seems "dead" then
> lspci says:
> Control: I/O- Mem- BusMaster-
> Interrupt: pin A routed to IRQ 19
> and no 'Latency:' and no 'Cache Line Size:' are the output of the 11:00  device.
> 
> But please realize this is likely screwed because a previous eject of the card did not
> fully release resources. When the slot was empty lspci reported 0xff and when it is
> loaded it likely reports some crap. Unless the bug causing 'stale' data to be reported
> (the 'Re: 3.8.2: stale pci device info for a previously inserted express card' thread)
> I wonder what can we trust in this output.
> 
>>>
>>> or even the Latency: line being gone completely from lspci -vvv output. Why is that?
>>> I think debug checks and prints in kernel are necessary.
>>>
>>>
>>> How do these related to /proc/interrupts not showing an IRQ for the 11:00 device?
>>> Does that prevent automated sata_sil24 loading once the card is inserted? Would
>>> you please add some extra debug prints and checks into the kernel?
>>>
>>> Take also into consideration the "3.8.2: stale pci device info for a previously inserted express card"
>>> for a list of chimeric entries reported by lspci. That could tell you which values
>>> are being cached and invalid. Hopefully some checks could be done between values
>>> read by lspci and those in /proc and /sys.
>>>
>>>
>>>
>>> Do you already know why almost nothing is logged by kernel wen either of your
>>> three patches (v1 sent on 03/29/13 08:41, v2 sent on 03/29/13 09:20, v3 sent on
>>> 03/30/13 11:54)?
>>
>> No.  Don't know why.  unpatched upstream kernel can produce kernel log?
> 
> OK, vanilla 3.9-rc1 also prints nothing to syslog relevant to hotplug (only pciehp
> tested). Logging itself works, as I said, rmmod sata_sil24 is logged. So, sorry,
> your patches did NOT break logging.
> 
> Martin
> 
> 
>>
>> Best Regards,
>> Huang Ying
>>
>>> I did not test the xHCI port behavior with any of your three patches because I have
>>> disabled USB support in this kernel altogether for 3.9-rc1 tests. And I would like to stick
>>> with that until we fix the pciehp issue. I stepped rather late into the big testing game,
>>> I believe the pciehp bug we are facing was not working since 3.5/3.6, I don't think
>>> the 3.9-rc1-based tests be much different from earlier kernels.
>>>
>>> For a broader view, on the 3.8 series we will meanwhile hopefully get to a fix of the
>>> PME# stuff. I think I reported quite a good number of potential problems yesterday.
>>> After that, I will check how xHCI behaves on 3.9 but I believe the PME#-related fix from
>>> 3.8 will be also applicable to fixing 3.9 so the xHCI won't have problems there anymore.
>>>
>>>
>>> Martin
>>
>>
>>
> --
> 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
> 
> 
--
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
diff mbox

Patch

--- lspci_vvv_initial.txt       2013-03-31 12:01:05.000000000 +0200
+++ lspci_vvv_ejected.txt       2013-03-31 12:01:24.000000000 +0200
@@ -293,7 +293,7 @@ 
        I/O behind bridge: 0000c000-0000dfff
        Memory behind bridge: f6c00000-f7cfffff
        Prefetchable memory behind bridge: 00000000f0000000-00000000f10fffff
-       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- <SERR- <PERR-
+       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort+ <SERR- <PERR-
        BridgeCtl: Parity- SERR- NoISA- VGA- MAbort- >Reset- FastB2B-
                PriDiscTmr- SecDiscTmr- DiscTmrStat- DiscTmrSERREn-
        Capabilities: [40] Express (v2) Root Port (Slot+), MSI 00
@@ -307,13 +307,13 @@ 
                        ClockPM- Surprise- LLActRep+ BwNot-
                LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
+               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
                SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
                        Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
                SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
                        Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
-               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
-                       Changed: MRL- PresDet- LinkState-
+               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
+                       Changed: MRL- PresDet- LinkState+
                RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
                RootCap: CRSVisible-
                RootSta: PME ReqID 0000, PMEStatus- PMEPending-
@@ -521,39 +521,7 @@ 
                AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
        Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
 
-11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
-       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
-       Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
-       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
-       Latency: 0, Cache Line Size: 64 bytes
-       Interrupt: pin A routed to IRQ 19
-       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [size=128]
-       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [size=16K]
-       Region 4: I/O ports at c000 [size=128]
-       Expansion ROM at f6c00000 [disabled] [size=512K]
-       Capabilities: [54] Power Management version 2
-               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
-               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
-       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
-               Address: 0000000000000000  Data: 0000
-       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
-               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
-                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
-               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
-                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
-                       MaxPayload 128 bytes, MaxReadReq 4096 bytes
-               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
-               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
-                       ClockPM- Surprise- LLActRep- BwNot-
-               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
-                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
-       Capabilities: [100 v1] Advanced Error Reporting
-               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
-               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
-               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
-               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
-               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
-               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
+11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
+       !!! Unknown header type 7f
        Kernel driver in use: sata_sil24
 

The after a hotinsert I see:

--- lspci_vvv_ejected.txt       2013-03-31 12:01:24.000000000 +0200
+++ lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
@@ -307,12 +307,12 @@ 
                        ClockPM- Surprise- LLActRep+ BwNot-
                LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
+               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
                SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
                        Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
                SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
                        Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
-               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
+               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
                        Changed: MRL- PresDet- LinkState+
                RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
                RootCap: CRSVisible-
@@ -521,7 +521,38 @@ 
                AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
        Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
 
-11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
-       !!! Unknown header type 7f
+11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
+       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
+       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
+       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
+       Interrupt: pin A routed to IRQ 19
+       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
+       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
+       Region 4: I/O ports at c000 [disabled] [size=128]
+       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
+       Capabilities: [54] Power Management version 2
+               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
+               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
+       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
+               Address: 0000000000000000  Data: 0000
+       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
+               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
+                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
+               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
+                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
+                       MaxPayload 128 bytes, MaxReadReq 512 bytes
+               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
+               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
+                       ClockPM- Surprise- LLActRep- BwNot-
+               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
+                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
+               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
+       Capabilities: [100 v1] Advanced Error Reporting
+               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
+               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
+               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
+               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
+               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
+               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
        Kernel driver in use: sata_sil24
 


The last hotremoval caused:

--- lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
+++ lspci_vvv_ejected_and_reinserted_ejected.txt        2013-03-31 12:03:16.000000000 +0200
@@ -307,12 +307,12 @@ 
                        ClockPM- Surprise- LLActRep+ BwNot-
                LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive+ BWMgmt+ ABWMgmt-
+               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt+ ABWMgmt-
                SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug+ Surprise+
                        Slot #7, PowerLimit 10.000W; Interlock- NoCompl+
                SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
                        Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
-               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
+               SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
                        Changed: MRL- PresDet- LinkState+
                RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
                RootCap: CRSVisible-
@@ -521,38 +521,7 @@ 
                AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
        Capabilities: [150 v1] Device Serial Number 08-00-28-00-00-20-00-00
 
-11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
-       Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
-       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
-       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
-       Interrupt: pin A routed to IRQ 19
-       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
-       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
-       Region 4: I/O ports at c000 [disabled] [size=128]
-       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
-       Capabilities: [54] Power Management version 2
-               Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
-               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
-       Capabilities: [5c] MSI: Enable- Count=1/1 Maskable- 64bit+
-               Address: 0000000000000000  Data: 0000
-       Capabilities: [70] Express (v1) Legacy Endpoint, MSI 00
-               DevCap: MaxPayload 1024 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
-                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
-               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
-                       RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
-                       MaxPayload 128 bytes, MaxReadReq 512 bytes
-               DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
-               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
-                       ClockPM- Surprise- LLActRep- BwNot-
-               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
-                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
-               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
-       Capabilities: [100 v1] Advanced Error Reporting
-               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq+ ACSViol-
-               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
-               UESvrt: DLP+ SDES- TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
-               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
-               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
-               AERCap: First Error Pointer: 14, GenCap+ CGenEn- ChkCap+ ChkEn-
+11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev ff) (prog-if ff)
+       !!! Unknown header type 7f
        Kernel driver in use: sata_sil24
 




Maybe I should, unlike in most previous reports, show a diff between a colplugged state
and the hotinserted states:

--- lspci_vvv_initial.txt       2013-03-31 12:01:05.000000000 +0200
+++ lspci_vvv_ejected_and_reinserted.txt        2013-03-31 12:02:24.000000000 +0200
@@ -293,7 +293,7 @@ 
        I/O behind bridge: 0000c000-0000dfff
        Memory behind bridge: f6c00000-f7cfffff
        Prefetchable memory behind bridge: 00000000f0000000-00000000f10fffff
-       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- <SERR- <PERR-
+       Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort+ <SERR- <PERR-
        BridgeCtl: Parity- SERR- NoISA- VGA- MAbort- >Reset- FastB2B-
                PriDiscTmr- SecDiscTmr- DiscTmrStat- DiscTmrSERREn-
        Capabilities: [40] Express (v2) Root Port (Slot+), MSI 00
@@ -313,7 +313,7 @@ 
                SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
                        Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
                SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet+ Interlock-
-                       Changed: MRL- PresDet- LinkState-
+                       Changed: MRL- PresDet- LinkState+
                RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
                RootCap: CRSVisible-
                RootSta: PME ReqID 0000, PMEStatus- PMEPending-
@@ -523,14 +523,13 @@ 
 
 11:00.0 Mass storage controller: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller (rev 01)
        Subsystem: Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
-       Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
+       Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
-       Latency: 0, Cache Line Size: 64 bytes
        Interrupt: pin A routed to IRQ 19
-       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [size=128]
-       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [size=16K]
-       Region 4: I/O ports at c000 [size=128]
-       Expansion ROM at f6c00000 [disabled] [size=512K]
+       Region 0: Memory at f6c84000 (64-bit, non-prefetchable) [disabled] [size=128]
+       Region 2: Memory at f6c80000 (64-bit, non-prefetchable) [disabled] [size=16K]
+       Region 4: I/O ports at c000 [disabled] [size=128]
+       [virtual] Expansion ROM at f6c00000 [disabled] [size=512K]
        Capabilities: [54] Power Management version 2
                Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=1 PME-
@@ -541,7 +540,7 @@ 
                        ExtTag- AttnBtn- AttnInd- PwrInd- RBE- FLReset-
                DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                        RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
-                       MaxPayload 128 bytes, MaxReadReq 4096 bytes
+                       MaxPayload 128 bytes, MaxReadReq 512 bytes
                DevSta: CorrErr- UncorrErr+ FatalErr- UnsuppReq+ AuxPwr- TransPend-
                LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s, Latency L0 unlimited, L1 unlimited
                        ClockPM- Surprise- LLActRep- BwNot-