Bug 208117 - rtsx_pci not restoring ASPM state after suspend/resume
Summary: rtsx_pci not restoring ASPM state after suspend/resume
Status: REOPENED
Alias: None
Product: Drivers
Classification: Unclassified
Component: MMC/SD (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Len Brown
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-06-09 21:35 UTC by James Ettle
Modified: 2020-08-02 16:27 UTC (History)
2 users (show)

See Also:
Kernel Version: 5.6.19
Tree: Mainline
Regression: No


Attachments
dmesg after suspend/resume cycle (88.29 KB, text/plain)
2020-06-09 21:35 UTC, James Ettle
Details
Typical post suspend/resume powertop screen (4.34 KB, text/plain)
2020-06-09 21:36 UTC, James Ettle
Details
turbostat output before suspend/resume (16.90 KB, text/plain)
2020-06-09 21:37 UTC, James Ettle
Details
turbostat output after suspend/resume (16.90 KB, text/plain)
2020-06-09 21:41 UTC, James Ettle
Details
lspci -s:01:00 -vvxxx before suspend (9.15 KB, text/plain)
2020-07-22 12:40 UTC, James Ettle
Details
lspci -s:01:00 -vvxxx after resume (9.16 KB, text/plain)
2020-07-22 12:40 UTC, James Ettle
Details
lspci -vvxxx for the bridge before suspend (4.76 KB, text/plain)
2020-07-23 13:10 UTC, James Ettle
Details
lspci -vvxxx for the bridge after resume (9.16 KB, text/plain)
2020-07-23 13:11 UTC, James Ettle
Details
lspci -vvxxx for the bridge after resume (4.76 KB, text/plain)
2020-07-23 13:13 UTC, James Ettle
Details
lspci -vvs 01:00 before suspend (no manual ASPM adjustments) (1.89 KB, text/plain)
2020-07-27 19:22 UTC, James Ettle
Details
lspci -vvs 00:1d.0 before suspend (no manual ASPM adjustments) (622 bytes, text/plain)
2020-07-27 19:22 UTC, James Ettle
Details
lspci -vvs 00:1d.0 after resume (no manual ASPM adjustments) (622 bytes, text/plain)
2020-07-27 19:23 UTC, James Ettle
Details
lspci -vvs 01:00 after resume (no manual ASPM adjustments) (1.89 KB, text/plain)
2020-07-27 19:23 UTC, James Ettle
Details
dmesg output from 5.7.10 with pci=earlydump (105.14 KB, text/plain)
2020-07-28 20:48 UTC, James Ettle
Details
dmesg output with Bjorn's debug patch (79.20 KB, text/plain)
2020-08-02 16:27 UTC, James Ettle
Details

Description James Ettle 2020-06-09 21:35:34 UTC
Created attachment 289585 [details]
dmesg after suspend/resume cycle

Following a suspend/resume cycle, my laptop's i5-10210U processor stops using deep package C-states (C6 and deeper).

When just booted, typical PC-state usage looks like:

# cat /sys/kernel/debug/pmc_core/package_cstate_show
Package C2 : 8981932
Package C3 : 6164143
Package C6 : 6819743
Package C7 : 15780
Package C8 : 36092391
Package C9 : 0
Package C10 : 0

and it'll go PC9/10 if I allow the screen to turn off. After a suspend-to-RAM/resume cycle, this becomes:

# cat /sys/kernel/debug/pmc_core/package_cstate_show
Package C2 : 3824217
Package C3 : 15955639
Package C6 : 896130   <- these
Package C7 : 3145     <- never
Package C8 : 4139578  <- increase
Package C9 : 0
Package C10 : 0

It looks like the processor briefly uses PC6-8 early in resume, but at some point afterwards never does, and it's not obvious to me from powertop what's preventing it. Laptop uses integrated graphics.

All powertop's recommendations have been applied. I've attached dmesg incorporating the suspend/resume, powertop screenshot after resume, and turbostat outputs before and after the suspend/resume.
Comment 1 James Ettle 2020-06-09 21:36:04 UTC
Created attachment 289587 [details]
Typical post suspend/resume powertop screen
Comment 2 James Ettle 2020-06-09 21:37:12 UTC
Created attachment 289589 [details]
turbostat output before suspend/resume
Comment 3 James Ettle 2020-06-09 21:41:11 UTC
Created attachment 289591 [details]
turbostat output after suspend/resume

Possible clues here (just superficial difference scanning):
line 24 - cpu3 C1E auto-promotion disabled before suspend, cpu6 C1E auto-promotion enabled after resume.
line 53 - MSR_HWP_CAPABILITIES eff 10 before, 8 after
Comment 4 James Ettle 2020-06-19 13:04:57 UTC
It looks like this is due to a driver not resetting the ASPM state after resume. Possible candidates are either rtsx_pci_sdmmc or r8196 corresponding respectively to 

01:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. RTL8411B PCI Express Card Reader [10ec:5287] (rev 01)
01:00.1 Ethernet controller [0200]: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller [10ec:8168] (rev 12)

Now by default l1_aspm = 0 for these devices, and link/l1_aspm is linked together for the two devices in sysfs (i.e. I can't set them independently) so I set it to 1 using udev.

rtsx_pci_sdmmc seems to be the more likely culprit as if I remove the driver, the l1_aspm state of the r8169 driver doesn't affect whether pc8 is reached.
Comment 5 James Ettle 2020-06-25 22:10:54 UTC
Component changed to MMC drivers -- looks like rtsx_pci isn't restoring the pre-suspend ASPM state. It also appears to be switching ASPM off when rtsx_pci_sdmmc is loaded (judging by the package C-state occupancy in powertop) even though it's showing as on in sysfs.
Comment 6 James Ettle 2020-07-04 14:22:30 UTC
Having looked up more on PCI 'functions', I'm remarking here that RTL8411B is a multi-function device that acts as both an r8169 ethernet chip and rtsx_pci card reader. Wonder if this is causing confusion.

https://www.realtek.com/en/products/communications-network-ics/item/rtl8411b-n
Comment 7 Bjorn Helgaas 2020-07-21 20:46:46 UTC
James, would you mind attaching the output of "sudo lspci -s01:00.0 -vvxxx"?  Maybe once before suspend and another after resume?

A PCI driver should not be responsible for saving/restoring ASPM state.  ASPM *should* be managed completely by the PCI core without any driver involvement.
But those rtsx drivers do muck with ASPM.  I don't know whether it's to work around hardware errata or to work around deficiencies in the PCI core or what.  But in any event, it's not surprising that something's broken.
Comment 8 James Ettle 2020-07-22 12:40:27 UTC
Created attachment 290443 [details]
lspci -s:01:00 -vvxxx before suspend
Comment 9 James Ettle 2020-07-22 12:40:46 UTC
Created attachment 290445 [details]
lspci -s:01:00 -vvxxx after resume
Comment 10 James Ettle 2020-07-22 12:43:00 UTC
(In reply to Bjorn Helgaas from comment #7)
> James, would you mind attaching the output of "sudo lspci -s01:00.0 -vvxxx"?
> Maybe once before suspend and another after resume?

Please find the requested output attached. A few notes:
- I did it for -s01:00 (so both functions, including the ethernet part);
- in both cases (before suspend and after resume) there were two 'pcilib: sysfs_read_vpd: read failed: Input/output error' error reported;
- I manually enable ASPM on this device on boot using a udev rule.
Comment 11 James Ettle 2020-07-22 14:38:15 UTC
(In reply to Bjorn Helgaas from comment #7)

> But those rtsx drivers do muck with ASPM.  I don't know whether it's to work
> around hardware errata or to work around deficiencies in the PCI core or
> what.  But in any event, it's not surprising that something's broken.

To be honest I've not used the card-reader that much, but it seems (based upon powertop observations of package C-states) that ASPM is turned off for this device as soon as there's any activity on it, even if manually switched on before.

For example:

1. Enable ASPM - get deep package C-states, insert an SD card - PC3 at the most.

2. Enable ASPM after inserting a card, do a transfer, then it appears ASPM is off again.

Seems ASPM remains off after the SD card is pulled. So whatever (if anything) the driver is working around it looks like it's being rather aggressive -- I'd assume (in my total inexperience!) it need only be disabled during card activity, or at least only when there's a card inserted.
Comment 12 Bjorn Helgaas 2020-07-23 00:56:37 UTC
What is your udev rule for enabling ASPM?  That runs on boot; does it also run after resume (I assume not)?

For 01:00.0 (the card reader) the relevant before/after suspend diff is:

-               LnkCtl: ASPM L1 Enabled
+               LnkCtl: ASPM L0s L1 Enabled

It looks like the driver enables ASPM during probe and resume:

  rtsx_pci_resume                       # .resume
    rtsx_pci_init_hw
    schedule_delayed_work(idle_work)
      
  rtsx_pci_idle_work                    # INIT_DELAYED_WORK(idle_work)
    rtsx_pm_power_saving
      rtsx_comm_pm_power_saving
        rtsx_enable_aspm
          rtsx_comm_set_aspm
            pcie_capability_clear_and_set_word(PCI_EXP_LNKCTL, pcr->aspm_en)

It disables ASPM during transfers and re-enables it afterwards.  But it's kind of ham-handed, and the PCI core assumes that *it* is handling ASPM config, so there's definitely potential for things going wrong.

AFAICT the driver never enables L0s, so either the PCI core or your udev rule must be doing that.

I forgot to ask: can you collect similar lspci output for the bridge leading to bus 01 (look for the device with "secondary=01")?
Comment 13 James Ettle 2020-07-23 13:10:14 UTC
My udev rules is

SUBSYSTEM=="pci", ATTR{vendor}=="0x10ec", ATTR{device}=="0x5287", ATTR{link/l1_aspm}="1", ATTR{power/control}="auto"

for the card reader, with a similar

SUBSYSTEM=="pci", ATTR{vendor}=="0x10ec", ATTR{device}=="0x8168", ATTR{link/l1_aspm}="1", ATTR{power/control}="auto"

for the r8169 function. I also have a /usr/lib/systemd/system-sleep hook which sets l1_aspm to 1 after resume. For some reason it needs a short pause (0.5s) before writing to sysfs, otherwise it has no effect. This hook was disabled in the before and after lspci outputs attached above.

I should probably point out that I'm inferring whether L1 ASPM is enabled based upon package C-state usage; I'm not sure if the state of sysfs is consistent here. For example, after resume (with no hooks in place), 
/sys/bus/pci/devices/0000:01:00.0/link/l1_aspm is 1 and I see no PC > 3. I have to set that sysfs file to 0, THEN to 1 (i.e. an actual change to the sysfs entry) before I see deep package sleep states again.

The bridge you asked is 00:1d.0, attachments of lspci -vvxxx before and after to follow.
Comment 14 James Ettle 2020-07-23 13:10:58 UTC
Created attachment 290479 [details]
lspci -vvxxx for the bridge before suspend
Comment 15 James Ettle 2020-07-23 13:11:16 UTC
Created attachment 290481 [details]
lspci -vvxxx for the bridge after resume
Comment 16 James Ettle 2020-07-23 13:13:06 UTC
Created attachment 290483 [details]
lspci -vvxxx for the bridge after resume
Comment 17 James Ettle 2020-07-23 17:00:41 UTC
Bug 198951 looks like the same phenomenon.
Comment 18 James Ettle 2020-07-27 19:22:10 UTC
Created attachment 290625 [details]
lspci -vvs 01:00 before suspend (no manual ASPM adjustments)
Comment 19 James Ettle 2020-07-27 19:22:42 UTC
Created attachment 290627 [details]
lspci -vvs 00:1d.0 before suspend (no manual ASPM adjustments)
Comment 20 James Ettle 2020-07-27 19:23:24 UTC
Created attachment 290629 [details]
lspci -vvs 00:1d.0 after resume (no manual ASPM adjustments)
Comment 21 James Ettle 2020-07-27 19:23:54 UTC
Created attachment 290631 [details]
lspci -vvs 01:00 after resume (no manual ASPM adjustments)
Comment 22 James Ettle 2020-07-28 20:48:44 UTC
Created attachment 290655 [details]
dmesg output from 5.7.10 with pci=earlydump
Comment 23 James Ettle 2020-08-02 16:27:53 UTC
Created attachment 290713 [details]
dmesg output with Bjorn's debug patch

Note You need to log in before you can comment on or make changes to this bug.