[PATCH] PM / Sleep: Print name of wakeup source that aborts suspend

[PATCH] PM / Sleep: Print name of wakeup source that aborts suspend

[Todd Poynor]

Print active wakeup sources, or the most recently active wakeup
source, when a PM transition is aborted due to wakeup source
events.

Signed-off-by: Todd Poynor <toddpoynor@google.com>
---
 drivers/base/power/wakeup.c |   29 +++++++++++++++++++++++++++++
 1 files changed, 29 insertions(+), 0 deletions(-)

A driver or app may repeatedly request a wakeup source while the system
is attempting to enter suspend, which may indicate a bug or at least
point out a highly active system component that is responsible for
decreased battery life on a mobile device.  Even when the incidence
of suspend abort is not severe, identifying wakeup sources that
frequently abort suspend can be a useful clue for power management
analysis.

In some cases the existing stats can point out the offender where there is
an unexpectedly high activation count that stands out from the others, but
in other cases the wakeup source frequently taken just after the rest of
the system thinks its time to suspend might not stand out in the overall
stats.

It is also often useful to have information about what's been happening
recently, rather than totals of all activity for the system boot.

It's suggested to (optionally?) dump a line about which wakeup source
aborted suspend to aid analysis of these situations.

diff --git a/drivers/base/power/wakeup.c b/drivers/base/power/wakeup.c
index cbb463b..c079ffe 100644
--- a/drivers/base/power/wakeup.c
+++ b/drivers/base/power/wakeup.c
@@ -649,6 +649,31 @@ void pm_wakeup_event(struct device *dev, unsigned int msec)
 }
 EXPORT_SYMBOL_GPL(pm_wakeup_event);
 
+static void print_active_wakeup_sources(void)
+{
+	struct wakeup_source *ws;
+	int active = 0;
+	struct wakeup_source *last_activity_ws = NULL;
+
+	rcu_read_lock();
+	list_for_each_entry_rcu(ws, &wakeup_sources, entry) {
+		if (ws->active) {
+			pr_info("active wakeup source: %s\n", ws->name);
+			active = 1;
+		} else if (!active &&
+			   (!last_activity_ws ||
+			    ws->last_time.tv64 >
+			    last_activity_ws->last_time.tv64)) {
+			last_activity_ws = ws;
+		}
+	}
+
+	if (!active && last_activity_ws)
+		pr_info("last active wakeup source: %s\n",
+			last_activity_ws->name);
+	rcu_read_unlock();
+}
+
 /**
  * pm_wakeup_pending - Check if power transition in progress should be aborted.
  *
@@ -671,6 +696,10 @@ bool pm_wakeup_pending(void)
 		events_check_enabled = !ret;
 	}
 	spin_unlock_irqrestore(&events_lock, flags);
+
+	if (ret)
+		print_active_wakeup_sources();
+
 	return ret;
 }
 
-- 
1.7.7.3

Re: [PATCH] PM / Sleep: Print name of wakeup source that aborts suspend

[Rafael J. Wysocki]

On Wednesday, July 18, 2012, Todd Poynor wrote:
> Print active wakeup sources, or the most recently active wakeup
> source, when a PM transition is aborted due to wakeup source
> events.
> 
> Signed-off-by: Todd Poynor <toddpoynor@google.com>
> ---
>  drivers/base/power/wakeup.c |   29 +++++++++++++++++++++++++++++
>  1 files changed, 29 insertions(+), 0 deletions(-)
> 
> A driver or app may repeatedly request a wakeup source while the system
> is attempting to enter suspend, which may indicate a bug or at least
> point out a highly active system component that is responsible for
> decreased battery life on a mobile device.  Even when the incidence
> of suspend abort is not severe, identifying wakeup sources that
> frequently abort suspend can be a useful clue for power management
> analysis.
> 
> In some cases the existing stats can point out the offender where there is
> an unexpectedly high activation count that stands out from the others, but
> in other cases the wakeup source frequently taken just after the rest of
> the system thinks its time to suspend might not stand out in the overall
> stats.
> 
> It is also often useful to have information about what's been happening
> recently, rather than totals of all activity for the system boot.
> 
> It's suggested to (optionally?) dump a line about which wakeup source
> aborted suspend to aid analysis of these situations.
> 
> diff --git a/drivers/base/power/wakeup.c b/drivers/base/power/wakeup.c
> index cbb463b..c079ffe 100644
> --- a/drivers/base/power/wakeup.c
> +++ b/drivers/base/power/wakeup.c
> @@ -649,6 +649,31 @@ void pm_wakeup_event(struct device *dev, unsigned int msec)
>  }
>  EXPORT_SYMBOL_GPL(pm_wakeup_event);
>  
> +static void print_active_wakeup_sources(void)
> +{
> +	struct wakeup_source *ws;
> +	int active = 0;
> +	struct wakeup_source *last_activity_ws = NULL;
> +
> +	rcu_read_lock();
> +	list_for_each_entry_rcu(ws, &wakeup_sources, entry) {
> +		if (ws->active) {
> +			pr_info("active wakeup source: %s\n", ws->name);
> +			active = 1;

Can we do a break here?  Or do we want to get all of them?

> +		} else if (!active &&
> +			   (!last_activity_ws ||
> +			    ws->last_time.tv64 >
> +			    last_activity_ws->last_time.tv64)) {

ktime_to_ns() anyone?

> +			last_activity_ws = ws;
> +		}
> +	}
> +
> +	if (!active && last_activity_ws)
> +		pr_info("last active wakeup source: %s\n",
> +			last_activity_ws->name);
> +	rcu_read_unlock();
> +}
> +
>  /**
>   * pm_wakeup_pending - Check if power transition in progress should be aborted.
>   *
> @@ -671,6 +696,10 @@ bool pm_wakeup_pending(void)
>  		events_check_enabled = !ret;
>  	}
>  	spin_unlock_irqrestore(&events_lock, flags);
> +
> +	if (ret)
> +		print_active_wakeup_sources();
> +
>  	return ret;
>  }

There is no way this or equivalent can go into v3.6.  It may go into v3.7,
but there's a plenty of time for that.

Thanks,
Rafael

Re: [PATCH] PM / Sleep: Print name of wakeup source that aborts suspend

[Todd Poynor]

On Wed, Jul 18, 2012 at 09:47:34PM +0200, Rafael J. Wysocki wrote:
> On Wednesday, July 18, 2012, Todd Poynor wrote:
...
> > +{
> > +	struct wakeup_source *ws;
> > +	int active = 0;
> > +	struct wakeup_source *last_activity_ws = NULL;
> > +
> > +	rcu_read_lock();
> > +	list_for_each_entry_rcu(ws, &wakeup_sources, entry) {
> > +		if (ws->active) {
> > +			pr_info("active wakeup source: %s\n", ws->name);
> > +			active = 1;
> 
> Can we do a break here?  Or do we want to get all of them?

I haven't seen more than 3 activated during suspend entry at a time, but
could just list one.  I haven't made that change yet but will if it's
preferred.

> 
> > +		} else if (!active &&
> > +			   (!last_activity_ws ||
> > +			    ws->last_time.tv64 >
> > +			    last_activity_ws->last_time.tv64)) {
> 
> ktime_to_ns() anyone?

Sure, I avoided it because some configs do math on each of these, but
perhaps most implementations implement it as a NOP.

> 
> > +			last_activity_ws = ws;
> > +		}
> > +	}
> > +
> > +	if (!active && last_activity_ws)
> > +		pr_info("last active wakeup source: %s\n",
> > +			last_activity_ws->name);
> > +	rcu_read_unlock();
> > +}
> > +
> >  /**
> >   * pm_wakeup_pending - Check if power transition in progress should be aborted.
> >   *
> > @@ -671,6 +696,10 @@ bool pm_wakeup_pending(void)
> >  		events_check_enabled = !ret;
> >  	}
> >  	spin_unlock_irqrestore(&events_lock, flags);
> > +
> > +	if (ret)
> > +		print_active_wakeup_sources();
> > +
> >  	return ret;
> >  }
> 
> There is no way this or equivalent can go into v3.6.  It may go into v3.7,
> but there's a plenty of time for that.

Sounds fine, thanks.

> 
> Thanks,
> Rafael

Todd

Re: [PATCH] PM / Sleep: Print name of wakeup source that aborts suspend

[Rafael J. Wysocki]

On Friday, July 20, 2012, Todd Poynor wrote:
> On Wed, Jul 18, 2012 at 09:47:34PM +0200, Rafael J. Wysocki wrote:
> > On Wednesday, July 18, 2012, Todd Poynor wrote:
> ...
> > > +{
> > > +	struct wakeup_source *ws;
> > > +	int active = 0;
> > > +	struct wakeup_source *last_activity_ws = NULL;
> > > +
> > > +	rcu_read_lock();
> > > +	list_for_each_entry_rcu(ws, &wakeup_sources, entry) {
> > > +		if (ws->active) {
> > > +			pr_info("active wakeup source: %s\n", ws->name);
> > > +			active = 1;
> > 
> > Can we do a break here?  Or do we want to get all of them?
> 
> I haven't seen more than 3 activated during suspend entry at a time, but
> could just list one.  I haven't made that change yet but will if it's
> preferred.

That depend on what your needs are.  For debugging purposes it probably is
better to print them all.

Thanks,
Rafael