| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <22234577.eFycb7UY1F@vostro.rjw.lan> Date: Fri, 06 Sep 2013 01:48:38 +0200 From: "Rafael J. Wysocki" <rjw@...k.pl> To: Alex Williamson <alex.williamson@...hat.com> Cc: ACPI Devel Maling List <linux-acpi@...r.kernel.org>, Bjorn Helgaas <bhelgaas@...gle.com>, LKML <linux-kernel@...r.kernel.org>, Linux PCI <linux-pci@...r.kernel.org>, Yinghai Lu <yinghai@...nel.org>, Jiang Liu <liuj97@...il.com>, Mika Westerberg <mika.westerberg@...ux.intel.com>, "Kirill A. Shutemov" <kirill.shutemov@...ux.intel.com> Subject: Re: Excess dmesg output from ACPIPHP on boot (was: Re: [PATCH 25/30] ACPI / hotplug / PCI: Check for new devices on enabled slots) On Thursday, September 05, 2013 05:31:58 PM Alex Williamson wrote: > On Fri, 2013-09-06 at 01:36 +0200, Rafael J. Wysocki wrote: > > On Thursday, September 05, 2013 05:08:03 PM Alex Williamson wrote: > > > On Fri, 2013-09-06 at 00:40 +0200, Rafael J. Wysocki wrote: > > > > On Thursday, September 05, 2013 04:17:25 PM Alex Williamson wrote: > > > > > On Thu, 2013-09-05 at 23:39 +0200, Rafael J. Wysocki wrote: > > > > > > On Thursday, September 05, 2013 09:44:26 PM Rafael J. Wysocki wrote: > > > > > > > On Thursday, September 05, 2013 08:21:41 AM Alex Williamson wrote: > > > > > > > > > > > > [...] > > > > > > > > > > > > > > > > > > > > > > > > [ 18.288122] pci 0000:00:00.0: no hotplug settings from platform > > > > > > > > > [ 18.288127] pcieport 0000:00:01.0: no hotplug settings from platform > > > > > > > > > [ 18.288142] pci 0000:01:00.0: no hotplug settings from platform > > > > > > > > > [ 18.288157] pci 0000:01:00.1: no hotplug settings from platform > > > > > > > > > [ 18.288162] pcieport 0000:00:03.0: no hotplug settings from platform > > > > > > > > > [ 18.288176] pci 0000:02:00.0: no hotplug settings from platform > > > > > > > > > [ 18.288190] pci 0000:02:00.1: no hotplug settings from platform > > > > > > > > > [ 18.288195] pcieport 0000:00:07.0: no hotplug settings from platform > > > > > > > > > [ 18.288209] pci 0000:03:00.0: no hotplug settings from platform > > > > > > > > > [ 18.288224] pci 0000:03:00.1: no hotplug settings from platform > > > > > > > > > [ 18.288228] pci 0000:00:14.0: no hotplug settings from platform > > > > > > > > > [ 18.288233] pci 0000:00:14.1: no hotplug settings from platform > > > > > > > > > [ 18.288237] pci 0000:00:14.2: no hotplug settings from platform > > > > > > > > > [ 18.288242] pci 0000:00:16.0: no hotplug settings from platform > > > > > > > > > [ 18.288247] pci 0000:00:16.1: no hotplug settings from platform > > > > > > > > > [ 18.288251] pci 0000:00:16.2: no hotplug settings from platform > > > > > > > > > [ 18.288256] pci 0000:00:16.3: no hotplug settings from platform > > > > > > > > > [ 18.288260] pci 0000:00:16.4: no hotplug settings from platform > > > > > > > > > [ 18.288265] pci 0000:00:16.5: no hotplug settings from platform > > > > > > > > > [ 18.288269] pci 0000:00:16.6: no hotplug settings from platform > > > > > > > > > [ 18.288274] pci 0000:00:16.7: no hotplug settings from platform > > > > > > > > > [ 18.288278] pci 0000:00:1a.0: no hotplug settings from platform > > > > > > > > > [ 18.288279] pci 0000:00:1a.0: using default PCI settings > > > > > > > > > [ 18.288292] pci 0000:00:1a.1: no hotplug settings from platform > > > > > > > > > [ 18.288293] pci 0000:00:1a.1: using default PCI settings > > > > > > > > > [ 18.288307] ehci-pci 0000:00:1a.7: no hotplug settings from platform > > > > > > > > > [ 18.288308] ehci-pci 0000:00:1a.7: using default PCI settings > > > > > > > > > [ 18.288322] pci 0000:00:1b.0: no hotplug settings from platform > > > > > > > > > [ 18.288327] pcieport 0000:00:1c.0: no hotplug settings from platform > > > > > > > > > [ 18.288332] pcieport 0000:00:1c.4: no hotplug settings from platform > > > > > > > > > [ 18.288344] pci 0000:05:00.0: no hotplug settings from platform > > > > > > > > > [ 18.288349] pci 0000:00:1d.0: no hotplug settings from platform > > > > > > > > > [ 18.288350] pci 0000:00:1d.0: using default PCI settings > > > > > > > > > [ 18.288360] pci 0000:00:1d.1: no hotplug settings from platform > > > > > > > > > [ 18.288361] pci 0000:00:1d.1: using default PCI settings > > > > > > > > > [ 18.288374] pci 0000:00:1d.2: no hotplug settings from platform > > > > > > > > > [ 18.288374] pci 0000:00:1d.2: using default PCI settings > > > > > > > > > [ 18.288387] pci 0000:00:1d.3: no hotplug settings from platform > > > > > > > > > [ 18.288387] pci 0000:00:1d.3: using default PCI settings > > > > > > > > > > > > > > > > > > The boot is noticeably slower. What's going to happen on systems that > > > > > > > > > actually have a significant I/O topology vs my little workstation? > > > > > > > > > > > > > > That depends on how many bus check/device check events they generate on boot. > > > > > > > > > > > > > > My test machines don't generate them during boot at all (even the one with > > > > > > > a Thunderbolt connector), so I don't see the messages in question during boot > > > > > > > on any of them. Mika doesn't see them either I suppose, or he would have told > > > > > > > me about that before. > > > > > > > > > > > > > > And let's just make it clear that it is not usual or even OK to generate bus > > > > > > > checks or device checks during boot like this. And since the changes in > > > > > > > question have been in linux-next since right after the 3.11 merge window, I > > > > > > > think that someone would have complained already had that been a common issue. > > > > > > > > > > > > > > Of course, we need to deal with that somehow nevertheless. :-) > > > > > > > > > > > > > > > Just to give you an idea: > > > > > > > > > > > > > > > > CONFIG_HOTPLUG_PCI_ACPI=y > > > > > > > > > > > > > > > > $ dmesg | wc > > > > > > > > 5697 49935 384368 > > > > > > > > > > > > > > > > $ dmesg | tail --lines=1 > > > > > > > > [ 53.137123] Ebtables v2.0 registered > > > > > > > > > > > > > > > > -- vs -- > > > > > > > > > > > > > > > > # CONFIG_HOTPLUG_PCI_ACPI is not set > > > > > > > > > > > > > > > > $ dmesg | wc > > > > > > > > 1053 9176 71652 > > > > > > > > > > > > > > > > $dmesg | tail --lines=1 > > > > > > > > [ 28.917220] Ebtables v2.0 registered > > > > > > > > > > > > > > > > So it spews out 5x more output with acpiphp enabled and takes and extra > > > > > > > > 24s to boot (nearly 2x). Not good. > > > > > > > > > > > > > > The "no hotplug settings from platform" message is from pci_configure_slot(). > > > > > > > I think the messages you're seeing are from the call to it in > > > > > > > acpiphp_set_hpp_values() which is called by enable_slot(). > > > > > > > > > > > > > > There, I think, we can simply check the return value of pci_scan_slot() and > > > > > > > if that is 0 (no new devices), we can just skip everything under the call to > > > > > > > __pci_bus_assign_resources(). > > > > > > > > > > > > > > However, we can't skip the scanning of bridges, if any, because there may be > > > > > > > new devices below them and I guess that's what takes so much time on your > > > > > > > machine. > > > > > > > > > > > > OK, one piece is missing. We may need to evaluate _OSC after handling each > > > > > > event to let the platform know the status. > > > > > > > > > > > > Can you please check if the appended patch makes any difference (with the > > > > > > previous fix applied, of course)? > > > > > > > > > > > > If fact, it is two patches combined. One of them optimizes enable_slot() > > > > > > slightly and the other adds the missing _OSC evaluation. > > > > > > > > > > Better, still double the output: > > > > > > > > > > $ dmesg | wc > > > > > 2169 19047 152710 > > > > > > > > I see. > > > > > > > > What about the timing? > > > > > > ~40s below vs ~29s for acpiphp config'd out above. > > > > Well, that's better than before. > > > > I'll prepare "official" patches with the last changes then too. > > > > > > > $ dmesg | tail --lines=1 > > > > > [ 39.980918] Ebtables v2.0 registered > > > > > > > > > > Here's another interesting stat: > > > > > > > > > > $ dmesg | colrm 1 15 | sort | uniq -c | sort -nr | head --lines=25 > > > > > 73 pci 0000:00:1f.0: BAR 13: [io 0x1000-0x107f] has bogus alignment > > > > > 73 pci 0000:00:1e.0: PCI bridge to [bus 06] > > > > > 64 pci 0000:00:1e.0: bridge window [mem 0x81100000-0x812fffff 64bit pref] > > > > > 64 pci 0000:00:1e.0: bridge window [mem 0x80f00000-0x810fffff] > > > > > 64 pci 0000:00:1e.0: bridge window [io 0x7000-0x7fff] > > > > > 38 pci 0000:00:1c.4: PCI bridge to [bus 05] > > > > > 38 pci 0000:00:1c.4: bridge window [mem 0xf4f00000-0xf4ffffff] > > > > > 38 pci 0000:00:1c.0: PCI bridge to [bus 04] > > > > > 38 pci 0000:00:07.0: PCI bridge to [bus 03] > > > > > 38 pci 0000:00:07.0: bridge window [mem 0xf2000000-0xf40fffff] > > > > > 38 pci 0000:00:07.0: bridge window [mem 0xe0000000-0xf1ffffff 64bit pref] > > > > > 38 pci 0000:00:07.0: bridge window [io 0x4000-0x4fff] > > > > > 38 pci 0000:00:03.0: PCI bridge to [bus 02] > > > > > 38 pci 0000:00:03.0: bridge window [mem 0xf4e00000-0xf4efffff] > > > > > 38 pci 0000:00:03.0: bridge window [mem 0xd0000000-0xdfffffff 64bit pref] > > > > > 38 pci 0000:00:03.0: bridge window [io 0x3000-0x3fff] > > > > > 38 pci 0000:00:01.0: PCI bridge to [bus 01] > > > > > 38 pci 0000:00:01.0: bridge window [mem 0xf4100000-0xf4bfffff] > > > > > 38 pci 0000:00:01.0: bridge window [io 0x2000-0x2fff] > > > > > 37 pci 0000:00:1c.4: bridge window [mem 0x80c00000-0x80dfffff 64bit pref] > > > > > 37 pci 0000:00:1c.4: bridge window [io 0x6000-0x6fff] > > > > > 37 pci 0000:00:1c.0: bridge window [mem 0x80a00000-0x80bfffff 64bit pref] > > > > > 37 pci 0000:00:1c.0: bridge window [mem 0x80800000-0x809fffff] > > > > > 37 pci 0000:00:1c.0: bridge window [io 0x5000-0x5fff] > > > > > 36 pci 0000:00:01.0: bridge window [mem 0x80000000-0x807fffff 64bit pref] > > > > > > > > > > This is nearly the entire difference, just 25 lines repeated over and > > > > > over. > > > > Can you check how many times the lines above are repeated? > > The line count is pre-pended to each line. 73 times for the first two > line, etc. Too late, too tired. Sorry. Hmm, there's kind of too many of them given the number of notifications. Interesting. OK, I'll look deeper into things tomorrow, maybe I'll find some clues. > > > > > > > > Well, this is the bridge sizing I talked about previously. We still get > > > > apparently spurious bus check/device check events and they trigger bridge > > > > scans. > > > > > > > > I'm not sure what to do about that and I wonder whether or not this is > > > > reproducible on any other machines you can test. > > > > > > I can try it on a couple other systems, but probably not until tomorrow. > > > > Tomorrow (or even later) works just fine for me. :-) > > > > > > Can you please change dbg() to pr_info() under ACPI_NOTIFY_BUS_CHECK and > > > > ACPI_NOTIFY_DEVICE_CHECK in hotplug_event() (acpiphp_glue.c), grep the boot > > > > dmesg log for "check notify" and send the result? I'm wondering what's > > > > going on there. > > > > > > $ dmesg | grep "check notify" > > > [ 1.633228] hotplug_event: Device check notify on \_SB_.PCI0.PEX2 > > > [ 2.472004] hotplug_event: Device check notify on \_SB_.PCI0.PEX3 > > > [ 2.477288] hotplug_event: Device check notify on \_SB_.PCI0.PEX4 > > > [ 2.482571] hotplug_event: Device check notify on \_SB_.PCI0.PEX5 > > > [ 2.482579] hotplug_event: Device check notify on \_SB_.PCI0.PEX6 > > > [ 8.204953] hotplug_event: Device check notify on \_SB_.PCI0.PEX2 > > > [ 8.209632] hotplug_event: Device check notify on \_SB_.PCI0.PEX3 > > > [ 8.214272] hotplug_event: Device check notify on \_SB_.PCI0.PEX4 > > > [ 8.218894] hotplug_event: Device check notify on \_SB_.PCI0.PEX5 > > > [ 8.218901] hotplug_event: Device check notify on \_SB_.PCI0.PEX6 > > > > So I guess the PEXn things are PCIe ports and we get two notifications > > for each of them, so everything below them gets rescanned. > > > > I've just talked to Bjorn about that and we don't seem to have a good idea > > how to handle this. The notifies shouldn't be there, but we kind of have > > to handle them. > > > > I guess we could suppress the output from repeated bridge scans. Alternatively, > > we could just blacklist this particular system somehow if the problem is > > specific to it. > > Can't we determine that nothing has changed and avoid re-printing? I suppose so, but that's not going to be a simple modification, because the output is from somewhat deep in the stack. > I have a hard time believing this system is all that unique. Yes, it is quite likely that there are more systems like that. Thanks, Rafael -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@...r.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists