Possible PCI Regression Linux 5.3-rc1

Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

Hi all,

I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
regression that shows on both of my machines. It is also reproducible 
with the unmodified Ubuntu mainline kernel, downloadable at [1].

Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
imperceivable amount of time). Booting with pci.dyndbg does not reveal 
why.

$ uname -r
5.3.0-050300rc1-generic
$ time lspci -vt 1>/dev/null

real	0m2.321s
user	0m0.026s
sys	0m0.000s

If none of you are aware of this or what is causing it, I will submit a 
bug report to Bugzilla.

I am away from 2019-07-27 to mid 2019-08-04. I will post my patches for 
5.3-rc1 before I leave. If possible, please have a quick look over them 
while I am away for trivial changes or oopsies for me to fix, so that I 
can fire off another series ASAP, so that later when we do a full 
analysis, there are less problems.

Thank you!

Kind regards,

Nicholas Johnson

[1]
https://kernel.ubuntu.com/~kernel-ppa/mainline/v5.3-rc1/

Re: Possible PCI Regression Linux 5.3-rc1

[Bjorn Helgaas]

On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
> Hi all,
> 
> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
> regression that shows on both of my machines. It is also reproducible 
> with the unmodified Ubuntu mainline kernel, downloadable at [1].
> 
> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
> why.
> 
> $ uname -r
> 5.3.0-050300rc1-generic
> $ time lspci -vt 1>/dev/null
> 
> real	0m2.321s
> user	0m0.026s
> sys	0m0.000s
> 
> If none of you are aware of this or what is causing it, I will submit a 
> bug report to Bugzilla.

I wasn't aware of this; thanks for reporting it!  I wasn't able to
reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
the like?  Maybe try "lspci -n" to see if it's related to looking up
the names?

Re: Possible PCI Regression Linux 5.3-rc1

[Logan Gunthorpe]

On 2019-07-24 7:38 a.m., Bjorn Helgaas wrote:
> On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
>> Hi all,
>>
>> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
>> regression that shows on both of my machines. It is also reproducible 
>> with the unmodified Ubuntu mainline kernel, downloadable at [1].
>>
>> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
>> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
>> why.
>>
>> $ uname -r
>> 5.3.0-050300rc1-generic
>> $ time lspci -vt 1>/dev/null
>>
>> real	0m2.321s
>> user	0m0.026s
>> sys	0m0.000s
>>
>> If none of you are aware of this or what is causing it, I will submit a 
>> bug report to Bugzilla.
> 
> I wasn't aware of this; thanks for reporting it!  I wasn't able to
> reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
> the like?  Maybe try "lspci -n" to see if it's related to looking up
> the names?
I also just tested 5.3-rc1 on my machine and lspci behaves normally.

Logan

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Wed, Jul 24, 2019 at 08:38:14AM -0500, Bjorn Helgaas wrote:
> On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
> > Hi all,
> > 
> > I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
> > regression that shows on both of my machines. It is also reproducible 
> > with the unmodified Ubuntu mainline kernel, downloadable at [1].
> > 
> > Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
> > imperceivable amount of time). Booting with pci.dyndbg does not reveal 
> > why.
> > 
> > $ uname -r
> > 5.3.0-050300rc1-generic
> > $ time lspci -vt 1>/dev/null
> > 
> > real	0m2.321s
> > user	0m0.026s
> > sys	0m0.000s
> > 
> > If none of you are aware of this or what is causing it, I will submit a 
> > bug report to Bugzilla.
> 
> I wasn't aware of this; thanks for reporting it!  I wasn't able to
> reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
> the like?  Maybe try "lspci -n" to see if it's related to looking up
> the names?

For a second you had me doubting myself - it could have been a Ubuntu 
thing. But no, I just reproduced it on Arch Linux, and double checked 
that it was not doing it on 5.2. Also, the problem occurs even without 
the PCI kernel parameters which I usually pass.

Looking into this further, it seems that removing the Thunderbolt 
controller solves the issue, where XX is the bus after the root port:

$ echo 1 | sudo tee /sys/bus/pci/devices/0000\:XX\:00.0/remove

Removing the USB controller of the Thunderbolt controller alone can 
alleviate the problem for a few seconds, before it returns - I have no 
idea why. Removing the whole Thunderbolt controller from the root solves 
the problem indefinitely.

This is why you cannot reproduce it in QEMU - no Thunderbolt controller.

It could be a coincidence that it does it for Thunderbolt, but Mika 
Westerberg might be interested now.

Doing "lspci -n" makes no difference - it suffers the problem whenever 
the normal command does.

Doing "strace lspci -vt" unloaded a lot of information that I cannot 
summarise. But if you have access to a physical system with Thunderbolt, 
then you might be able to reproduce the issue and have a better chance 
of pinpointing the problem than I.

Thanks for looking at this.

Kind regards,
Nicholas

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Wed, Jul 24, 2019 at 09:48:19AM -0600, Logan Gunthorpe wrote:
> 
> 
> On 2019-07-24 7:38 a.m., Bjorn Helgaas wrote:
> > On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
> >> Hi all,
> >>
> >> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
> >> regression that shows on both of my machines. It is also reproducible 
> >> with the unmodified Ubuntu mainline kernel, downloadable at [1].
> >>
> >> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
> >> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
> >> why.
> >>
> >> $ uname -r
> >> 5.3.0-050300rc1-generic
> >> $ time lspci -vt 1>/dev/null
> >>
> >> real	0m2.321s
> >> user	0m0.026s
> >> sys	0m0.000s
> >>
> >> If none of you are aware of this or what is causing it, I will submit a 
> >> bug report to Bugzilla.
> > 
> > I wasn't aware of this; thanks for reporting it!  I wasn't able to
> > reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
> > the like?  Maybe try "lspci -n" to see if it's related to looking up
> > the names?
> I also just tested 5.3-rc1 on my machine and lspci behaves normally.
> 
> Logan

I have looked deeper into this and it seems that removing the 
Thunderbolt controller from the root port with sysfs resolves the issue. 
If the system you tried this on does not have Thunderbolt, then you will 
not have been able to reproduce the bug. Please see the message to Bjorn 
which you are carbon copied into for more elaboration.

Thanks for looking at this.

Regards,
Nicholas

Re: Possible PCI Regression Linux 5.3-rc1

[Logan Gunthorpe]

On 2019-07-25 7:18 a.m., Nicholas Johnson wrote:
> On Wed, Jul 24, 2019 at 08:38:14AM -0500, Bjorn Helgaas wrote:
>> On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
>>> Hi all,
>>>
>>> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
>>> regression that shows on both of my machines. It is also reproducible 
>>> with the unmodified Ubuntu mainline kernel, downloadable at [1].
>>>
>>> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
>>> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
>>> why.
>>>
>>> $ uname -r
>>> 5.3.0-050300rc1-generic
>>> $ time lspci -vt 1>/dev/null
>>>
>>> real	0m2.321s
>>> user	0m0.026s
>>> sys	0m0.000s
>>>
>>> If none of you are aware of this or what is causing it, I will submit a 
>>> bug report to Bugzilla.
>>
>> I wasn't aware of this; thanks for reporting it!  I wasn't able to
>> reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
>> the like?  Maybe try "lspci -n" to see if it's related to looking up
>> the names?
> 
> For a second you had me doubting myself - it could have been a Ubuntu 
> thing. But no, I just reproduced it on Arch Linux, and double checked 
> that it was not doing it on 5.2. Also, the problem occurs even without 
> the PCI kernel parameters which I usually pass.

Ok, can you bisect to find the commit that causes this issue?

Thanks,

Logan

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Thu, Jul 25, 2019 at 09:50:48AM -0600, Logan Gunthorpe wrote:
> 
> 
> On 2019-07-25 7:18 a.m., Nicholas Johnson wrote:
> > On Wed, Jul 24, 2019 at 08:38:14AM -0500, Bjorn Helgaas wrote:
> >> On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
> >>> Hi all,
> >>>
> >>> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
> >>> regression that shows on both of my machines. It is also reproducible 
> >>> with the unmodified Ubuntu mainline kernel, downloadable at [1].
> >>>
> >>> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
> >>> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
> >>> why.
> >>>
> >>> $ uname -r
> >>> 5.3.0-050300rc1-generic
> >>> $ time lspci -vt 1>/dev/null
> >>>
> >>> real	0m2.321s
> >>> user	0m0.026s
> >>> sys	0m0.000s
> >>>
> >>> If none of you are aware of this or what is causing it, I will submit a 
> >>> bug report to Bugzilla.
> >>
> >> I wasn't aware of this; thanks for reporting it!  I wasn't able to
> >> reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
> >> the like?  Maybe try "lspci -n" to see if it's related to looking up
> >> the names?
> > 
> > For a second you had me doubting myself - it could have been a Ubuntu 
> > thing. But no, I just reproduced it on Arch Linux, and double checked 
> > that it was not doing it on 5.2. Also, the problem occurs even without 
> > the PCI kernel parameters which I usually pass.
> 
> Ok, can you bisect to find the commit that causes this issue?

I have done a partial bisect and then found the culprit commit by visual 
inspection. I would have done the full bisect, but I am using highly
underpowered i7-7700K so each round requires 20-30 minutes of compiling.

Reversing the following commit solves the issue:

commit c2bf1fc212f7e6f25ace1af8f0b3ac061ea48ba5
Author: Mika Westerberg <mika.westerberg@linux.intel.com>
PCI: Add missing link delays required by the PCIe spec

Mika, care to weigh in (assuming you are back from four weeks leave)? 
Clearly this creates delays in "lspci -vt" in some Thunderbolt systems, 
but not all - otherwise you would have caught it. You mentioned Ice Lake 
in the commit log so perhaps it works fine on Ice Lake.

Thanks,
Nicholas

> 
> Thanks,
> 
> Logan

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Sun, Aug 04, 2019 at 04:47:36PM +0800, NicholasJohnson wrote:
> On Thu, Jul 25, 2019 at 09:50:48AM -0600, Logan Gunthorpe wrote:
> > 
> > 
> > On 2019-07-25 7:18 a.m., Nicholas Johnson wrote:
> > > On Wed, Jul 24, 2019 at 08:38:14AM -0500, Bjorn Helgaas wrote:
> > >> On Wed, Jul 24, 2019 at 12:54:00PM +0000, Nicholas Johnson wrote:
> > >>> Hi all,
> > >>>
> > >>> I was just rebasing my patches for linux 5.3-rc1 and noticed a possible 
> > >>> regression that shows on both of my machines. It is also reproducible 
> > >>> with the unmodified Ubuntu mainline kernel, downloadable at [1].
> > >>>
> > >>> Running the lspci command takes 1-3 seconds with 5.3-rc1 (rather than an 
> > >>> imperceivable amount of time). Booting with pci.dyndbg does not reveal 
> > >>> why.
> > >>>
> > >>> $ uname -r
> > >>> 5.3.0-050300rc1-generic
> > >>> $ time lspci -vt 1>/dev/null
> > >>>
> > >>> real	0m2.321s
> > >>> user	0m0.026s
> > >>> sys	0m0.000s
> > >>>
> > >>> If none of you are aware of this or what is causing it, I will submit a 
> > >>> bug report to Bugzilla.
> > >>
> > >> I wasn't aware of this; thanks for reporting it!  I wasn't able to
> > >> reproduce this in qemu.  Can you play with "strace -r lspci -vt" and
> > >> the like?  Maybe try "lspci -n" to see if it's related to looking up
> > >> the names?
> > > 
> > > For a second you had me doubting myself - it could have been a Ubuntu 
> > > thing. But no, I just reproduced it on Arch Linux, and double checked 
> > > that it was not doing it on 5.2. Also, the problem occurs even without 
> > > the PCI kernel parameters which I usually pass.
> > 
> > Ok, can you bisect to find the commit that causes this issue?
> 
> I have done a partial bisect and then found the culprit commit by visual 
> inspection. I would have done the full bisect, but I am using highly
> underpowered i7-7700K so each round requires 20-30 minutes of compiling.
> 
> Reversing the following commit solves the issue:
> 
> commit c2bf1fc212f7e6f25ace1af8f0b3ac061ea48ba5
> Author: Mika Westerberg <mika.westerberg@linux.intel.com>
> PCI: Add missing link delays required by the PCIe spec
> 
> Mika, care to weigh in (assuming you are back from four weeks leave)? 
> Clearly this creates delays in "lspci -vt" in some Thunderbolt systems, 
> but not all - otherwise you would have caught it. You mentioned Ice Lake 
> in the commit log so perhaps it works fine on Ice Lake.
> 
> Thanks,
> Nicholas

I am re-posting to add more information. Here is my Thunderbolt, with 
the NHI under bus 05 ("lspci -t"):

           +-1c.4-[03-6d]----00.0-[04-6d]--+-00.0-[05]----00.0
           |                               +-01.0-[06-38]----00.0-[07-38]----01.0-[08]----00.0
           |                               +-02.0-[39]----00.0
           |                               \-04.0-[3a-6d]--

$ time cat /sys/bus/pci/devices/0000\:05\:00.0/config | hexdump
0000000 8086 15d2 0406 0010 0002 0880 0000 0000
0000010 0000 ac00 0000 ac04 0000 0000 0000 0000
0000020 0000 0000 0000 0000 0000 0000 1028 08af
0000030 0000 0000 0080 0000 0000 0000 01ff 0000
0000040

real	0m1.132s
user	0m0.002s
sys	0m0.000s

But it is instant for all of the other busses - so it has something to 
do with the NHI in particular.

Regards,
Nicholas

> 
> > 
> > Thanks,
> > 
> > Logan

Re: Possible PCI Regression Linux 5.3-rc1

[Mika Westerberg]

Hi,

On Sun, Aug 04, 2019 at 08:47:43AM +0000, Nicholas Johnson wrote:
> Reversing the following commit solves the issue:
> 
> commit c2bf1fc212f7e6f25ace1af8f0b3ac061ea48ba5
> Author: Mika Westerberg <mika.westerberg@linux.intel.com>
> PCI: Add missing link delays required by the PCIe spec
> 
> Mika, care to weigh in (assuming you are back from four weeks leave)? 

I'm back now.

> Clearly this creates delays in "lspci -vt" in some Thunderbolt systems, 
> but not all - otherwise you would have caught it. You mentioned Ice Lake 
> in the commit log so perhaps it works fine on Ice Lake.

I also tried it on other systems but it may be that something is
missing. Can you add "pciepordrv.dyndbg" to the kernel command line (or
change the dev_dbg() in wait_for_downstream_link() to dev_info() instead
and attach the dmesg along with full 'sudo lspci -vv' output to the
following bugzilla (as I think they are the same issue in the end):

  https://bugzilla.kernel.org/show_bug.cgi?id=204413

Thanks!

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Mon, Aug 05, 2019 at 03:34:50PM +0300, Mika Westerberg wrote:
> Hi,
> 
> On Sun, Aug 04, 2019 at 08:47:43AM +0000, Nicholas Johnson wrote:
> > Reversing the following commit solves the issue:
> > 
> > commit c2bf1fc212f7e6f25ace1af8f0b3ac061ea48ba5
> > Author: Mika Westerberg <mika.westerberg@linux.intel.com>
> > PCI: Add missing link delays required by the PCIe spec
> > 
> > Mika, care to weigh in (assuming you are back from four weeks leave)? 
> 
> I'm back now.
> 
> > Clearly this creates delays in "lspci -vt" in some Thunderbolt systems, 
> > but not all - otherwise you would have caught it. You mentioned Ice Lake 
> > in the commit log so perhaps it works fine on Ice Lake.
> 
> I also tried it on other systems but it may be that something is
> missing. Can you add "pciepordrv.dyndbg" to the kernel command line (or
> change the dev_dbg() in wait_for_downstream_link() to dev_info() instead
> and attach the dmesg along with full 'sudo lspci -vv' output to the
> following bugzilla (as I think they are the same issue in the end):
> 
>   https://bugzilla.kernel.org/show_bug.cgi?id=204413
> 
> Thanks!

Re: Possible PCI Regression Linux 5.3-rc1

[Nicholas Johnson]

On Mon, Aug 05, 2019 at 03:34:50PM +0300, Mika Westerberg wrote:
> Hi,
> 
> On Sun, Aug 04, 2019 at 08:47:43AM +0000, Nicholas Johnson wrote:
> > Reversing the following commit solves the issue:
> > 
> > commit c2bf1fc212f7e6f25ace1af8f0b3ac061ea48ba5
> > Author: Mika Westerberg <mika.westerberg@linux.intel.com>
> > PCI: Add missing link delays required by the PCIe spec
> > 
> > Mika, care to weigh in (assuming you are back from four weeks leave)? 
> 
> I'm back now.
> 
> > Clearly this creates delays in "lspci -vt" in some Thunderbolt systems, 
> > but not all - otherwise you would have caught it. You mentioned Ice Lake 
> > in the commit log so perhaps it works fine on Ice Lake.
> 
> I also tried it on other systems but it may be that something is
> missing. Can you add "pciepordrv.dyndbg" to the kernel command line (or
> change the dev_dbg() in wait_for_downstream_link() to dev_info() instead
> and attach the dmesg along with full 'sudo lspci -vv' output to the
> following bugzilla (as I think they are the same issue in the end):
> 
>   https://bugzilla.kernel.org/show_bug.cgi?id=204413
> 
> Thanks!

Done. Please note the update I sent to my own email with more 
information, elaborating that it is reading the config from under the 
NHI which causes the delay. If bus 05 is under the NHI, then the 
following command has a delay:

$ cat /sys/bus/pci/devices/0000\:05\:00.0/config

Whereas reading config from all the other busses is fine. This is what 
is holding up the lspci command.

If possible, please look over my patches briefly to catch any silly 
mistakes or trivial changes to get stuff out of the way for thorough 
review later. I really want to at least get the alignment patch in which 
will help Linux with native enumeration and solve your bug report.

Thanks!

Regards,
Nicholas.