Re: [PATCH] revert "PCI: log vendor/device ID always"

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Bjorn Helgaas]

On Tue, Oct 2, 2012 at 8:23 AM, Nathan Zimmer <nzimmer@sgi.com> wrote:
> Revert commit id 2c6413aee215a43b1f95e218067abcde50ccbc5e
> On larger systems (256 cores+) with signifigant IO attached this single message
> represents over 20% of the messages at boot.

Is this causing a problem?  The messages are at KERN_DEBUG, so they
shouldn't be going to the console by default anyway.

I/O devices normally have at least one BAR, as well as some PME
messages, so a change like this won't affect them too much.  My guess
is that it's really the large number of CPUs, where we find all the
uncore/memory controller/etc stuff where this is a problem.  Those
devices don't have BARs, so
this line is probably the only information about them in dmesg.

> Cc: Bjorn Helgaas <bhelgaas@google.com>
> Cc: Jesse Barnes <jbarnes@virtuousgeek.org>
>
> Signed-off-by: Nathan Zimmer <nzimmer@sgi.com>
> ---
>  drivers/pci/probe.c |    4 ++--
>  1 files changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/pci/probe.c b/drivers/pci/probe.c
> index 9f8a6b7..a1add54 100644
> --- a/drivers/pci/probe.c
> +++ b/drivers/pci/probe.c
> @@ -1002,8 +1002,8 @@ int pci_setup_device(struct pci_dev *dev)
>         dev->revision = class & 0xff;
>         dev->class = class >> 8;                    /* upper 3 bytes */
>
> -       dev_printk(KERN_DEBUG, &dev->dev, "[%04x:%04x] type %02x class %#08x\n",
> -                  dev->vendor, dev->device, dev->hdr_type, dev->class);
> +       dev_dbg(&dev->dev, "[%04x:%04x] type %02x class %#08x\n",
> +               dev->vendor, dev->device, dev->hdr_type, dev->class);
>
>         /* need to have dev->class ready */
>         dev->cfg_size = pci_cfg_space_size(dev);
> --
> 1.6.0.2
>

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Nathan Zimmer]

On 10/03/2012 05:54 PM, Bjorn Helgaas wrote:
> On Tue, Oct 2, 2012 at 8:23 AM, Nathan Zimmer <nzimmer@sgi.com> wrote:
>> Revert commit id 2c6413aee215a43b1f95e218067abcde50ccbc5e
>> On larger systems (256 cores+) with signifigant IO attached this single message
>> represents over 20% of the messages at boot.
> Is this causing a problem?  The messages are at KERN_DEBUG, so they
> shouldn't be going to the console by default anyway.

The problems is that it really does tend to overwhelm dmesg on large 
systems.
This causes two issues, one is it makes it harder to notice unexpected 
messages, second it tends to push out more other messages.

At many of our customer sites the log level is set to KERN_DEBUG. It 
helps avoid reboots due to operator impatience.  Machines this large 
take significantly longer then typical to boot and seeing the extra 
messages reassures them that the kernel isn't hung.

> I/O devices normally have at least one BAR, as well as some PME
> messages, so a change like this won't affect them too much.  My guess
> is that it's really the large number of CPUs, where we find all the
> uncore/memory controller/etc stuff where this is a problem.  Those
> devices don't have BARs, so
> this line is probably the only information about them in dmesg.
It certainly appears that this is the only line about them in dmesg.

>> Cc: Bjorn Helgaas <bhelgaas@google.com>
>> Cc: Jesse Barnes <jbarnes@virtuousgeek.org>
>>
>> Signed-off-by: Nathan Zimmer <nzimmer@sgi.com>
>> ---
>>   drivers/pci/probe.c |    4 ++--
>>   1 files changed, 2 insertions(+), 2 deletions(-)
>>
>> diff --git a/drivers/pci/probe.c b/drivers/pci/probe.c
>> index 9f8a6b7..a1add54 100644
>> --- a/drivers/pci/probe.c
>> +++ b/drivers/pci/probe.c
>> @@ -1002,8 +1002,8 @@ int pci_setup_device(struct pci_dev *dev)
>>          dev->revision = class & 0xff;
>>          dev->class = class >> 8;                    /* upper 3 bytes */
>>
>> -       dev_printk(KERN_DEBUG, &dev->dev, "[%04x:%04x] type %02x class %#08x\n",
>> -                  dev->vendor, dev->device, dev->hdr_type, dev->class);
>> +       dev_dbg(&dev->dev, "[%04x:%04x] type %02x class %#08x\n",
>> +               dev->vendor, dev->device, dev->hdr_type, dev->class);
>>
>>          /* need to have dev->class ready */
>>          dev->cfg_size = pci_cfg_space_size(dev);
>> --
>> 1.6.0.2
>>

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Joe Perches]

On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
> At many of our customer sites the log level is set to KERN_DEBUG. It 
> helps avoid reboots due to operator impatience.  Machines this large 
> take significantly longer then typical to boot and seeing the extra 
> messages reassures them that the kernel isn't hung.

That argues for adding some KERN_INFO "still booting" messages
not logging unnecessary KERN_DEBUG messages.

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Nathan Zimmer]

On 10/04/2012 11:37 AM, Joe Perches wrote:
> On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
>> At many of our customer sites the log level is set to KERN_DEBUG. It
>> helps avoid reboots due to operator impatience.  Machines this large
>> take significantly longer then typical to boot and seeing the extra
>> messages reassures them that the kernel isn't hung.
> That argues for adding some KERN_INFO "still booting" messages
> not logging unnecessary KERN_DEBUG messages.
>
>
Actually I would think that argues for reducing boot times on these 
large systems.

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Joe Perches]

On Fri, 2012-10-05 at 08:55 -0500, Nathan Zimmer wrote:
> On 10/04/2012 11:37 AM, Joe Perches wrote:
> > On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
> >> At many of our customer sites the log level is set to KERN_DEBUG. It
> >> helps avoid reboots due to operator impatience.  Machines this large
> >> take significantly longer then typical to boot and seeing the extra
> >> messages reassures them that the kernel isn't hung.
> > That argues for adding some KERN_INFO "still booting" messages
> > not logging unnecessary KERN_DEBUG messages.
> >
> Actually I would think that argues for reducing boot times on these 
> large systems.

Right.

That's an independent argument, but sure, go ahead
and do that too.

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Nathan Zimmer]

On 10/05/2012 09:14 AM, Joe Perches wrote:
> On Fri, 2012-10-05 at 08:55 -0500, Nathan Zimmer wrote:
>> On 10/04/2012 11:37 AM, Joe Perches wrote:
>>> On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
>>>> At many of our customer sites the log level is set to KERN_DEBUG. It
>>>> helps avoid reboots due to operator impatience.  Machines this large
>>>> take significantly longer then typical to boot and seeing the extra
>>>> messages reassures them that the kernel isn't hung.
>>> That argues for adding some KERN_INFO "still booting" messages
>>> not logging unnecessary KERN_DEBUG messages.
>>>
>> Actually I would think that argues for reducing boot times on these
>> large systems.
> Right.
>
> That's an independent argument, but sure, go ahead
> and do that too.
>


Here is output for my workstation a simple 4x box

-bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
      12     108     804
-bash-4.1$ dmesg | wc
     744    6359   49474


Here is some output from one of the biggest boxes.

-bash-4.1$ dmesg | wc
   26503  235414 1811651
-bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
   12085  108765  821780

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Bjorn Helgaas]

On Fri, Oct 5, 2012 at 8:54 AM, Nathan Zimmer <nzimmer@sgi.com> wrote:
> On 10/05/2012 09:14 AM, Joe Perches wrote:
>>
>> On Fri, 2012-10-05 at 08:55 -0500, Nathan Zimmer wrote:
>>>
>>> On 10/04/2012 11:37 AM, Joe Perches wrote:
>>>>
>>>> On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
>>>>>
>>>>> At many of our customer sites the log level is set to KERN_DEBUG. It
>>>>> helps avoid reboots due to operator impatience.  Machines this large
>>>>> take significantly longer then typical to boot and seeing the extra
>>>>> messages reassures them that the kernel isn't hung.
>>>>
>>>> That argues for adding some KERN_INFO "still booting" messages
>>>> not logging unnecessary KERN_DEBUG messages.
>>>>
>>> Actually I would think that argues for reducing boot times on these
>>> large systems.
>>
>> Right.
>>
>> That's an independent argument, but sure, go ahead
>> and do that too.
>>
>
>
> Here is output for my workstation a simple 4x box
>
> -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
>      12     108     804
> -bash-4.1$ dmesg | wc
>     744    6359   49474
>
>
> Here is some output from one of the biggest boxes.
>
> -bash-4.1$ dmesg | wc
>   26503  235414 1811651
> -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
>   12085 108765  821780

Many vendors don't expose host bridges that lead to the CPU-related
PCI devices because they don't want the OS to muck with them.  We
currently blindly probe for these in domain 0, so we find them anyway
(I think we should change this behavior).

I'd guess that having all these CPU-related devices around also really
clutters up "lspci" output, and of course, consumes memory for all the
pci_dev structs in the kernel.  It takes some time to enumerate them
all, so avoiding that would speed up boot somewhat.

So I wonder if it might be more useful to figure out how to avoid
enumerating those devices in the first place?  The first step would be
to stop exposing PNP0A03/PNP0A08 host bridges that lead to them.  As I
mentioned, we currently will probably find them anyway via blind
probing.  You might be able to avoid that if you could place them in a
PCI domain other than 0.

Bjorn

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Joe Perches]

On Fri, 2012-10-05 at 09:16 -0600, Bjorn Helgaas wrote:
> On Fri, Oct 5, 2012 at 8:54 AM, Nathan Zimmer <nzimmer@sgi.com> wrote:
> > On 10/05/2012 09:14 AM, Joe Perches wrote:
> >> On Fri, 2012-10-05 at 08:55 -0500, Nathan Zimmer wrote:
> >>> On 10/04/2012 11:37 AM, Joe Perches wrote:
> >>>> On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
> >>>>> At many of our customer sites the log level is set to KERN_DEBUG. It
> >>>>> helps avoid reboots due to operator impatience.  Machines this large
> >>>>> take significantly longer then typical to boot and seeing the extra
> >>>>> messages reassures them that the kernel isn't hung.
> >>>>
> >>>> That argues for adding some KERN_INFO "still booting" messages
> >>>> not logging unnecessary KERN_DEBUG messages.
> >>>>
> >>> Actually I would think that argues for reducing boot times on these
> >>> large systems.
> >>
> >> Right.
> >>
> >> That's an independent argument, but sure, go ahead
> >> and do that too.
[]
> > Here is output for my workstation a simple 4x box
> >
> > -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
> >      12     108     804
> > -bash-4.1$ dmesg | wc
> >     744    6359   49474
> > Here is some output from one of the biggest boxes.
> > -bash-4.1$ dmesg | wc
> >   26503  235414 1811651
> > -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
> >   12085 108765  821780
> 
> Many vendors don't expose host bridges that lead to the CPU-related
> PCI devices because they don't want the OS to muck with them.  We
> currently blindly probe for these in domain 0, so we find them anyway
> (I think we should change this behavior).
> 
> I'd guess that having all these CPU-related devices around also really
> clutters up "lspci" output, and of course, consumes memory for all the
> pci_dev structs in the kernel.  It takes some time to enumerate them
> all, so avoiding that would speed up boot somewhat.
> 
> So I wonder if it might be more useful to figure out how to avoid
> enumerating those devices in the first place?  The first step would be
> to stop exposing PNP0A03/PNP0A08 host bridges that lead to them.  As I
> mentioned, we currently will probably find them anyway via blind
> probing.  You might be able to avoid that if you could place them in a
> PCI domain other than 0

And in the meantime, maybe something like this and not logging
at KERN_DEBUG when using verbose_boot would help avoid impatient
operator reboots.

 drivers/pci/hotplug/sgi_hotplug.c |    4 ++++
 1 file changed, 4 insertions(+)

diff --git a/drivers/pci/hotplug/sgi_hotplug.c b/drivers/pci/hotplug/sgi_hotplug.c
index f64ca92..b3abd1a 100644
--- a/drivers/pci/hotplug/sgi_hotplug.c
+++ b/drivers/pci/hotplug/sgi_hotplug.c
@@ -368,6 +368,10 @@ static int enable_slot(struct hotplug_slot *bss_hotplug_slot)
 		}
 	}
 
+	if (some_verbose_boot_flag)
+		dev_info(&slot->pci_bus->self->dev, "Testing slot %d\n",
+			 slot->device_num + 1);
+
 	num_funcs = pci_scan_slot(slot->pci_bus,
 				  PCI_DEVFN(slot->device_num + 1, 0));
 	if (!num_funcs) {

Re: [PATCH] revert "PCI: log vendor/device ID always"

[Nathan Zimmer]

On 10/05/2012 10:16 AM, Bjorn Helgaas wrote:
> On Fri, Oct 5, 2012 at 8:54 AM, Nathan Zimmer <nzimmer@sgi.com> wrote:
>> On 10/05/2012 09:14 AM, Joe Perches wrote:
>>> On Fri, 2012-10-05 at 08:55 -0500, Nathan Zimmer wrote:
>>>> On 10/04/2012 11:37 AM, Joe Perches wrote:
>>>>> On Thu, 2012-10-04 at 11:02 -0500, Nathan Zimmer wrote:
>>>>>> At many of our customer sites the log level is set to KERN_DEBUG. It
>>>>>> helps avoid reboots due to operator impatience.  Machines this large
>>>>>> take significantly longer then typical to boot and seeing the extra
>>>>>> messages reassures them that the kernel isn't hung.
>>>>> That argues for adding some KERN_INFO "still booting" messages
>>>>> not logging unnecessary KERN_DEBUG messages.
>>>>>
>>>> Actually I would think that argues for reducing boot times on these
>>>> large systems.
>>> Right.
>>>
>>> That's an independent argument, but sure, go ahead
>>> and do that too.
>>>
>>
>> Here is output for my workstation a simple 4x box
>>
>> -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
>>       12     108     804
>> -bash-4.1$ dmesg | wc
>>      744    6359   49474
>>
>>
>> Here is some output from one of the biggest boxes.
>>
>> -bash-4.1$ dmesg | wc
>>    26503  235414 1811651
>> -bash-4.1$ dmesg | grep "type [0-9][0-9] class" | wc
>>    12085 108765  821780
> Many vendors don't expose host bridges that lead to the CPU-related
> PCI devices because they don't want the OS to muck with them.  We
> currently blindly probe for these in domain 0, so we find them anyway
> (I think we should change this behavior).
>
> I'd guess that having all these CPU-related devices around also really
> clutters up "lspci" output, and of course, consumes memory for all the
> pci_dev structs in the kernel.  It takes some time to enumerate them
> all, so avoiding that would speed up boot somewhat.

Yea now that you mention it lspci is quite cluttered.

>
> So I wonder if it might be more useful to figure out how to avoid
> enumerating those devices in the first place?  The first step would be
> to stop exposing PNP0A03/PNP0A08 host bridges that lead to them.  As I
> mentioned, we currently will probably find them anyway via blind
> probing.  You might be able to avoid that if you could place them in a
> PCI domain other than 0.
>
> Bjorn

This seems like a better way to go.  I'll start digging down this route.