Re: [Regression] pcie_wait_for_link_delay (1132.853 ms @ 5039.414431)

From: Paul Menzel
Date: Tue Aug 06 2019 - 10:02:50 EST

Dear Mika,


On 06.08.19 13:31, Mika Westerberg wrote:
> On Tue, Aug 06, 2019 at 11:57:26AM +0200, Paul Menzel wrote:

>> On 06.08.19 11:36, Mika Westerberg wrote:
>>> +Nicholas and Matthias
>>>
>>> On Tue, Aug 06, 2019 at 11:20:37AM +0200, Paul Menzel wrote:
>>
>>>> Commit c2bf1fc2 (PCI: Add missing link delays required by the PCIe spec) [1]
>>>> increases the resume time from ACPI S3 on a desktop system Dell OptiPlex 5040
>>>> by one second. It looks like this is expected from the commit message, but
>>>> breaks existing systems with boot time requirements. I measured this with the
>>>> help of the pm-graph script `sleepgraph.py` [2].
>>>>
>>>> 0000:00:01.0 resume_noirq (1134.715 ms @ 5039.412578 to 5040.547293)
>>>> â
>>>> pcie_wait_for_link_delay (1132.853 ms @ 5039.414431)
>>
>> By the way, here is the trace excerpt with the interesting comments.
>>
>> ```
>> 5040.547284 | 1) kworker-3594 | 1132852 us | } /* schedule_timeout */
>> 5040.547284 | 1) kworker-3594 | 1132853 us | } /* msleep */
>> 5040.547284 | 1) kworker-3594 | 1132853 us | } /* pcie_wait_for_link_delay */
>> 5040.547284 | 1) kworker-3594 | 1132856 us | } /* wait_for_downstream_link */
>> 5040.547285 | 1) kworker-3594 | | device_for_each_child() {
>> 5040.547285 | 1) kworker-3594 | 0.185 us | _raw_spin_lock_irqsave();
>> 5040.547286 | 1) kworker-3594 | 0.136 us | _raw_spin_unlock_irqrestore();
>> 5040.547286 | 1) kworker-3594 | 0.190 us | pm_iter();
>> 5040.547286 | 1) kworker-3594 | 0.129 us | _raw_spin_lock_irqsave();
>> 5040.547287 | 1) kworker-3594 | 0.134 us | _raw_spin_unlock_irqrestore();
>> 5040.547287 | 1) kworker-3594 | 0.194 us | pm_iter();
>> 5040.547287 | 1) kworker-3594 | 0.134 us | _raw_spin_lock_irqsave();
>> 5040.547288 | 1) kworker-3594 | 0.133 us | _raw_spin_unlock_irqrestore();
>> 5040.547288 | 1) kworker-3594 | 0.187 us | pm_iter();
>> 5040.547288 | 1) kworker-3594 | 0.135 us | _raw_spin_lock_irqsave();
>> 5040.547289 | 1) kworker-3594 | 0.135 us | _raw_spin_unlock_irqrestore();
>> 5040.547289 | 1) kworker-3594 | 0.271 us | pm_iter();
>> 5040.547289 | 1) kworker-3594 | 0.132 us | _raw_spin_lock_irqsave();
>> 5040.547290 | 1) kworker-3594 | 0.137 us | _raw_spin_unlock_irqrestore();
>> 5040.547290 | 1) kworker-3594 | 5.036 us | } /* device_for_each_child */
>> 5040.547290 | 1) kworker-3594 | 1132862 us | } /* pcie_port_device_resume_noirq */
>> 5040.547290 | 1) kworker-3594 | 1134709 us | } /* pci_pm_resume_noirq */
>> ```
>>
>>>> $ lspci -nn
>>>> 00:00.0 Host bridge [0600]: Intel Corporation Xeon E3-1200 v5/E3-1500 v5/6th Gen Core Processor Host Bridge/DRAM Registers [8086:191f] (rev 07)
>>>> 00:01.0 PCI bridge [0604]: Intel Corporation Xeon E3-1200 v5/E3-1500 v5/6th Gen Core Processor PCIe Controller (x16) [8086:1901] (rev 07)
>>>> 00:14.0 USB controller [0c03]: Intel Corporation Sunrise Point-H USB 3.0 xHCI Controller [8086:a12f] (rev 31)
>>>> 00:14.2 Signal processing controller [1180]: Intel Corporation Sunrise Point-H Thermal subsystem [8086:a131] (rev 31)
>>>> 00:16.0 Communication controller [0780]: Intel Corporation Sunrise Point-H CSME HECI #1 [8086:a13a] (rev 31)
>>>> 00:17.0 SATA controller [0106]: Intel Corporation Sunrise Point-H SATA controller [AHCI mode] [8086:a102] (rev 31)
>>>> 00:1c.0 PCI bridge [0604]: Intel Corporation Sunrise Point-H PCI Express Root Port #1 [8086:a110] (rev f1)
>>>> 00:1f.0 ISA bridge [0601]: Intel Corporation Sunrise Point-H LPC Controller [8086:a146] (rev 31)
>>>> 00:1f.2 Memory controller [0580]: Intel Corporation Sunrise Point-H PMC [8086:a121] (rev 31)
>>>> 00:1f.3 Audio device [0403]: Intel Corporation Sunrise Point-H HD Audio [8086:a170] (rev 31)
>>>> 00:1f.4 SMBus [0c05]: Intel Corporation Sunrise Point-H SMBus [8086:a123] (rev 31)
>>>> 00:1f.6 Ethernet controller [0200]: Intel Corporation Ethernet Connection (2) I219-V [8086:15b8] (rev 31)
>>>> 01:00.0 VGA compatible controller [0300]: Advanced Micro Devices, Inc. [AMD/ATI] Oland XT [Radeon HD 8670 / R7 250/350] [1002:6610] (rev 81)
>>>> 01:00.1 Audio device [0403]: Advanced Micro Devices, Inc. [AMD/ATI] Cape Verde/Pitcairn HDMI Audio [Radeon HD 7700/7800 Series] [1002:aab0]
>>>> 02:00.0 PCI bridge [0604]: Texas Instruments XIO2001 PCI Express-to-PCI Bridge [104c:8240]
>>>>
>>>> So, itâs about the internal Intel graphics device, which is not used on this
>>>> system, as there is an external AMD graphics device plugged in.
>>>>
>>>> As far as I understand it, itâs a bug in the firmware, that a one second delay
>>>> is specified?
>>
>> How can I read out the delay from the system as done in?
>
> The delay is not system wide so it depends on the device. Typically it
> is 100ms but there is a way to shorten it using ACPI _DSM.

Yeah, I know. I was wondering if it can easily be read out for a device
under `/sys`, other debug level or, for example, with `lspci` or
`acpidump`.

>> ```
>> static int get_downstream_delay(struct pci_bus *bus)
>> {
>> struct pci_dev *pdev;
>> int min_delay = 100;
>> int max_delay = 0;
>>
>> list_for_each_entry(pdev, &bus->devices, bus_list) {
>> if (!pdev->imm_ready)
>> min_delay = 0;
>> else if (pdev->d3cold_delay < min_delay)
>> min_delay = pdev->d3cold_delay;
>> if (pdev->d3cold_delay > max_delay)
>> max_delay = pdev->d3cold_delay;
>> }
>>
>> return max(min_delay, max_delay);
>> }
>> ```
>>
>>>> Anyway, there is such firmware out there, so Iâd like to avoid the time
>>>> increases.
>>>>
>>>> As a first step, the commit should be extended to print a warning (maybe if
>>>> `initcall_debug` is specified), when the delay is higher than letâs say 50(?)
>>>> ms. Also better documentation how to debug these delays would be appreciated.
>>
>> As your commit message says the standard demands a delay of at least 100 ms, 50 ms
>> is of course too short, and maybe 150 ms or so should be used as the threshold.
>>
>>>> If there is no easy solution, itâd be great if the commit could be reverted for
>>>> now, and a better solution be discussed for the next release.
>>>
>>> There is also kernel bugzilla entry about another regression this causes
>>> here:
>>>
>>> https://bugzilla.kernel.org/show_bug.cgi?id=204413
>>>
>>> I agree we should revert c2bf1fc2 now. I'll try to come up alternative
>>> solution to these missing delays that hopefully does not break existing
>>> setups.
>>>
>>> Rafael, Bjorn,
>>>
>>> Can you revert the commit or do you want me to send a revert patch?
>>>
>>> Thanks and sorry about the breakage.
>>
>> No worries.
>
> Thanks for the lspci output. This explains the 1 second delay:
>
>> LnkCap: Port #2, Speed 8GT/s, Width x16, ASPM L0s L1, Exit Latency L0s <256ns, L1 <8us
>> ClockPM- Surprise- LLActRep- BwNot+ ASPMOptComp+
>
> The port does not support active link reporting. Can you try the below
> patch?
>
> Nicholas, can you also try it? I think it should solve your issue as
> well.
>
> Thanks!
>
> diff --git a/drivers/pci/pcie/portdrv_core.c b/drivers/pci/pcie/portdrv_core.c
> index 308c3e0c4a34..bb8c753013d0 100644
> --- a/drivers/pci/pcie/portdrv_core.c
> +++ b/drivers/pci/pcie/portdrv_core.c
> @@ -434,7 +434,8 @@ static void wait_for_downstream_link(struct pci_dev *pdev)
> * need to wait 100ms. For higher speeds (gen3) we need to wait
> * first for the data link layer to become active.
> */
> - if (pcie_get_speed_cap(pdev) <= PCIE_SPEED_5_0GT)
> + if (pcie_get_speed_cap(pdev) <= PCIE_SPEED_5_0GT ||
> + !pdev->link_active_reporting)
> msleep(delay);
> else
> pcie_wait_for_link_delay(pdev, true, delay);

I can confirm, that the delay is reduced now.

pcieport @ 0000:00:01.0 {pcieport} async_device (Total Suspend: 12.118 ms Total Resume: 105.604 ms)

How can I enable the verbose log messages you got in your commit
message like below?

pcieport 0000:00:1b.0: wait for 100ms after DLLLA is set before access to 0000:01:00.0


Kind regards,

Paul

Attachment: smime.p7s
Description: S/MIME Cryptographic Signature