Patchwork ehci-pci D3cold logspam

login
register
mail settings
Submitter Bjorn Helgaas
Date Sept. 23, 2013, 9:28 p.m.
Message ID <CAErSpo4SGnM4Ycy=YRbdMox2b0JE=P=J_1-7HpPMwEy+=rJDjQ@mail.gmail.com>
Download mbox | patch
Permalink /patch/277306/
State Accepted
Headers show

Comments

Bjorn Helgaas - Sept. 23, 2013, 9:28 p.m.
[+cc Rafael, linux-pm]

On Mon, Sep 23, 2013 at 1:36 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
> On Mon, 23 Sep 2013, Andy Lutomirski wrote:
>
>> I've been getting this on several recent kernel revisions.  Is it
>> interesting?  If so, I'm happy to help diagnose it.  If not, can the
>> message be killed or severely ratelimited?  I'm getting so much of
>> this that it tends to overflow the log ring.
>
> It's interesting only if you care about when your EHCI controllers get
> resumed and suspended.  In this case, it's not clear why the
> transitions happen so rapidly.  It looks like some sort of polling
> is going on at roughly 2-second intervals.
>
>> [  287.344991] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
>> [  287.445433] ehci-pci 0000:00:1d.0: setting latency timer to 64
>> [  287.446255] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
>> [  287.456094] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
>> [  287.547205] ehci-pci 0000:00:1a.0: setting latency timer to 64
>> [  287.557890] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
>> [  290.126910] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
>> [  290.227958] ehci-pci 0000:00:1d.0: setting latency timer to 64
>> [  290.228416] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
>> [  290.238749] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
>> [  290.328904] ehci-pci 0000:00:1a.0: setting latency timer to 64
>> [  290.339565] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
>> [  292.214834] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
>> [  292.315458] ehci-pci 0000:00:1d.0: setting latency timer to 64
>> [  292.315908] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
>> [  292.326262] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
>> [  292.416487] ehci-pci 0000:00:1a.0: setting latency timer to 64
>> [  292.431075] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
>> [  295.458048] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
>> [  295.558613] ehci-pci 0000:00:1d.0: setting latency timer to 64
>
> This question should be addressed to the PCI mailing list (cc'ed), as
> those two messages are generated by
> drivers/pci/pci-acpi.c:acpi_pci_set_power_state() and
> drivers/pci/pci.c:pcibios_set_master() respectively.

d010e5769 ("PCI / ACPI: Use dev_dbg() instead of dev_info() in
acpi_pci_set_power_state()") might be part of the solution.  That was
done in response to https://bugzilla.kernel.org/show_bug.cgi?id=60636,
which looks basically the same as your complaint.

But if we are indeed polling every two seconds, even a dev_dbg() seems
like overkill to me.  Rafael or Lan can probably provide a better
answer here.

As for the "setting latency timer" messages, I really doubt those are
useful to anybody.  If nobody objects, I'll just drop it, e.g.:

the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Rafael J. Wysocki - Sept. 23, 2013, 11:14 p.m.
On Monday, September 23, 2013 04:28:49 PM Bjorn Helgaas wrote:
> [+cc Rafael, linux-pm]
> 
> On Mon, Sep 23, 2013 at 1:36 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
> > On Mon, 23 Sep 2013, Andy Lutomirski wrote:
> >
> >> I've been getting this on several recent kernel revisions.  Is it
> >> interesting?  If so, I'm happy to help diagnose it.  If not, can the
> >> message be killed or severely ratelimited?  I'm getting so much of
> >> this that it tends to overflow the log ring.
> >
> > It's interesting only if you care about when your EHCI controllers get
> > resumed and suspended.  In this case, it's not clear why the
> > transitions happen so rapidly.  It looks like some sort of polling
> > is going on at roughly 2-second intervals.
> >
> >> [  287.344991] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
> >> [  287.445433] ehci-pci 0000:00:1d.0: setting latency timer to 64
> >> [  287.446255] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
> >> [  287.456094] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
> >> [  287.547205] ehci-pci 0000:00:1a.0: setting latency timer to 64
> >> [  287.557890] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
> >> [  290.126910] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
> >> [  290.227958] ehci-pci 0000:00:1d.0: setting latency timer to 64
> >> [  290.228416] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
> >> [  290.238749] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
> >> [  290.328904] ehci-pci 0000:00:1a.0: setting latency timer to 64
> >> [  290.339565] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
> >> [  292.214834] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
> >> [  292.315458] ehci-pci 0000:00:1d.0: setting latency timer to 64
> >> [  292.315908] ehci-pci 0000:00:1a.0: power state changed by ACPI to D0
> >> [  292.326262] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
> >> [  292.416487] ehci-pci 0000:00:1a.0: setting latency timer to 64
> >> [  292.431075] ehci-pci 0000:00:1a.0: power state changed by ACPI to D3cold
> >> [  295.458048] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
> >> [  295.558613] ehci-pci 0000:00:1d.0: setting latency timer to 64
> >
> > This question should be addressed to the PCI mailing list (cc'ed), as
> > those two messages are generated by
> > drivers/pci/pci-acpi.c:acpi_pci_set_power_state() and
> > drivers/pci/pci.c:pcibios_set_master() respectively.
> 
> d010e5769 ("PCI / ACPI: Use dev_dbg() instead of dev_info() in
> acpi_pci_set_power_state()") might be part of the solution.  That was
> done in response to https://bugzilla.kernel.org/show_bug.cgi?id=60636,
> which looks basically the same as your complaint.
> 
> But if we are indeed polling every two seconds, even a dev_dbg() seems
> like overkill to me.  Rafael or Lan can probably provide a better
> answer here.

I'd like to be able to see if ACPI PM is called for devices at least in
debug mode.  Otherwise it's difficult to say why things don't work sometimes.

Thanks,
Rafael

--
To unsubscribe from this list: send the line "unsubscribe linux-pci" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Alan Stern - Sept. 24, 2013, 2:12 p.m.
On Mon, 23 Sep 2013, Bjorn Helgaas wrote:

> d010e5769 ("PCI / ACPI: Use dev_dbg() instead of dev_info() in
> acpi_pci_set_power_state()") might be part of the solution.  That was
> done in response to https://bugzilla.kernel.org/show_bug.cgi?id=60636,
> which looks basically the same as your complaint.
> 
> But if we are indeed polling every two seconds, even a dev_dbg() seems
> like overkill to me.  Rafael or Lan can probably provide a better
> answer here.
> 
> As for the "setting latency timer" messages, I really doubt those are
> useful to anybody.  If nobody objects, I'll just drop it, e.g.:
> 
> diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
> index b821a62..55a947b 100644
> --- a/drivers/pci/pci.c
> +++ b/drivers/pci/pci.c
> @@ -2854,7 +2854,7 @@ void __weak pcibios_set_master(struct pci_dev *dev)
>                 lat = pcibios_max_latency;
>         else
>                 return;
> -       dev_printk(KERN_DEBUG, &dev->dev, "setting latency timer to %d\n", lat);
> +
>         pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
>  }

No objection from me.

Alan Stern

--
To unsubscribe from this list: send the line "unsubscribe linux-pci" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Patch

diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
index b821a62..55a947b 100644
--- a/drivers/pci/pci.c
+++ b/drivers/pci/pci.c
@@ -2854,7 +2854,7 @@  void __weak pcibios_set_master(struct pci_dev *dev)
                lat = pcibios_max_latency;
        else
                return;
-       dev_printk(KERN_DEBUG, &dev->dev, "setting latency timer to %d\n", lat);
+
        pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
 }
--
To unsubscribe from this list: send the line "unsubscribe linux-pci" in