[RFC] PM / Runtime: decrease verbosity in kernel log

[RFC] PM / Runtime: decrease verbosity in kernel log

[Vincent Palatin]

When activating the PCI runtime PM on a laptop, my kernel log is filled with
messages such as the following ones and can be hardly read to find interesting
information:
ehci_hcd 0000:00:1d.7: PME# disabled
ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:1d.7: setting latency timer to 64
ehci_hcd 0000:00:1d.7: PCI INT A disabled
ehci_hcd 0000:00:1d.7: PME# enabled
ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
ehci_hcd 0000:00:1d.7: PME# disabled
ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ehci_hcd 0000:00:1d.7: setting latency timer to 64
ehci_hcd 0000:00:1d.7: PCI INT A disabled
ehci_hcd 0000:00:1d.7: PME# enabled
ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff]

All those messages are triggered by the following cause, the laptop has a USB
3G modem with USB autosuspend activated. The USB device will wake up about
every 30s to do some network related activities. Every time, the modem wakes
up this triggers the wake up of the attached EHCI/PCI USB host controller
which reconfigures its PCI interface, then everything go back to a suspended mode.

Having the same 10 lines of log repeated is not really useful, but I probably
cannot totally remove them since there are somewhat useful for PCI hotplug
users and other PCI debugging.
So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
outputs traces only when the device has not the runtime PM activated,
and guard those traces with it.
(cf the 2 patches in this thread as a PoC)

--
Vincent

[PATCH 1/2] PM / Runtime: add conditional trace macro

[Vincent Palatin]

Add a new "dev_printk_norpm" macro which prints the trace only when the
device has not the runtime PM activated.
Some traces (e.g. PCI configuration) are useful in default mode but when
the runtime PM is activated, they become very noisy if the device is
often enabled/disabled.

If needed, CONFIG_PM_VERBOSE will re-activate all the original traces.

Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
---
 include/linux/pm_runtime.h |   12 ++++++++++++
 1 files changed, 12 insertions(+), 0 deletions(-)

diff --git a/include/linux/pm_runtime.h b/include/linux/pm_runtime.h
index daac05d..57da18c 100644
--- a/include/linux/pm_runtime.h
+++ b/include/linux/pm_runtime.h
@@ -22,6 +22,18 @@
 					    usage_count */
 #define RPM_AUTO		0x08	/* Use autosuspend_delay */
 
+/* print trace only if the runtime PM is not activated on the device */
+#ifdef CONFIG_PM_VERBOSE
+#define dev_printk_norpm(level, dev, format, ...)      \
+	dev_printk(level, dev, format, ##__VA_ARGS__);
+#else
+#define dev_printk_norpm(level, dev, format, ...)              \
+({                                                             \
+	if (!pm_runtime_enabled(dev))                          \
+		dev_printk(level, dev, format, ##__VA_ARGS__); \
+})
+#endif
+
 #ifdef CONFIG_PM_RUNTIME
 
 extern struct workqueue_struct *pm_wq;
-- 
1.7.3.1

[PATCH 2/2] PM / Runtime: make PCI traces quieter

[Vincent Palatin]

When the runtime PM is activated on PCI, if a device switches state
frequently (e.g. an EHCI controller with autosuspending USB devices
connected) the PCI configuration traces might be very verbose in the
kernel log. Let's desactivate them in such a situation.

Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
---
 arch/x86/pci/i386.c     |    4 +++-
 drivers/acpi/pci_irq.c  |   15 ++++++++++-----
 drivers/pci/pci.c       |   11 ++++++-----
 drivers/pci/setup-res.c |    8 +++++---
 4 files changed, 24 insertions(+), 14 deletions(-)

diff --git a/arch/x86/pci/i386.c b/arch/x86/pci/i386.c
index 494f2e7..2bb0e1e 100644
--- a/arch/x86/pci/i386.c
+++ b/arch/x86/pci/i386.c
@@ -31,6 +31,7 @@
 #include <linux/ioport.h>
 #include <linux/errno.h>
 #include <linux/bootmem.h>
+#include <linux/pm_runtime.h>
 
 #include <asm/pat.h>
 #include <asm/e820.h>
@@ -269,7 +270,8 @@ void 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);
+	dev_printk_norpm(KERN_DEBUG, &dev->dev,
+			 "setting latency timer to %d\n", lat);
 	pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
 }
 
diff --git a/drivers/acpi/pci_irq.c b/drivers/acpi/pci_irq.c
index 7f9eba9..8cc1194 100644
--- a/drivers/acpi/pci_irq.c
+++ b/drivers/acpi/pci_irq.c
@@ -34,6 +34,7 @@
 #include <linux/types.h>
 #include <linux/spinlock.h>
 #include <linux/pm.h>
+#include <linux/pm_runtime.h>
 #include <linux/pci.h>
 #include <linux/acpi.h>
 #include <linux/slab.h>
@@ -487,10 +488,13 @@ int acpi_pci_irq_enable(struct pci_dev *dev)
 	else
 		link_desc[0] = '\0';
 
-	dev_info(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
-		 pin_name(pin), link_desc, gsi,
-		 (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
-		 (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
+	dev_printk_norpm(KERN_INFO, &dev->dev, "PCI INT %c%s -> "
+			 "GSI %u (%s, %s) -> IRQ %d\n",
+			 pin_name(pin), link_desc, gsi,
+			 (triggering == ACPI_LEVEL_SENSITIVE) ?
+			 "level" : "edge",
+			 (polarity == ACPI_ACTIVE_LOW) ?
+			 "low" : "high", dev->irq);
 
 	return 0;
 }
@@ -524,6 +528,7 @@ void acpi_pci_irq_disable(struct pci_dev *dev)
 	 * (e.g. PCI_UNDEFINED_IRQ).
 	 */
 
-	dev_info(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
+	dev_printk_norpm(KERN_INFO, &dev->dev, "PCI INT %c disabled\n",
+			 pin_name(pin));
 	acpi_unregister_gsi(gsi);
 }
diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
index 0ce6742..9f6b48c 100644
--- a/drivers/pci/pci.c
+++ b/drivers/pci/pci.c
@@ -964,9 +964,10 @@ void pci_restore_state(struct pci_dev *dev)
 	for (i = 15; i >= 0; i--) {
 		pci_read_config_dword(dev, i * 4, &val);
 		if (val != dev->saved_config_space[i]) {
-			dev_printk(KERN_DEBUG, &dev->dev, "restoring config "
-				"space at offset %#x (was %#x, writing %#x)\n",
-				i, val, (int)dev->saved_config_space[i]);
+			dev_printk_norpm(KERN_DEBUG, &dev->dev,
+					 "restoring space at offset %#x "
+					 "(was %#x, writing %#x)\n", i, val,
+					 (int)dev->saved_config_space[i]);
 			pci_write_config_dword(dev,i * 4,
 				dev->saved_config_space[i]);
 		}
@@ -1531,8 +1532,8 @@ void pci_pme_active(struct pci_dev *dev, bool enable)
 	}
 
 out:
-	dev_printk(KERN_DEBUG, &dev->dev, "PME# %s\n",
-			enable ? "enabled" : "disabled");
+	dev_printk_norpm(KERN_DEBUG, &dev->dev, "PME# %s\n",
+			 enable ? "enabled" : "disabled");
 }
 
 /**
diff --git a/drivers/pci/setup-res.c b/drivers/pci/setup-res.c
index 51a9095..942399c 100644
--- a/drivers/pci/setup-res.c
+++ b/drivers/pci/setup-res.c
@@ -23,6 +23,7 @@
 #include <linux/ioport.h>
 #include <linux/cache.h>
 #include <linux/slab.h>
+#include <linux/pm_runtime.h>
 #include "pci.h"
 
 
@@ -84,9 +85,10 @@ void pci_update_resource(struct pci_dev *dev, int resno)
 		}
 	}
 	res->flags &= ~IORESOURCE_UNSET;
-	dev_info(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
-		 resno, res, (unsigned long long)region.start,
-		 (unsigned long long)region.end);
+	dev_printk_norpm(KERN_INFO, &dev->dev,
+			 "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
+			 resno, res, (unsigned long long)region.start,
+			 (unsigned long long)region.end);
 }
 
 int pci_claim_resource(struct pci_dev *dev, int resource)
-- 
1.7.3.1

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Alan Stern]

On Fri, 16 Sep 2011, Vincent Palatin wrote:

> When activating the PCI runtime PM on a laptop, my kernel log is filled with
> messages such as the following ones and can be hardly read to find interesting
> information:
> ehci_hcd 0000:00:1d.7: PME# disabled
> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
> ehci_hcd 0000:00:1d.7: setting latency timer to 64
> ehci_hcd 0000:00:1d.7: PCI INT A disabled
> ehci_hcd 0000:00:1d.7: PME# enabled
> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
...

> All those messages are triggered by the following cause, the laptop has a USB
> 3G modem with USB autosuspend activated. The USB device will wake up about
> every 30s to do some network related activities. Every time, the modem wakes
> up this triggers the wake up of the attached EHCI/PCI USB host controller
> which reconfigures its PCI interface, then everything go back to a suspended mode.
> 
> Having the same 10 lines of log repeated is not really useful, but I probably
> cannot totally remove them since there are somewhat useful for PCI hotplug
> users and other PCI debugging.
> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
> outputs traces only when the device has not the runtime PM activated,
> and guard those traces with it.
> (cf the 2 patches in this thread as a PoC)

Wouldn't it be easier just to change the existing messages to DEBUG 
level?  Or are they more important than that?

Alan Stern

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Vincent Palatin]

On Sat, Sep 17, 2011 at 09:23, Alan Stern <stern@rowland.harvard.edu> wrote:
> On Fri, 16 Sep 2011, Vincent Palatin wrote:
>
>> When activating the PCI runtime PM on a laptop, my kernel log is filled with
>> messages such as the following ones and can be hardly read to find interesting
>> information:
>> ehci_hcd 0000:00:1d.7: PME# disabled
>> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
>> ehci_hcd 0000:00:1d.7: setting latency timer to 64
>> ehci_hcd 0000:00:1d.7: PCI INT A disabled
>> ehci_hcd 0000:00:1d.7: PME# enabled
>> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
>> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
>> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
> ...
>
>> All those messages are triggered by the following cause, the laptop has a USB
>> 3G modem with USB autosuspend activated. The USB device will wake up about
>> every 30s to do some network related activities. Every time, the modem wakes
>> up this triggers the wake up of the attached EHCI/PCI USB host controller
>> which reconfigures its PCI interface, then everything go back to a suspended mode.
>>
>> Having the same 10 lines of log repeated is not really useful, but I probably
>> cannot totally remove them since there are somewhat useful for PCI hotplug
>> users and other PCI debugging.
>> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
>> outputs traces only when the device has not the runtime PM activated,
>> and guard those traces with it.
>> (cf the 2 patches in this thread as a PoC)
>
> Wouldn't it be easier just to change the existing messages to DEBUG
> level?  Or are they more important than that?

Yes, I can simply replace all those printk by dev_dbg traces. For my
use case, it's perfect.
My main concern was people using PCI hotplug, I think, then, their log
will remain mostly silent when inserting a card, I don't know if this
is acceptable or not.

-- 
Vincent Palatin

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Rafael J. Wysocki]

On Monday, September 19, 2011, Vincent Palatin wrote:
> On Sat, Sep 17, 2011 at 09:23, Alan Stern <stern@rowland.harvard.edu> wrote:
> > On Fri, 16 Sep 2011, Vincent Palatin wrote:
> >
> >> When activating the PCI runtime PM on a laptop, my kernel log is filled with
> >> messages such as the following ones and can be hardly read to find interesting
> >> information:
> >> ehci_hcd 0000:00:1d.7: PME# disabled
> >> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
> >> ehci_hcd 0000:00:1d.7: setting latency timer to 64
> >> ehci_hcd 0000:00:1d.7: PCI INT A disabled
> >> ehci_hcd 0000:00:1d.7: PME# enabled
> >> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
> > ...
> >
> >> All those messages are triggered by the following cause, the laptop has a USB
> >> 3G modem with USB autosuspend activated. The USB device will wake up about
> >> every 30s to do some network related activities. Every time, the modem wakes
> >> up this triggers the wake up of the attached EHCI/PCI USB host controller
> >> which reconfigures its PCI interface, then everything go back to a suspended mode.
> >>
> >> Having the same 10 lines of log repeated is not really useful, but I probably
> >> cannot totally remove them since there are somewhat useful for PCI hotplug
> >> users and other PCI debugging.
> >> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
> >> outputs traces only when the device has not the runtime PM activated,
> >> and guard those traces with it.
> >> (cf the 2 patches in this thread as a PoC)
> >
> > Wouldn't it be easier just to change the existing messages to DEBUG
> > level?  Or are they more important than that?
> 
> Yes, I can simply replace all those printk by dev_dbg traces. For my
> use case, it's perfect.
> My main concern was people using PCI hotplug, I think, then, their log
> will remain mostly silent when inserting a card, I don't know if this
> is acceptable or not.

I think they don't really need that information except for debugging, right?

Rafael

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Vincent Palatin]

On Mon, Sep 19, 2011 at 14:08, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> On Monday, September 19, 2011, Vincent Palatin wrote:
>> On Sat, Sep 17, 2011 at 09:23, Alan Stern <stern@rowland.harvard.edu> wrote:
>> > On Fri, 16 Sep 2011, Vincent Palatin wrote:
>> >
>> >> When activating the PCI runtime PM on a laptop, my kernel log is filled with
>> >> messages such as the following ones and can be hardly read to find interesting
>> >> information:
>> >> ehci_hcd 0000:00:1d.7: PME# disabled
>> >> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
>> >> ehci_hcd 0000:00:1d.7: setting latency timer to 64
>> >> ehci_hcd 0000:00:1d.7: PCI INT A disabled
>> >> ehci_hcd 0000:00:1d.7: PME# enabled
>> >> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
>> > ...
>> >
>> >> All those messages are triggered by the following cause, the laptop has a USB
>> >> 3G modem with USB autosuspend activated. The USB device will wake up about
>> >> every 30s to do some network related activities. Every time, the modem wakes
>> >> up this triggers the wake up of the attached EHCI/PCI USB host controller
>> >> which reconfigures its PCI interface, then everything go back to a suspended mode.
>> >>
>> >> Having the same 10 lines of log repeated is not really useful, but I probably
>> >> cannot totally remove them since there are somewhat useful for PCI hotplug
>> >> users and other PCI debugging.
>> >> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
>> >> outputs traces only when the device has not the runtime PM activated,
>> >> and guard those traces with it.
>> >> (cf the 2 patches in this thread as a PoC)
>> >
>> > Wouldn't it be easier just to change the existing messages to DEBUG
>> > level?  Or are they more important than that?
>>
>> Yes, I can simply replace all those printk by dev_dbg traces. For my
>> use case, it's perfect.
>> My main concern was people using PCI hotplug, I think, then, their log
>> will remain mostly silent when inserting a card, I don't know if this
>> is acceptable or not.
>
> I think they don't really need that information except for debugging, right?

I think so.
I will send a new patch with dev_dbg in replacement of the noisy
printks for PCI messages.

-- 
Vincent

[PATCH] PM / Runtime: make PCI traces quieter

[Vincent Palatin]

When the runtime PM is activated on PCI, if a device switches state frequently
(e.g. an EHCI controller with autosuspending USB devices connected)
the PCI configuration traces might be very verbose in the kernel log.
Let's guard those traces with DEBUG condition.

Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
---
 arch/x86/pci/i386.c     |    2 +-
 drivers/acpi/pci_irq.c  |   10 +++++-----
 drivers/pci/pci.c       |    5 ++---
 drivers/pci/setup-res.c |    6 +++---
 4 files changed, 11 insertions(+), 12 deletions(-)

diff --git a/arch/x86/pci/i386.c b/arch/x86/pci/i386.c
index 494f2e7..eb5d20b 100644
--- a/arch/x86/pci/i386.c
+++ b/arch/x86/pci/i386.c
@@ -269,7 +269,7 @@ void 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);
+	dev_dbg(&dev->dev, "setting latency timer to %d\n", lat);
 	pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
 }
 
diff --git a/drivers/acpi/pci_irq.c b/drivers/acpi/pci_irq.c
index 7f9eba9..0eefa12 100644
--- a/drivers/acpi/pci_irq.c
+++ b/drivers/acpi/pci_irq.c
@@ -487,10 +487,10 @@ int acpi_pci_irq_enable(struct pci_dev *dev)
 	else
 		link_desc[0] = '\0';
 
-	dev_info(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
-		 pin_name(pin), link_desc, gsi,
-		 (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
-		 (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
+	dev_dbg(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
+		pin_name(pin), link_desc, gsi,
+		(triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
+		(polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
 
 	return 0;
 }
@@ -524,6 +524,6 @@ void acpi_pci_irq_disable(struct pci_dev *dev)
 	 * (e.g. PCI_UNDEFINED_IRQ).
 	 */
 
-	dev_info(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
+	dev_dbg(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
 	acpi_unregister_gsi(gsi);
 }
diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
index 0ce6742..d339c30 100644
--- a/drivers/pci/pci.c
+++ b/drivers/pci/pci.c
@@ -964,7 +964,7 @@ void pci_restore_state(struct pci_dev *dev)
 	for (i = 15; i >= 0; i--) {
 		pci_read_config_dword(dev, i * 4, &val);
 		if (val != dev->saved_config_space[i]) {
-			dev_printk(KERN_DEBUG, &dev->dev, "restoring config "
+			dev_dbg(&dev->dev, "restoring config "
 				"space at offset %#x (was %#x, writing %#x)\n",
 				i, val, (int)dev->saved_config_space[i]);
 			pci_write_config_dword(dev,i * 4,
@@ -1531,8 +1531,7 @@ void pci_pme_active(struct pci_dev *dev, bool enable)
 	}
 
 out:
-	dev_printk(KERN_DEBUG, &dev->dev, "PME# %s\n",
-			enable ? "enabled" : "disabled");
+	dev_dbg(&dev->dev, "PME# %s\n", enable ? "enabled" : "disabled");
 }
 
 /**
diff --git a/drivers/pci/setup-res.c b/drivers/pci/setup-res.c
index 51a9095..3878fe9 100644
--- a/drivers/pci/setup-res.c
+++ b/drivers/pci/setup-res.c
@@ -84,9 +84,9 @@ void pci_update_resource(struct pci_dev *dev, int resno)
 		}
 	}
 	res->flags &= ~IORESOURCE_UNSET;
-	dev_info(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
-		 resno, res, (unsigned long long)region.start,
-		 (unsigned long long)region.end);
+	dev_dbg(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
+		resno, res, (unsigned long long)region.start,
+		(unsigned long long)region.end);
 }
 
 int pci_claim_resource(struct pci_dev *dev, int resource)
-- 
1.7.3.1

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Yinghai Lu]

On Wed, Sep 21, 2011 at 10:24 AM, Vincent Palatin <vpalatin@chromium.org> wrote:
> On Mon, Sep 19, 2011 at 14:08, Rafael J. Wysocki <rjw@sisk.pl> wrote:
>> On Monday, September 19, 2011, Vincent Palatin wrote:
>>> On Sat, Sep 17, 2011 at 09:23, Alan Stern <stern@rowland.harvard.edu> wrote:
>>> > On Fri, 16 Sep 2011, Vincent Palatin wrote:
>>> >
>>> >> When activating the PCI runtime PM on a laptop, my kernel log is filled with
>>> >> messages such as the following ones and can be hardly read to find interesting
>>> >> information:
>>> >> ehci_hcd 0000:00:1d.7: PME# disabled
>>> >> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
>>> >> ehci_hcd 0000:00:1d.7: setting latency timer to 64
>>> >> ehci_hcd 0000:00:1d.7: PCI INT A disabled
>>> >> ehci_hcd 0000:00:1d.7: PME# enabled
>>> >> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
>>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
>>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
>>> > ...
>>> >
>>> >> All those messages are triggered by the following cause, the laptop has a USB
>>> >> 3G modem with USB autosuspend activated. The USB device will wake up about
>>> >> every 30s to do some network related activities. Every time, the modem wakes
>>> >> up this triggers the wake up of the attached EHCI/PCI USB host controller
>>> >> which reconfigures its PCI interface, then everything go back to a suspended mode.
>>> >>
>>> >> Having the same 10 lines of log repeated is not really useful, but I probably
>>> >> cannot totally remove them since there are somewhat useful for PCI hotplug
>>> >> users and other PCI debugging.
>>> >> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
>>> >> outputs traces only when the device has not the runtime PM activated,
>>> >> and guard those traces with it.
>>> >> (cf the 2 patches in this thread as a PoC)
>>> >
>>> > Wouldn't it be easier just to change the existing messages to DEBUG
>>> > level?  Or are they more important than that?
>>>
>>> Yes, I can simply replace all those printk by dev_dbg traces. For my
>>> use case, it's perfect.
>>> My main concern was people using PCI hotplug, I think, then, their log
>>> will remain mostly silent when inserting a card, I don't know if this
>>> is acceptable or not.
>>
>> I think they don't really need that information except for debugging, right?
>
> I think so.
> I will send a new patch with dev_dbg in replacement of the noisy
> printks for PCI messages.
>

please use dev_printk(KERN_DEBUG,...) instead. otherwise will need
recompile the kernel with DEBUG enabled
to get debug message with debug in boot command line.

Yinghai

Re: [RFC] PM / Runtime: decrease verbosity in kernel log

[Rafael J. Wysocki]

On Wednesday, September 21, 2011, Yinghai Lu wrote:
> On Wed, Sep 21, 2011 at 10:24 AM, Vincent Palatin <vpalatin@chromium.org> wrote:
> > On Mon, Sep 19, 2011 at 14:08, Rafael J. Wysocki <rjw@sisk.pl> wrote:
> >> On Monday, September 19, 2011, Vincent Palatin wrote:
> >>> On Sat, Sep 17, 2011 at 09:23, Alan Stern <stern@rowland.harvard.edu> wrote:
> >>> > On Fri, 16 Sep 2011, Vincent Palatin wrote:
> >>> >
> >>> >> When activating the PCI runtime PM on a laptop, my kernel log is filled with
> >>> >> messages such as the following ones and can be hardly read to find interesting
> >>> >> information:
> >>> >> ehci_hcd 0000:00:1d.7: PME# disabled
> >>> >> ehci_hcd 0000:00:1d.7: PCI INT A -> GSI 16 (level, low) -> IRQ 16
> >>> >> ehci_hcd 0000:00:1d.7: setting latency timer to 64
> >>> >> ehci_hcd 0000:00:1d.7: PCI INT A disabled
> >>> >> ehci_hcd 0000:00:1d.7: PME# enabled
> >>> >> ehci_hcd 0000:00:1d.7: BAR 0: set to [mem 0x92205000-0x922053ff] (PCI address [0x92205000-0x922053ff])
> >>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0xf (was 0x100, writing 0x10b)
> >>> >> ehci_hcd 0000:00:1d.7: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900002)
> >>> > ...
> >>> >
> >>> >> All those messages are triggered by the following cause, the laptop has a USB
> >>> >> 3G modem with USB autosuspend activated. The USB device will wake up about
> >>> >> every 30s to do some network related activities. Every time, the modem wakes
> >>> >> up this triggers the wake up of the attached EHCI/PCI USB host controller
> >>> >> which reconfigures its PCI interface, then everything go back to a suspended mode.
> >>> >>
> >>> >> Having the same 10 lines of log repeated is not really useful, but I probably
> >>> >> cannot totally remove them since there are somewhat useful for PCI hotplug
> >>> >> users and other PCI debugging.
> >>> >> So, my proposal is to create a new dev_printk macro : "dev_printk_norpm" which
> >>> >> outputs traces only when the device has not the runtime PM activated,
> >>> >> and guard those traces with it.
> >>> >> (cf the 2 patches in this thread as a PoC)
> >>> >
> >>> > Wouldn't it be easier just to change the existing messages to DEBUG
> >>> > level?  Or are they more important than that?
> >>>
> >>> Yes, I can simply replace all those printk by dev_dbg traces. For my
> >>> use case, it's perfect.
> >>> My main concern was people using PCI hotplug, I think, then, their log
> >>> will remain mostly silent when inserting a card, I don't know if this
> >>> is acceptable or not.
> >>
> >> I think they don't really need that information except for debugging, right?
> >
> > I think so.
> > I will send a new patch with dev_dbg in replacement of the noisy
> > printks for PCI messages.
> >
> 
> please use dev_printk(KERN_DEBUG,...) instead. otherwise will need
> recompile the kernel with DEBUG enabled
> to get debug message with debug in boot command line.

Hmm?  I thought that using dev_dbg() was the recommended way?

Rafael

Re: [PATCH] PM / Runtime: make PCI traces quieter

[Rafael J. Wysocki]

On Wednesday, September 21, 2011, Vincent Palatin wrote:
> When the runtime PM is activated on PCI, if a device switches state frequently
> (e.g. an EHCI controller with autosuspending USB devices connected)
> the PCI configuration traces might be very verbose in the kernel log.
> Let's guard those traces with DEBUG condition.
> 
> Signed-off-by: Vincent Palatin <vpalatin@chromium.org>

Acked-by: Rafael J. Wysocki <rjw@sisk.pl>

> ---
>  arch/x86/pci/i386.c     |    2 +-
>  drivers/acpi/pci_irq.c  |   10 +++++-----
>  drivers/pci/pci.c       |    5 ++---
>  drivers/pci/setup-res.c |    6 +++---
>  4 files changed, 11 insertions(+), 12 deletions(-)
> 
> diff --git a/arch/x86/pci/i386.c b/arch/x86/pci/i386.c
> index 494f2e7..eb5d20b 100644
> --- a/arch/x86/pci/i386.c
> +++ b/arch/x86/pci/i386.c
> @@ -269,7 +269,7 @@ void 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);
> +	dev_dbg(&dev->dev, "setting latency timer to %d\n", lat);
>  	pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
>  }
>  
> diff --git a/drivers/acpi/pci_irq.c b/drivers/acpi/pci_irq.c
> index 7f9eba9..0eefa12 100644
> --- a/drivers/acpi/pci_irq.c
> +++ b/drivers/acpi/pci_irq.c
> @@ -487,10 +487,10 @@ int acpi_pci_irq_enable(struct pci_dev *dev)
>  	else
>  		link_desc[0] = '\0';
>  
> -	dev_info(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
> -		 pin_name(pin), link_desc, gsi,
> -		 (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
> -		 (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
> +	dev_dbg(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
> +		pin_name(pin), link_desc, gsi,
> +		(triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
> +		(polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
>  
>  	return 0;
>  }
> @@ -524,6 +524,6 @@ void acpi_pci_irq_disable(struct pci_dev *dev)
>  	 * (e.g. PCI_UNDEFINED_IRQ).
>  	 */
>  
> -	dev_info(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
> +	dev_dbg(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
>  	acpi_unregister_gsi(gsi);
>  }
> diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
> index 0ce6742..d339c30 100644
> --- a/drivers/pci/pci.c
> +++ b/drivers/pci/pci.c
> @@ -964,7 +964,7 @@ void pci_restore_state(struct pci_dev *dev)
>  	for (i = 15; i >= 0; i--) {
>  		pci_read_config_dword(dev, i * 4, &val);
>  		if (val != dev->saved_config_space[i]) {
> -			dev_printk(KERN_DEBUG, &dev->dev, "restoring config "
> +			dev_dbg(&dev->dev, "restoring config "
>  				"space at offset %#x (was %#x, writing %#x)\n",
>  				i, val, (int)dev->saved_config_space[i]);
>  			pci_write_config_dword(dev,i * 4,
> @@ -1531,8 +1531,7 @@ void pci_pme_active(struct pci_dev *dev, bool enable)
>  	}
>  
>  out:
> -	dev_printk(KERN_DEBUG, &dev->dev, "PME# %s\n",
> -			enable ? "enabled" : "disabled");
> +	dev_dbg(&dev->dev, "PME# %s\n", enable ? "enabled" : "disabled");
>  }
>  
>  /**
> diff --git a/drivers/pci/setup-res.c b/drivers/pci/setup-res.c
> index 51a9095..3878fe9 100644
> --- a/drivers/pci/setup-res.c
> +++ b/drivers/pci/setup-res.c
> @@ -84,9 +84,9 @@ void pci_update_resource(struct pci_dev *dev, int resno)
>  		}
>  	}
>  	res->flags &= ~IORESOURCE_UNSET;
> -	dev_info(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
> -		 resno, res, (unsigned long long)region.start,
> -		 (unsigned long long)region.end);
> +	dev_dbg(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
> +		resno, res, (unsigned long long)region.start,
> +		(unsigned long long)region.end);
>  }
>  
>  int pci_claim_resource(struct pci_dev *dev, int resource)
> 

Re: [PATCH] PM / Runtime: make PCI traces quieter

[Vincent Palatin]

Hi Jesse,
Any comment on that patch ?
On Wed, Sep 21, 2011 at 11:29, Rafael J. Wysocki <rjw@sisk.pl> wrote:
>
> On Wednesday, September 21, 2011, Vincent Palatin wrote:
> > When the runtime PM is activated on PCI, if a device switches state frequently
> > (e.g. an EHCI controller with autosuspending USB devices connected)
> > the PCI configuration traces might be very verbose in the kernel log.
> > Let's guard those traces with DEBUG condition.
> >
> > Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
>
> Acked-by: Rafael J. Wysocki <rjw@sisk.pl>
>
> > ---
> >  arch/x86/pci/i386.c     |    2 +-
> >  drivers/acpi/pci_irq.c  |   10 +++++-----
> >  drivers/pci/pci.c       |    5 ++---
> >  drivers/pci/setup-res.c |    6 +++---
> >  4 files changed, 11 insertions(+), 12 deletions(-)
> >
> > diff --git a/arch/x86/pci/i386.c b/arch/x86/pci/i386.c
> > index 494f2e7..eb5d20b 100644
> > --- a/arch/x86/pci/i386.c
> > +++ b/arch/x86/pci/i386.c
> > @@ -269,7 +269,7 @@ void 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);
> > +     dev_dbg(&dev->dev, "setting latency timer to %d\n", lat);
> >       pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
> >  }
> >
> > diff --git a/drivers/acpi/pci_irq.c b/drivers/acpi/pci_irq.c
> > index 7f9eba9..0eefa12 100644
> > --- a/drivers/acpi/pci_irq.c
> > +++ b/drivers/acpi/pci_irq.c
> > @@ -487,10 +487,10 @@ int acpi_pci_irq_enable(struct pci_dev *dev)
> >       else
> >               link_desc[0] = '\0';
> >
> > -     dev_info(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
> > -              pin_name(pin), link_desc, gsi,
> > -              (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
> > -              (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
> > +     dev_dbg(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
> > +             pin_name(pin), link_desc, gsi,
> > +             (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
> > +             (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
> >
> >       return 0;
> >  }
> > @@ -524,6 +524,6 @@ void acpi_pci_irq_disable(struct pci_dev *dev)
> >        * (e.g. PCI_UNDEFINED_IRQ).
> >        */
> >
> > -     dev_info(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
> > +     dev_dbg(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
> >       acpi_unregister_gsi(gsi);
> >  }
> > diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
> > index 0ce6742..d339c30 100644
> > --- a/drivers/pci/pci.c
> > +++ b/drivers/pci/pci.c
> > @@ -964,7 +964,7 @@ void pci_restore_state(struct pci_dev *dev)
> >       for (i = 15; i >= 0; i--) {
> >               pci_read_config_dword(dev, i * 4, &val);
> >               if (val != dev->saved_config_space[i]) {
> > -                     dev_printk(KERN_DEBUG, &dev->dev, "restoring config "
> > +                     dev_dbg(&dev->dev, "restoring config "
> >                               "space at offset %#x (was %#x, writing %#x)\n",
> >                               i, val, (int)dev->saved_config_space[i]);
> >                       pci_write_config_dword(dev,i * 4,
> > @@ -1531,8 +1531,7 @@ void pci_pme_active(struct pci_dev *dev, bool enable)
> >       }
> >
> >  out:
> > -     dev_printk(KERN_DEBUG, &dev->dev, "PME# %s\n",
> > -                     enable ? "enabled" : "disabled");
> > +     dev_dbg(&dev->dev, "PME# %s\n", enable ? "enabled" : "disabled");
> >  }
> >
> >  /**
> > diff --git a/drivers/pci/setup-res.c b/drivers/pci/setup-res.c
> > index 51a9095..3878fe9 100644
> > --- a/drivers/pci/setup-res.c
> > +++ b/drivers/pci/setup-res.c
> > @@ -84,9 +84,9 @@ void pci_update_resource(struct pci_dev *dev, int resno)
> >               }
> >       }
> >       res->flags &= ~IORESOURCE_UNSET;
> > -     dev_info(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
> > -              resno, res, (unsigned long long)region.start,
> > -              (unsigned long long)region.end);
> > +     dev_dbg(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
> > +             resno, res, (unsigned long long)region.start,
> > +             (unsigned long long)region.end);
> >  }
> >
> >  int pci_claim_resource(struct pci_dev *dev, int resource)
> >
>

--
Vincent

Re: [PATCH] PM / Runtime: make PCI traces quieter

[Jesse Barnes]

[-- Attachment #1: Type: text/plain, Size: 330 bytes --]

On Mon, 28 Nov 2011 11:15:43 -0800
Vincent Palatin <vpalatin@chromium.org> wrote:

> Hi Jesse,
> Any comment on that patch ?

Yeah making these into debug statements is ok with me, but I don't see
the original in my inbox.  Bounce it over and I'll apply.

Thanks,
-- 
Jesse Barnes, Intel Open Source Technology Center

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 836 bytes --]

[PATCH] PM / Runtime: make PCI traces quieter

[Vincent Palatin]

When the runtime PM is activated on PCI, if a device switches state frequently
(e.g. an EHCI controller with autosuspending USB devices connected)
the PCI configuration traces might be very verbose in the kernel log.
Let's guard those traces with DEBUG condition.

Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
---
 arch/x86/pci/i386.c     |    2 +-
 drivers/acpi/pci_irq.c  |   10 +++++-----
 drivers/pci/pci.c       |    5 ++---
 drivers/pci/setup-res.c |    6 +++---
 4 files changed, 11 insertions(+), 12 deletions(-)

diff --git a/arch/x86/pci/i386.c b/arch/x86/pci/i386.c
index 794b092..e215a9b 100644
--- a/arch/x86/pci/i386.c
+++ b/arch/x86/pci/i386.c
@@ -270,7 +270,7 @@ void 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);
+	dev_dbg(&dev->dev, "setting latency timer to %d\n", lat);
 	pci_write_config_byte(dev, PCI_LATENCY_TIMER, lat);
 }
 
diff --git a/drivers/acpi/pci_irq.c b/drivers/acpi/pci_irq.c
index 7f9eba9..0eefa12 100644
--- a/drivers/acpi/pci_irq.c
+++ b/drivers/acpi/pci_irq.c
@@ -487,10 +487,10 @@ int acpi_pci_irq_enable(struct pci_dev *dev)
 	else
 		link_desc[0] = '\0';
 
-	dev_info(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
-		 pin_name(pin), link_desc, gsi,
-		 (triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
-		 (polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
+	dev_dbg(&dev->dev, "PCI INT %c%s -> GSI %u (%s, %s) -> IRQ %d\n",
+		pin_name(pin), link_desc, gsi,
+		(triggering == ACPI_LEVEL_SENSITIVE) ? "level" : "edge",
+		(polarity == ACPI_ACTIVE_LOW) ? "low" : "high", dev->irq);
 
 	return 0;
 }
@@ -524,6 +524,6 @@ void acpi_pci_irq_disable(struct pci_dev *dev)
 	 * (e.g. PCI_UNDEFINED_IRQ).
 	 */
 
-	dev_info(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
+	dev_dbg(&dev->dev, "PCI INT %c disabled\n", pin_name(pin));
 	acpi_unregister_gsi(gsi);
 }
diff --git a/drivers/pci/pci.c b/drivers/pci/pci.c
index 6f45a73..8119757 100644
--- a/drivers/pci/pci.c
+++ b/drivers/pci/pci.c
@@ -964,7 +964,7 @@ void pci_restore_state(struct pci_dev *dev)
 	for (i = 15; i >= 0; i--) {
 		pci_read_config_dword(dev, i * 4, &val);
 		if (val != dev->saved_config_space[i]) {
-			dev_printk(KERN_DEBUG, &dev->dev, "restoring config "
+			dev_dbg(&dev->dev, "restoring config "
 				"space at offset %#x (was %#x, writing %#x)\n",
 				i, val, (int)dev->saved_config_space[i]);
 			pci_write_config_dword(dev,i * 4,
@@ -1529,8 +1529,7 @@ void pci_pme_active(struct pci_dev *dev, bool enable)
 	}
 
 out:
-	dev_printk(KERN_DEBUG, &dev->dev, "PME# %s\n",
-			enable ? "enabled" : "disabled");
+	dev_dbg(&dev->dev, "PME# %s\n", enable ? "enabled" : "disabled");
 }
 
 /**
diff --git a/drivers/pci/setup-res.c b/drivers/pci/setup-res.c
index 5717509b..b66bfdb 100644
--- a/drivers/pci/setup-res.c
+++ b/drivers/pci/setup-res.c
@@ -85,9 +85,9 @@ void pci_update_resource(struct pci_dev *dev, int resno)
 		}
 	}
 	res->flags &= ~IORESOURCE_UNSET;
-	dev_info(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
-		 resno, res, (unsigned long long)region.start,
-		 (unsigned long long)region.end);
+	dev_dbg(&dev->dev, "BAR %d: set to %pR (PCI address [%#llx-%#llx])\n",
+		resno, res, (unsigned long long)region.start,
+		(unsigned long long)region.end);
 }
 
 int pci_claim_resource(struct pci_dev *dev, int resource)
-- 
1.7.3.1

Re: [PATCH] PM / Runtime: make PCI traces quieter

[Jesse Barnes]

[-- Attachment #1: Type: text/plain, Size: 605 bytes --]

On Mon,  5 Dec 2011 11:51:18 -0800
Vincent Palatin <vpalatin@chromium.org> wrote:

> When the runtime PM is activated on PCI, if a device switches state frequently
> (e.g. an EHCI controller with autosuspending USB devices connected)
> the PCI configuration traces might be very verbose in the kernel log.
> Let's guard those traces with DEBUG condition.
> 
> Signed-off-by: Vincent Palatin <vpalatin@chromium.org>
> ---

Applied to linux-next, thanks.  The latency timer message is gone now
though, so it didn't need to be fixed. :)

-- 
Jesse Barnes, Intel Open Source Technology Center

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 836 bytes --]