Re: [Intel-gfx] [PATCH v2] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

Re: [Intel-gfx] [PATCH v2] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Rafael J. Wysocki]

On 11/27/2015 12:39 PM, Jani Nikula wrote:
> On Wed, 18 Nov 2015, Daniel Vetter <daniel@ffwll.ch> wrote:
>> On Wed, Nov 18, 2015 at 03:28:38PM +0200, Imre Deak wrote:
>>> On ke, 2015-11-18 at 12:56 +0200, Imre Deak wrote:
>>>> The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
>>>> suspend hooks as errors, but they still show up as errors in dmesg. Tune
>>>> them down.
>>>>
>>>> One problem caused by this was noticed by Daniel: the i915 driver
>>>> returns EAGAIN to signal a temporary failure to suspend and as a request
>>>> towards the RPM core for scheduling a suspend again. This is a normal
>>>> event, but the resulting error message flags a breakage during the
>>>> driver's automated testing which parses dmesg and picks up the error.
>>>>
>>>> v2:
>>>> - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
>>>>
>>>> Reported-by: Daniel Vetter <daniel.vetter@intel.com>
>>>> Signed-off-by: Imre Deak <imre.deak@intel.com>
>>> Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
>> Reviewed-by: Daniel Vetter <daniel.vetter@ffwll.ch>
>>
>> Rafael, can you please pick this up for 4.4? The spurious KERN_ERR noise
>> in dmesg is causing a lot fo spurious fail in our (very recently put into
>> place) i915 CI system.
> Rafael, ping.

Well, so I'm not sure about this one.

And the question is ->

>>>> ---
>>>>   drivers/base/power/main.c |  7 +++++--
>>>>   drivers/pci/pci-driver.c  |  2 +-
>>>>   include/linux/pm.h        | 11 +++++++++--
>>>>   3 files changed, 15 insertions(+), 5 deletions(-)
>>>>
>>>> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
>>>> index 1710c26..39d2090 100644
>>>> --- a/drivers/base/power/main.c
>>>> +++ b/drivers/base/power/main.c
>>>> @@ -1679,9 +1679,12 @@ int dpm_suspend_start(pm_message_t state)
>>>>   }
>>>>   EXPORT_SYMBOL_GPL(dpm_suspend_start);
>>>>   
>>>> -void __suspend_report_result(const char *function, void *fn, int ret)
>>>> +void __suspend_report_result(const char *function, void *fn, int ret,
>>>> +			     bool runtime_pm)
>>>>   {
>>>> -	if (ret)
>>>> +	if (runtime_pm && (ret == -EBUSY || ret == -EAGAIN))
>>>> +		printk(KERN_DEBUG "%s(): %pF returns %d\n", function, fn, ret);
>>>> +	else if (ret)
>>>>   		printk(KERN_ERR "%s(): %pF returns %d\n", function, fn, ret);
>>>>   }

-> why you are adding overhead to this function, instead of -->

>>>>   EXPORT_SYMBOL_GPL(__suspend_report_result);
>>>> diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
>>>> index 108a311..9569572 100644
>>>> --- a/drivers/pci/pci-driver.c
>>>> +++ b/drivers/pci/pci-driver.c
>>>> @@ -1142,7 +1142,7 @@ static int pci_pm_runtime_suspend(struct device *dev)
>>>>   	pci_dev->state_saved = false;
>>>>   	pci_dev->no_d3cold = false;
>>>>   	error = pm->runtime_suspend(dev);
>>>> -	suspend_report_result(pm->runtime_suspend, error);
>>>> +	rpm_suspend_report_result(pm->runtime_suspend, error);

--> replacing the suspend_report_result() above with a direct printk() 
in the if (error) block below.

Surely, suspend_report_result() was not designed with runtime PM in mind 
and it was a mistake to use it here.  It just seemed to do the right 
thing, but it clearly doesn't.

>>>>   	if (error)
>>>>   		return error;
>>>>   	if (!pci_dev->d3cold_allowed)
>>>> diff --git a/include/linux/pm.h b/include/linux/pm.h
>>>> index 35d599e..54f37e3 100644
>>>> --- a/include/linux/pm.h
>>>> +++ b/include/linux/pm.h
>>>> @@ -702,11 +702,17 @@ extern int dpm_suspend_late(pm_message_t state);
>>>>   extern int dpm_suspend(pm_message_t state);
>>>>   extern int dpm_prepare(pm_message_t state);
>>>>   
>>>> -extern void __suspend_report_result(const char *function, void *fn, int ret);
>>>> +extern void __suspend_report_result(const char *function, void *fn, int ret,
>>>> +				    bool runtime_pm);
>>>>   
>>>>   #define suspend_report_result(fn, ret)					\
>>>>   	do {								\
>>>> -		__suspend_report_result(__func__, fn, ret);		\
>>>> +		__suspend_report_result(__func__, fn, ret, false);	\
>>>> +	} while (0)
>>>> +
>>>> +#define rpm_suspend_report_result(fn, ret)				\
>>>> +	do {								\
>>>> +		__suspend_report_result(__func__, fn, ret, true);	\
>>>>   	} while (0)
>>>>   
>>>>   extern int device_pm_wait_for_dev(struct device *sub, struct device *dev);
>>>> @@ -744,6 +750,7 @@ static inline int dpm_suspend_start(pm_message_t state)
>>>>   }
>>>>   
>>>>   #define suspend_report_result(fn, ret)		do {} while (0)
>>>> +#define rpm_suspend_report_result(fn, ret)	do {} while (0)
>>>>   
>>>>   static inline int device_pm_wait_for_dev(struct device *a, struct device *b)
>>>>   {

BTW, if you're changing PM code, it is good to CC linux-pm too (now 
done) and if you're changing PCI code, it is mandatory to CC linux-pci 
and the PCI maintainer (now done too).

Thanks,
Rafael

Re: [Intel-gfx] [PATCH v2] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Imre Deak]

On pe, 2015-11-27 at 15:44 +0100, Rafael J. Wysocki wrote:
> On 11/27/2015 12:39 PM, Jani Nikula wrote:
> > On Wed, 18 Nov 2015, Daniel Vetter <daniel@ffwll.ch> wrote:
> > > On Wed, Nov 18, 2015 at 03:28:38PM +0200, Imre Deak wrote:
> > > > On ke, 2015-11-18 at 12:56 +0200, Imre Deak wrote:
> > > > > The runtime PM core doesn't treat EBUSY and EAGAIN retvals
> > > > > from the driver
> > > > > suspend hooks as errors, but they still show up as errors in
> > > > > dmesg. Tune
> > > > > them down.
> > > > > 
> > > > > One problem caused by this was noticed by Daniel: the i915
> > > > > driver
> > > > > returns EAGAIN to signal a temporary failure to suspend and
> > > > > as a request
> > > > > towards the RPM core for scheduling a suspend again. This is
> > > > > a normal
> > > > > event, but the resulting error message flags a breakage
> > > > > during the
> > > > > driver's automated testing which parses dmesg and picks up
> > > > > the error.
> > > > > 
> > > > > v2:
> > > > > - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> > > > > 
> > > > > Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> > > > > Signed-off-by: Imre Deak <imre.deak@intel.com>
> > > > Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> > > Reviewed-by: Daniel Vetter <daniel.vetter@ffwll.ch>
> > > 
> > > Rafael, can you please pick this up for 4.4? The spurious
> > > KERN_ERR noise
> > > in dmesg is causing a lot fo spurious fail in our (very recently
> > > put into
> > > place) i915 CI system.
> > Rafael, ping.
> 
> Well, so I'm not sure about this one.
> 
> And the question is ->
> 
> > > > > ---
> > > > >   drivers/base/power/main.c |  7 +++++--
> > > > >   drivers/pci/pci-driver.c  |  2 +-
> > > > >   include/linux/pm.h        | 11 +++++++++--
> > > > >   3 files changed, 15 insertions(+), 5 deletions(-)
> > > > > 
> > > > > diff --git a/drivers/base/power/main.c
> > > > > b/drivers/base/power/main.c
> > > > > index 1710c26..39d2090 100644
> > > > > --- a/drivers/base/power/main.c
> > > > > +++ b/drivers/base/power/main.c
> > > > > @@ -1679,9 +1679,12 @@ int dpm_suspend_start(pm_message_t
> > > > > state)
> > > > >   }
> > > > >   EXPORT_SYMBOL_GPL(dpm_suspend_start);
> > > > >   
> > > > > -void __suspend_report_result(const char *function, void *fn,
> > > > > int ret)
> > > > > +void __suspend_report_result(const char *function, void *fn,
> > > > > int ret,
> > > > > +			     bool runtime_pm)
> > > > >   {
> > > > > -	if (ret)
> > > > > +	if (runtime_pm && (ret == -EBUSY || ret == -EAGAIN))
> > > > > +		printk(KERN_DEBUG "%s(): %pF returns %d\n",
> > > > > function, fn, ret);
> > > > > +	else if (ret)
> > > > >   		printk(KERN_ERR "%s(): %pF returns %d\n",
> > > > > function, fn, ret);
> > > > >   }
> 
> -> why you are adding overhead to this function, instead of -->
> 
> > > > >   EXPORT_SYMBOL_GPL(__suspend_report_result);
> > > > > diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-
> > > > > driver.c
> > > > > index 108a311..9569572 100644
> > > > > --- a/drivers/pci/pci-driver.c
> > > > > +++ b/drivers/pci/pci-driver.c
> > > > > @@ -1142,7 +1142,7 @@ static int
> > > > > pci_pm_runtime_suspend(struct device *dev)
> > > > >   	pci_dev->state_saved = false;
> > > > >   	pci_dev->no_d3cold = false;
> > > > >   	error = pm->runtime_suspend(dev);
> > > > > -	suspend_report_result(pm->runtime_suspend, error);
> > > > > +	rpm_suspend_report_result(pm->runtime_suspend,
> > > > > error);
> 
> --> replacing the suspend_report_result() above with a direct
> printk() 
> in the if (error) block below.
> 
> Surely, suspend_report_result() was not designed with runtime PM in
> mind 
> and it was a mistake to use it here.  It just seemed to do the right 
> thing, but it clearly doesn't.

Ok, a helper like rpm_suspend_report_result() seemed like a good idea,
since handling -EBUSY and -EAGAIN error reporting will be the same for
callers of the pm->runtime_suspend hooks not just the PCI drivers. But
since the only user of this is the PCI core atm we can just add a
printk locally as you suggested. I'll follow up with v2.

> > > > >   	if (error)
> > > > >   		return error;
> > > > >   	if (!pci_dev->d3cold_allowed)
> > > > > diff --git a/include/linux/pm.h b/include/linux/pm.h
> > > > > index 35d599e..54f37e3 100644
> > > > > --- a/include/linux/pm.h
> > > > > +++ b/include/linux/pm.h
> > > > > @@ -702,11 +702,17 @@ extern int
> > > > > dpm_suspend_late(pm_message_t state);
> > > > >   extern int dpm_suspend(pm_message_t state);
> > > > >   extern int dpm_prepare(pm_message_t state);
> > > > >   
> > > > > -extern void __suspend_report_result(const char *function,
> > > > > void *fn, int ret);
> > > > > +extern void __suspend_report_result(const char *function,
> > > > > void *fn, int ret,
> > > > > +				    bool runtime_pm);
> > > > >   
> > > > >   #define suspend_report_result(fn, ret)			
> > > > > 		\
> > > > >   	do {						
> > > > > 		\
> > > > > -		__suspend_report_result(__func__, fn, ret);	
> > > > > 	\
> > > > > +		__suspend_report_result(__func__, fn, ret,
> > > > > false);	\
> > > > > +	} while (0)
> > > > > +
> > > > > +#define rpm_suspend_report_result(fn, ret)			
> > > > > 	\
> > > > > +	do {							
> > > > > 	\
> > > > > +		__suspend_report_result(__func__, fn, ret,
> > > > > true);	\
> > > > >   	} while (0)
> > > > >   
> > > > >   extern int device_pm_wait_for_dev(struct device *sub,
> > > > > struct device *dev);
> > > > > @@ -744,6 +750,7 @@ static inline int
> > > > > dpm_suspend_start(pm_message_t state)
> > > > >   }
> > > > >   
> > > > >   #define suspend_report_result(fn, ret)		do {}
> > > > > while (0)
> > > > > +#define rpm_suspend_report_result(fn, ret)	do {}
> > > > > while (0)
> > > > >   
> > > > >   static inline int device_pm_wait_for_dev(struct device *a,
> > > > > struct device *b)
> > > > >   {
> 
> BTW, if you're changing PM code, it is good to CC linux-pm too (now 
> done) and if you're changing PCI code, it is mandatory to CC linux-
> pci 
> and the PCI maintainer (now done too).

Sorry, I thought about it too after sending it. Will do so in the
future.

--Imre

[PATCH v3] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Imre Deak]

The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
suspend hooks as errors, but they still show up as errors in dmesg. Tune
them down.

One problem caused by this was noticed by Daniel: the i915 driver
returns EAGAIN to signal a temporary failure to suspend and as a request
towards the RPM core for scheduling a suspend again. This is a normal
event, but the resulting error message flags a breakage during the
driver's automated testing which parses dmesg and picks up the error.

v2:
- fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
v3:
- instead of modifying the suspend_report_result() helper to disinguish
  between the runtime and system suspend case, inline the error
  printing, it's not used anywhere else (Rafael)

Reported-by: Daniel Vetter <daniel.vetter@intel.com>
Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
CC: Bjorn Helgaas <bhelgaas@google.com>
CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Signed-off-by: Imre Deak <imre.deak@intel.com>
---
 drivers/pci/pci-driver.c | 15 +++++++++++++--
 1 file changed, 13 insertions(+), 2 deletions(-)

diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
index 4446fcb..67eb4ac 100644
--- a/drivers/pci/pci-driver.c
+++ b/drivers/pci/pci-driver.c
@@ -1146,9 +1146,20 @@ static int pci_pm_runtime_suspend(struct device *dev)
 	pci_dev->state_saved = false;
 	pci_dev->no_d3cold = false;
 	error = pm->runtime_suspend(dev);
-	suspend_report_result(pm->runtime_suspend, error);
-	if (error)
+	if (error) {
+		/*
+		 * -EBUSY and -EAGAIN is used to request the runtime PM core
+		 * to schedule a new suspend, so don't flag it as an error.
+		 */
+		if (error == -EBUSY || error == -EAGAIN)
+			printk(KERN_DEBUG "%s(): %pF returns %d\n", __func__,
+			       pm->runtime_suspend, error);
+		else
+			printk(KERN_ERR "%s(): %pF returns %d\n", __func__,
+			       pm->runtime_suspend, error);
+
 		return error;
+	}
 	if (!pci_dev->d3cold_allowed)
 		pci_dev->no_d3cold = true;
 
-- 
2.5.0

Re: [PATCH v3] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Rafael J. Wysocki]

On Fri, Nov 27, 2015 at 7:17 PM, Imre Deak <imre.deak@intel.com> wrote:
> The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
> suspend hooks as errors, but they still show up as errors in dmesg. Tune
> them down.
>
> One problem caused by this was noticed by Daniel: the i915 driver
> returns EAGAIN to signal a temporary failure to suspend and as a request
> towards the RPM core for scheduling a suspend again. This is a normal
> event, but the resulting error message flags a breakage during the
> driver's automated testing which parses dmesg and picks up the error.
>
> v2:
> - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> v3:
> - instead of modifying the suspend_report_result() helper to disinguish
>   between the runtime and system suspend case, inline the error
>   printing, it's not used anywhere else (Rafael)
>
> Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> CC: Bjorn Helgaas <bhelgaas@google.com>
> CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Signed-off-by: Imre Deak <imre.deak@intel.com>
> ---
>  drivers/pci/pci-driver.c | 15 +++++++++++++--
>  1 file changed, 13 insertions(+), 2 deletions(-)
>
> diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
> index 4446fcb..67eb4ac 100644
> --- a/drivers/pci/pci-driver.c
> +++ b/drivers/pci/pci-driver.c
> @@ -1146,9 +1146,20 @@ static int pci_pm_runtime_suspend(struct device *dev)
>         pci_dev->state_saved = false;
>         pci_dev->no_d3cold = false;
>         error = pm->runtime_suspend(dev);
> -       suspend_report_result(pm->runtime_suspend, error);
> -       if (error)
> +       if (error) {
> +               /*
> +                * -EBUSY and -EAGAIN is used to request the runtime PM core
> +                * to schedule a new suspend, so don't flag it as an error.
> +                */

KERN_DEBUG and KERN_ERR are log levels, not flags.

Besides, maybe we can use pr_err() and pr_debug() here?

> +               if (error == -EBUSY || error == -EAGAIN)
> +                       printk(KERN_DEBUG "%s(): %pF returns %d\n", __func__,
> +                              pm->runtime_suspend, error);
> +               else
> +                       printk(KERN_ERR "%s(): %pF returns %d\n", __func__,
> +                              pm->runtime_suspend, error);
> +
>                 return error;
> +       }
>         if (!pci_dev->d3cold_allowed)
>                 pci_dev->no_d3cold = true;
>
> --

Thanks,
Rafael

[PATCH v4] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Imre Deak]

The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
suspend hooks as errors, but they still show up as errors in dmesg. Tune
them down.

One problem caused by this was noticed by Daniel: the i915 driver
returns EAGAIN to signal a temporary failure to suspend and as a request
towards the RPM core for scheduling a suspend again. This is a normal
event, but the resulting error message flags a breakage during the
driver's automated testing which parses dmesg and picks up the error.

v2:
- fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
v3:
- instead of modifying the suspend_report_result() helper to disinguish
  between the runtime and system suspend case, inline the error
  printing, it's not used anywhere else (Rafael)
v4:
- don't refer to log levels as flags in code comment (Rafael)
- use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)

Reported-by: Daniel Vetter <daniel.vetter@intel.com>
Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
CC: Bjorn Helgaas <bhelgaas@google.com>
CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Signed-off-by: Imre Deak <imre.deak@intel.com>
---
 drivers/pci/pci-driver.c | 16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
index 4446fcb..32a9947 100644
--- a/drivers/pci/pci-driver.c
+++ b/drivers/pci/pci-driver.c
@@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
 	pci_dev->state_saved = false;
 	pci_dev->no_d3cold = false;
 	error = pm->runtime_suspend(dev);
-	suspend_report_result(pm->runtime_suspend, error);
-	if (error)
+	if (error) {
+		/*
+		 * -EBUSY and -EAGAIN is used to request the runtime PM core
+		 * to schedule a new suspend, so log the event only with debug
+		 * log level.
+		 */
+		if (error == -EBUSY || error == -EAGAIN)
+			pr_debug("%s(): %pF returns %d\n", __func__,
+				 pm->runtime_suspend, error);
+		else
+			pr_err("%s(): %pF returns %d\n", __func__,
+			       pm->runtime_suspend, error);
+
 		return error;
+	}
 	if (!pci_dev->d3cold_allowed)
 		pci_dev->no_d3cold = true;
 
-- 
2.5.0

Re: [PATCH v4] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Rafael J. Wysocki]

On Saturday, November 28, 2015 10:34:24 AM Imre Deak wrote:
> The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
> suspend hooks as errors, but they still show up as errors in dmesg. Tune
> them down.
> 
> One problem caused by this was noticed by Daniel: the i915 driver
> returns EAGAIN to signal a temporary failure to suspend and as a request
> towards the RPM core for scheduling a suspend again. This is a normal
> event, but the resulting error message flags a breakage during the
> driver's automated testing which parses dmesg and picks up the error.
> 
> v2:
> - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> v3:
> - instead of modifying the suspend_report_result() helper to disinguish
>   between the runtime and system suspend case, inline the error
>   printing, it's not used anywhere else (Rafael)
> v4:
> - don't refer to log levels as flags in code comment (Rafael)
> - use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)
> 
> Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> CC: Bjorn Helgaas <bhelgaas@google.com>
> CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Signed-off-by: Imre Deak <imre.deak@intel.com>

This is fine by me.

Bjorn, any objections against applying it?  It reduces log noise quite
a bit for i915.

> ---
>  drivers/pci/pci-driver.c | 16 ++++++++++++++--
>  1 file changed, 14 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
> index 4446fcb..32a9947 100644
> --- a/drivers/pci/pci-driver.c
> +++ b/drivers/pci/pci-driver.c
> @@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
>  	pci_dev->state_saved = false;
>  	pci_dev->no_d3cold = false;
>  	error = pm->runtime_suspend(dev);
> -	suspend_report_result(pm->runtime_suspend, error);
> -	if (error)
> +	if (error) {
> +		/*
> +		 * -EBUSY and -EAGAIN is used to request the runtime PM core
> +		 * to schedule a new suspend, so log the event only with debug
> +		 * log level.
> +		 */
> +		if (error == -EBUSY || error == -EAGAIN)
> +			pr_debug("%s(): %pF returns %d\n", __func__,
> +				 pm->runtime_suspend, error);
> +		else
> +			pr_err("%s(): %pF returns %d\n", __func__,
> +			       pm->runtime_suspend, error);
> +
>  		return error;
> +	}
>  	if (!pci_dev->d3cold_allowed)
>  		pci_dev->no_d3cold = true;
>  
> 

Thanks,
Rafael

Re: [PATCH v4] PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

[Bjorn Helgaas]

Hi Imre,

> PCI / PM: tune down RPM suspend error message with EBUSY and EAGAIN retval

Please capitalize the first word, e.g., "Tune ..."

Maybe "Tune down non-fatal runtime suspend error messages" would be
more to the point.  Or maybe "retryable," since it sounds like that's
what's supposed to happen.


On Sat, Nov 28, 2015 at 10:34:24AM +0200, Imre Deak wrote:
> The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
> suspend hooks as errors, but they still show up as errors in dmesg. Tune
> them down.

I looked briefly for the place in the runtime PM core where we handle
EBUSY and EAGAIN specially, but I didn't find it.  A pointer would be
helpful.

> One problem caused by this was noticed by Daniel: the i915 driver
> returns EAGAIN to signal a temporary failure to suspend and as a request
> towards the RPM core for scheduling a suspend again. This is a normal
> event, but the resulting error message flags a breakage during the
> driver's automated testing which parses dmesg and picks up the error.
> 
> v2:
> - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> v3:
> - instead of modifying the suspend_report_result() helper to disinguish
>   between the runtime and system suspend case, inline the error
>   printing, it's not used anywhere else (Rafael)
> v4:
> - don't refer to log levels as flags in code comment (Rafael)
> - use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)

The version history is very useful during development but not after
merging, so I prefer it to go after the "---" marker so it doesn't get
included in the permanent changelog.

> Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> CC: Bjorn Helgaas <bhelgaas@google.com>
> CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Signed-off-by: Imre Deak <imre.deak@intel.com>
> ---
>  drivers/pci/pci-driver.c | 16 ++++++++++++++--
>  1 file changed, 14 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
> index 4446fcb..32a9947 100644
> --- a/drivers/pci/pci-driver.c
> +++ b/drivers/pci/pci-driver.c
> @@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
>  	pci_dev->state_saved = false;
>  	pci_dev->no_d3cold = false;
>  	error = pm->runtime_suspend(dev);
> -	suspend_report_result(pm->runtime_suspend, error);
> -	if (error)
> +	if (error) {
> +		/*
> +		 * -EBUSY and -EAGAIN is used to request the runtime PM core
> +		 * to schedule a new suspend, so log the event only with debug
> +		 * log level.
> +		 */
> +		if (error == -EBUSY || error == -EAGAIN)
> +			pr_debug("%s(): %pF returns %d\n", __func__,
> +				 pm->runtime_suspend, error);
> +		else
> +			pr_err("%s(): %pF returns %d\n", __func__,
> +			       pm->runtime_suspend, error);

This looks fine to me in principle.

We have the device pointer, so please use dev_printk(KERN_DEBUG) and
dev_err().  If you're OK with changing the semantics so the debug
message is only emitted when dynamically enabled, you could use
dev_dbg().

I don't know what a user is supposed to do with a message like:

  pci_pm_runtime_suspend(): ata_port_runtime_suspend+0x0/0x200 returns -12

It feels a little bit ... internal.  Using dev_err() will help anchor
it to a specific device.  It's not related to a specific PC in the
function, so maybe use %pf instead of %pF to get rid of the function
offset and size.  And the message doesn't say anything about what the
return code *means*; maybe something like:

  ata_piix 0000:00:14.0: can't suspend now (ata_port_runtime_suspend returned -11)
  ata_piix 0000:00:14.0: can't suspend (ata_port_runtime_suspend returned -12)

> +
>  		return error;
> +	}
>  	if (!pci_dev->d3cold_allowed)
>  		pci_dev->no_d3cold = true;
>  
> -- 
> 2.5.0
> 
> --
> 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 v5] PCI / PM: Tune down retryable runtime suspend error messages

[Imre Deak]

The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
suspend hooks as errors, but they still show up as errors in dmesg. Tune
them down. See rpm_suspend() for details of handling these return values.

Note that we use dev_dbg() for the retryable retvals, so after this
change you'll need either CONFIG_DYNAMIC_DEBUG or CONFIG_PCI_DEBUG
for them to show up in the log.

One problem caused by this was noticed by Daniel: the i915 driver
returns EAGAIN to signal a temporary failure to suspend and as a request
towards the RPM core for scheduling a suspend again. This is a normal
event, but the resulting error message flags a breakage during the
driver's automated testing which parses dmesg and picks up the error.

Reported-by: Daniel Vetter <daniel.vetter@intel.com>
Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
CC: Bjorn Helgaas <bhelgaas@google.com>
CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Signed-off-by: Imre Deak <imre.deak@intel.com>

---

v2:
- fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
v3:
- instead of modifying the suspend_report_result() helper to disinguish
  between the runtime and system suspend case, inline the error
  printing, it's not used anywhere else (Rafael)
v4:
- don't refer to log levels as flags in code comment (Rafael)
- use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)
v5:
- clarify commit message (Bjorn)
- use dev_dbg, dev_err instead of pr_debug, pr_err (Bjorn)
- use %pf in printk format instead of %pF (Bjorn)
- make the debug/error messages more meaningful (Bjorn)
---
 drivers/pci/pci-driver.c | 16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
index 4446fcb..d7ffd66 100644
--- a/drivers/pci/pci-driver.c
+++ b/drivers/pci/pci-driver.c
@@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
 	pci_dev->state_saved = false;
 	pci_dev->no_d3cold = false;
 	error = pm->runtime_suspend(dev);
-	suspend_report_result(pm->runtime_suspend, error);
-	if (error)
+	if (error) {
+		/*
+		 * -EBUSY and -EAGAIN is used to request the runtime PM core
+		 * to schedule a new suspend, so log the event only with debug
+		 * log level.
+		 */
+		if (error == -EBUSY || error == -EAGAIN)
+			dev_dbg(dev, "can't suspend now (%pf returned %d)\n",
+				pm->runtime_suspend, error);
+		else
+			dev_err(dev, "can't suspend (%pf returned %d)\n",
+				pm->runtime_suspend, error);
+
 		return error;
+	}
 	if (!pci_dev->d3cold_allowed)
 		pci_dev->no_d3cold = true;
 
-- 
2.5.0

Re: [PATCH v5] PCI / PM: Tune down retryable runtime suspend error messages

[Rafael J. Wysocki]

On Monday, November 30, 2015 09:02:55 PM Imre Deak wrote:
> The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
> suspend hooks as errors, but they still show up as errors in dmesg. Tune
> them down. See rpm_suspend() for details of handling these return values.
> 
> Note that we use dev_dbg() for the retryable retvals, so after this
> change you'll need either CONFIG_DYNAMIC_DEBUG or CONFIG_PCI_DEBUG
> for them to show up in the log.
> 
> One problem caused by this was noticed by Daniel: the i915 driver
> returns EAGAIN to signal a temporary failure to suspend and as a request
> towards the RPM core for scheduling a suspend again. This is a normal
> event, but the resulting error message flags a breakage during the
> driver's automated testing which parses dmesg and picks up the error.
> 
> Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> CC: Bjorn Helgaas <bhelgaas@google.com>
> CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Signed-off-by: Imre Deak <imre.deak@intel.com>

Hi Bjorn,

Are you going to handle this one or should I take care of it?

Rafael


> ---
> 
> v2:
> - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> v3:
> - instead of modifying the suspend_report_result() helper to disinguish
>   between the runtime and system suspend case, inline the error
>   printing, it's not used anywhere else (Rafael)
> v4:
> - don't refer to log levels as flags in code comment (Rafael)
> - use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)
> v5:
> - clarify commit message (Bjorn)
> - use dev_dbg, dev_err instead of pr_debug, pr_err (Bjorn)
> - use %pf in printk format instead of %pF (Bjorn)
> - make the debug/error messages more meaningful (Bjorn)
> ---
>  drivers/pci/pci-driver.c | 16 ++++++++++++++--
>  1 file changed, 14 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
> index 4446fcb..d7ffd66 100644
> --- a/drivers/pci/pci-driver.c
> +++ b/drivers/pci/pci-driver.c
> @@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
>  	pci_dev->state_saved = false;
>  	pci_dev->no_d3cold = false;
>  	error = pm->runtime_suspend(dev);
> -	suspend_report_result(pm->runtime_suspend, error);
> -	if (error)
> +	if (error) {
> +		/*
> +		 * -EBUSY and -EAGAIN is used to request the runtime PM core
> +		 * to schedule a new suspend, so log the event only with debug
> +		 * log level.
> +		 */
> +		if (error == -EBUSY || error == -EAGAIN)
> +			dev_dbg(dev, "can't suspend now (%pf returned %d)\n",
> +				pm->runtime_suspend, error);
> +		else
> +			dev_err(dev, "can't suspend (%pf returned %d)\n",
> +				pm->runtime_suspend, error);
> +
>  		return error;
> +	}
>  	if (!pci_dev->d3cold_allowed)
>  		pci_dev->no_d3cold = true;
>  
> 

-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

Re: [PATCH v5] PCI / PM: Tune down retryable runtime suspend error messages

[Bjorn Helgaas]

On Wed, Dec 02, 2015 at 02:54:45AM +0100, Rafael J. Wysocki wrote:
> On Monday, November 30, 2015 09:02:55 PM Imre Deak wrote:
> > The runtime PM core doesn't treat EBUSY and EAGAIN retvals from the driver
> > suspend hooks as errors, but they still show up as errors in dmesg. Tune
> > them down. See rpm_suspend() for details of handling these return values.
> > 
> > Note that we use dev_dbg() for the retryable retvals, so after this
> > change you'll need either CONFIG_DYNAMIC_DEBUG or CONFIG_PCI_DEBUG
> > for them to show up in the log.
> > 
> > One problem caused by this was noticed by Daniel: the i915 driver
> > returns EAGAIN to signal a temporary failure to suspend and as a request
> > towards the RPM core for scheduling a suspend again. This is a normal
> > event, but the resulting error message flags a breakage during the
> > driver's automated testing which parses dmesg and picks up the error.
> > 
> > Reported-by: Daniel Vetter <daniel.vetter@intel.com>
> > Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=92992
> > CC: Bjorn Helgaas <bhelgaas@google.com>
> > CC: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> > Signed-off-by: Imre Deak <imre.deak@intel.com>
> 
> Hi Bjorn,
> 
> Are you going to handle this one or should I take care of it?

Why don't you take it, since you're the PM guru :)

Acked-by: Bjorn Helgaas <bhelgaas@google.com>

Thanks for all your work, Imre!

> > ---
> > 
> > v2:
> > - fix compile breake when CONFIG_PM_SLEEP=n (0-day builder)
> > v3:
> > - instead of modifying the suspend_report_result() helper to disinguish
> >   between the runtime and system suspend case, inline the error
> >   printing, it's not used anywhere else (Rafael)
> > v4:
> > - don't refer to log levels as flags in code comment (Rafael)
> > - use pr_debug(), pr_err() instead of the corresponding printk() (Rafael)
> > v5:
> > - clarify commit message (Bjorn)
> > - use dev_dbg, dev_err instead of pr_debug, pr_err (Bjorn)
> > - use %pf in printk format instead of %pF (Bjorn)
> > - make the debug/error messages more meaningful (Bjorn)
> > ---
> >  drivers/pci/pci-driver.c | 16 ++++++++++++++--
> >  1 file changed, 14 insertions(+), 2 deletions(-)
> > 
> > diff --git a/drivers/pci/pci-driver.c b/drivers/pci/pci-driver.c
> > index 4446fcb..d7ffd66 100644
> > --- a/drivers/pci/pci-driver.c
> > +++ b/drivers/pci/pci-driver.c
> > @@ -1146,9 +1146,21 @@ static int pci_pm_runtime_suspend(struct device *dev)
> >  	pci_dev->state_saved = false;
> >  	pci_dev->no_d3cold = false;
> >  	error = pm->runtime_suspend(dev);
> > -	suspend_report_result(pm->runtime_suspend, error);
> > -	if (error)
> > +	if (error) {
> > +		/*
> > +		 * -EBUSY and -EAGAIN is used to request the runtime PM core
> > +		 * to schedule a new suspend, so log the event only with debug
> > +		 * log level.
> > +		 */
> > +		if (error == -EBUSY || error == -EAGAIN)
> > +			dev_dbg(dev, "can't suspend now (%pf returned %d)\n",
> > +				pm->runtime_suspend, error);
> > +		else
> > +			dev_err(dev, "can't suspend (%pf returned %d)\n",
> > +				pm->runtime_suspend, error);
> > +
> >  		return error;
> > +	}
> >  	if (!pci_dev->d3cold_allowed)
> >  		pci_dev->no_d3cold = true;
> >  
> > 
> 
> -- 
> I speak only for myself.
> Rafael J. Wysocki, Intel Open Source Technology Center.
> --
> 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