ehci-pci D3cold logspam

Submitted by Bjorn Helgaas on Sept. 23, 2013, 9:28 p.m.

Details

Message ID CAErSpo4SGnM4Ycy=YRbdMox2b0JE=P=J_1-7HpPMwEy+=rJDjQ@mail.gmail.com
State Accepted
Headers show

Commit Message

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

Comments

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 hide | download patch | download mbox

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