Re: close() on some Intel CNP-LP PCI devices takes up to 2.7 s

Re: close() on some Intel CNP-LP PCI devices takes up to 2.7 s

[Mika Westerberg]

On Tue, Jun 09, 2020 at 05:39:21PM +0200, Paul Menzel wrote:
> Dear Linux folks,
> 
> 
> On the Intel Cannon Point-LP laptop Dell Precision 3540 with a dedicated AMD
> graphics card (both graphics devices can be used) with Debian Sid/unstable
> with Linux 5.6.14, running lspci takes quite some time, and the screen even
> flickers a short moment before the result is displayed.
> 
> Tracing lspci with strace, shows that the close() function of the three
> devices takes from
> 
> •   00:1d.0 PCI bridge: Intel Corporation Cannon Point-LP PCI Express Root
> Port #9
> 
> •   04:00.0 System peripheral: Intel Corporation JHL6340 Thunderbolt 3 NHI
> (C step) [Alpine Ridge 2C 2016] (rev 02)
> 
> •   3b:00.0 Display controller: Advanced Micro Devices, Inc. [AMD/ATI] Lexa
> XT [Radeon PRO WX 3100]
> 
> takes from 270 ms to 2.5 s.
> 
> > 11:43:21.714391 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:04:00.0/config", O_RDONLY) = 3
> > 11:43:21.714448 pread64(3, "\206\200\331\25\6\4\20\0\2\0\200\10 \0\0\0\0\0\0\352\0\0\4\352\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0(\20\272\10\0\0\0\0\
> > 200\0\0\0\0\0\0\0\377\1\0\0", 64, 0) = 64
> > 11:43:24.487818 close(3)                = 0
> 
> > 11:43:24.489508 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:00:1d.0/config", O_RDONLY) = 3
> > 11:43:24.489598 pread64(3, "\206\200\260\235\7\4\20\0\360\0\4\6\20\0\201\0\0\0\0\0\0\0\0\0\0;;\00000\0  \354 \354\1\300\21\320\0\0\0\0\0\0\0\0\0\0\0\0
> > @\0\0\0\0\0\0\0\377\1\22\0", 64, 0) = 64
> > 11:43:24.966661 close(3)                = 0
> 
> > 11:43:24.988544 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:3b:00.0/config", O_RDONLY) = 3
> > 11:43:24.988584 pread64(3, "\2\20\205i\7\4\20\0\0\0\200\3\20\0\0\0\f\0\0\300\0\0\0\0\f\0\0\320\0\0\0\0\0010\0\0\0\0 \354\0\0\0\0(\20\272\10\0\0$\354H\0\0\0\0\0\0\0\377\1\0\0", 64, 0) = 64
> > 11:43:25.252745 close(3)
> 
> Unfortunately, I forgot to collect the tree output, but hopefully the
> attached Linux messages and strace of lspci output will be enough for the
> start.
> 
> Please tell me, if you want me to create a bug report in the Linux bug
> tracker.

Can you try this commit?

  https://git.kernel.org/pub/scm/linux/kernel/git/helgaas/pci.git/commit/?h=pci/pm&id=ec411e02b7a2e785a4ed9ed283207cd14f48699d

It should be in the mainline already as well.

Note we still need to obey the delays required by the PCIe spec so 100ms
after the link is trained but this one should at least get it down from
1100ms.

Re: close() on some Intel CNP-LP PCI devices takes up to 2.7 s

[Paul Menzel]

Dear Mika,


Am 09.06.20 um 17:44 schrieb Mika Westerberg:
> On Tue, Jun 09, 2020 at 05:39:21PM +0200, Paul Menzel wrote:

>> On the Intel Cannon Point-LP laptop Dell Precision 3540 with a dedicated AMD
>> graphics card (both graphics devices can be used) with Debian Sid/unstable
>> with Linux 5.6.14, running lspci takes quite some time, and the screen even
>> flickers a short moment before the result is displayed.
>>
>> Tracing lspci with strace, shows that the close() function of the three
>> devices takes from
>>
>> •   00:1d.0 PCI bridge: Intel Corporation Cannon Point-LP PCI Express Root
>> Port #9
>>
>> •   04:00.0 System peripheral: Intel Corporation JHL6340 Thunderbolt 3 NHI
>> (C step) [Alpine Ridge 2C 2016] (rev 02)
>>
>> •   3b:00.0 Display controller: Advanced Micro Devices, Inc. [AMD/ATI] Lexa
>> XT [Radeon PRO WX 3100]
>>
>> takes from 270 ms to 2.5 s.
>>
>>> 11:43:21.714391 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:04:00.0/config", O_RDONLY) = 3
>>> 11:43:21.714448 pread64(3, "\206\200\331\25\6\4\20\0\2\0\200\10 \0\0\0\0\0\0\352\0\0\4\352\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0(\20\272\10\0\0\0\0\
>>> 200\0\0\0\0\0\0\0\377\1\0\0", 64, 0) = 64
>>> 11:43:24.487818 close(3)                = 0
>>
>>> 11:43:24.489508 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:00:1d.0/config", O_RDONLY) = 3
>>> 11:43:24.489598 pread64(3, "\206\200\260\235\7\4\20\0\360\0\4\6\20\0\201\0\0\0\0\0\0\0\0\0\0;;\00000\0  \354 \354\1\300\21\320\0\0\0\0\0\0\0\0\0\0\0\0
>>> @\0\0\0\0\0\0\0\377\1\22\0", 64, 0) = 64
>>> 11:43:24.966661 close(3)                = 0
>>
>>> 11:43:24.988544 openat(AT_FDCWD, "/sys/bus/pci/devices/0000:3b:00.0/config", O_RDONLY) = 3
>>> 11:43:24.988584 pread64(3, "\2\20\205i\7\4\20\0\0\0\200\3\20\0\0\0\f\0\0\300\0\0\0\0\f\0\0\320\0\0\0\0\0010\0\0\0\0 \354\0\0\0\0(\20\272\10\0\0$\354H\0\0\0\0\0\0\0\377\1\0\0", 64, 0) = 64
>>> 11:43:25.252745 close(3)
>>
>> Unfortunately, I forgot to collect the tree output, but hopefully the
>> attached Linux messages and strace of lspci output will be enough for the
>> start.
>>
>> Please tell me, if you want me to create a bug report in the Linux bug
>> tracker.
> 
> Can you try this commit?
> 
>    https://git.kernel.org/pub/scm/linux/kernel/git/helgaas/pci.git/commit/?h=pci/pm&id=ec411e02b7a2e785a4ed9ed283207cd14f48699d
> 
> It should be in the mainline already as well.
> 
> Note we still need to obey the delays required by the PCIe spec so 100ms
> after the link is trained but this one should at least get it down from
> 1100ms.

Thank you for replying so quickly. Hopefully, I’ll be able to test the 
commit tomorrow.

One question though. The commit talks about resuming from suspend. I 
understand that training happens there.

In my case the system is already running. So I wonder, why link(?) 
training would still happening.


Kind regards,

Paul

Re: close() on some Intel CNP-LP PCI devices takes up to 2.7 s

[Mika Westerberg]

On Wed, Jun 10, 2020 at 08:18:07AM +0200, Paul Menzel wrote:
> Thank you for replying so quickly. Hopefully, I’ll be able to test the
> commit tomorrow.
> 
> One question though. The commit talks about resuming from suspend. I
> understand that training happens there.
> 
> In my case the system is already running. So I wonder, why link(?) training
> would still happening.

It also includes runtime PM so when the PCIe topology goes into D3cold
the links are "down" so once you run tool such as lspci the links need
to be re-trained to be able to access the devices connected to them.