[PATCH] PM-runtime: add tracepoints for usage_count changes

[PATCH] PM-runtime: add tracepoints for usage_count changes

[Michał Mirosław]

Add tracepoints to remaining places where device's power.usage_count
is changed. This helps debugging where and why autosuspend is prevented.

Signed-off-by: Michał Mirosław <mirq-linux@rere.qmqm.pl>
---
 drivers/base/power/runtime.c | 13 +++++++++++--
 include/trace/events/rpm.h   |  6 ++++++
 2 files changed, 17 insertions(+), 2 deletions(-)

diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
index 48616f358854..16134a69bf6f 100644
--- a/drivers/base/power/runtime.c
+++ b/drivers/base/power/runtime.c
@@ -1006,8 +1006,10 @@ int __pm_runtime_idle(struct device *dev, int rpmflags)
 	int retval;
 
 	if (rpmflags & RPM_GET_PUT) {
-		if (!atomic_dec_and_test(&dev->power.usage_count))
+		if (!atomic_dec_and_test(&dev->power.usage_count)) {
+			trace_rpm_usage_rcuidle(dev, rpmflags);
 			return 0;
+		}
 	}
 
 	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
@@ -1038,8 +1040,10 @@ int __pm_runtime_suspend(struct device *dev, int rpmflags)
 	int retval;
 
 	if (rpmflags & RPM_GET_PUT) {
-		if (!atomic_dec_and_test(&dev->power.usage_count))
+		if (!atomic_dec_and_test(&dev->power.usage_count)) {
+			trace_rpm_usage_rcuidle(dev, rpmflags);
 			return 0;
+		}
 	}
 
 	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
@@ -1101,6 +1105,7 @@ int pm_runtime_get_if_in_use(struct device *dev)
 	retval = dev->power.disable_depth > 0 ? -EINVAL :
 		dev->power.runtime_status == RPM_ACTIVE
 			&& atomic_inc_not_zero(&dev->power.usage_count);
+	trace_rpm_usage_rcuidle(dev, 0);
 	spin_unlock_irqrestore(&dev->power.lock, flags);
 	return retval;
 }
@@ -1434,6 +1439,8 @@ void pm_runtime_allow(struct device *dev)
 	dev->power.runtime_auto = true;
 	if (atomic_dec_and_test(&dev->power.usage_count))
 		rpm_idle(dev, RPM_AUTO | RPM_ASYNC);
+	else
+		trace_rpm_usage_rcuidle(dev, RPM_AUTO | RPM_ASYNC);
 
  out:
 	spin_unlock_irq(&dev->power.lock);
@@ -1501,6 +1508,8 @@ static void update_autosuspend(struct device *dev, int old_delay, int old_use)
 		if (!old_use || old_delay >= 0) {
 			atomic_inc(&dev->power.usage_count);
 			rpm_resume(dev, 0);
+		} else {
+			trace_rpm_usage_rcuidle(dev, 0);
 		}
 	}
 
diff --git a/include/trace/events/rpm.h b/include/trace/events/rpm.h
index 26927a560eab..3c716214dab1 100644
--- a/include/trace/events/rpm.h
+++ b/include/trace/events/rpm.h
@@ -74,6 +74,12 @@ DEFINE_EVENT(rpm_internal, rpm_idle,
 
 	TP_ARGS(dev, flags)
 );
+DEFINE_EVENT(rpm_internal, rpm_usage,
+
+	TP_PROTO(struct device *dev, int flags),
+
+	TP_ARGS(dev, flags)
+);
 
 TRACE_EVENT(rpm_return_int,
 	TP_PROTO(struct device *dev, unsigned long ip, int ret),
-- 
2.20.1

Re: [PATCH] PM-runtime: add tracepoints for usage_count changes

[Greg Kroah-Hartman]

On Sat, Jan 04, 2020 at 05:27:57PM +0100, Michał Mirosław wrote:
> Add tracepoints to remaining places where device's power.usage_count
> is changed. This helps debugging where and why autosuspend is prevented.
> 
> Signed-off-by: Michał Mirosław <mirq-linux@rere.qmqm.pl>
> ---
>  drivers/base/power/runtime.c | 13 +++++++++++--
>  include/trace/events/rpm.h   |  6 ++++++
>  2 files changed, 17 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
> index 48616f358854..16134a69bf6f 100644
> --- a/drivers/base/power/runtime.c
> +++ b/drivers/base/power/runtime.c
> @@ -1006,8 +1006,10 @@ int __pm_runtime_idle(struct device *dev, int rpmflags)
>  	int retval;
>  
>  	if (rpmflags & RPM_GET_PUT) {
> -		if (!atomic_dec_and_test(&dev->power.usage_count))
> +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> +			trace_rpm_usage_rcuidle(dev, rpmflags);

Who and what is really going to use these tracepoints?

And putting them in these if statements seems odd, are you sure that's
the correct place?  What do these show to userspace?

>  			return 0;
> +		}
>  	}
>  
>  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> @@ -1038,8 +1040,10 @@ int __pm_runtime_suspend(struct device *dev, int rpmflags)
>  	int retval;
>  
>  	if (rpmflags & RPM_GET_PUT) {
> -		if (!atomic_dec_and_test(&dev->power.usage_count))
> +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> +			trace_rpm_usage_rcuidle(dev, rpmflags);
>  			return 0;
> +		}
>  	}
>  
>  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> @@ -1101,6 +1105,7 @@ int pm_runtime_get_if_in_use(struct device *dev)
>  	retval = dev->power.disable_depth > 0 ? -EINVAL :
>  		dev->power.runtime_status == RPM_ACTIVE
>  			&& atomic_inc_not_zero(&dev->power.usage_count);
> +	trace_rpm_usage_rcuidle(dev, 0);

Why this one?


>  	spin_unlock_irqrestore(&dev->power.lock, flags);
>  	return retval;
>  }
> @@ -1434,6 +1439,8 @@ void pm_runtime_allow(struct device *dev)
>  	dev->power.runtime_auto = true;
>  	if (atomic_dec_and_test(&dev->power.usage_count))
>  		rpm_idle(dev, RPM_AUTO | RPM_ASYNC);
> +	else
> +		trace_rpm_usage_rcuidle(dev, RPM_AUTO | RPM_ASYNC);

Are you sure this is correct?

These feel odd...

thanks,

greg k-h

Re: [PATCH] PM-runtime: add tracepoints for usage_count changes

[Michał Mirosław]

On Sat, Jan 04, 2020 at 07:21:23PM +0100, Greg Kroah-Hartman wrote:
> On Sat, Jan 04, 2020 at 05:27:57PM +0100, Michał Mirosław wrote:
> > Add tracepoints to remaining places where device's power.usage_count
> > is changed. This helps debugging where and why autosuspend is prevented.
> > 
> > Signed-off-by: Michał Mirosław <mirq-linux@rere.qmqm.pl>
> > ---
> >  drivers/base/power/runtime.c | 13 +++++++++++--
> >  include/trace/events/rpm.h   |  6 ++++++
> >  2 files changed, 17 insertions(+), 2 deletions(-)
> > 
> > diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
> > index 48616f358854..16134a69bf6f 100644
> > --- a/drivers/base/power/runtime.c
> > +++ b/drivers/base/power/runtime.c
> > @@ -1006,8 +1006,10 @@ int __pm_runtime_idle(struct device *dev, int rpmflags)
> >  	int retval;
> >  
> >  	if (rpmflags & RPM_GET_PUT) {
> > -		if (!atomic_dec_and_test(&dev->power.usage_count))
> > +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> > +			trace_rpm_usage_rcuidle(dev, rpmflags);
> 
> Who and what is really going to use these tracepoints?
> 
> And putting them in these if statements seems odd, are you sure that's
> the correct place?  What do these show to userspace?
> 
> >  			return 0;
> > +		}
> >  	}
> >  
> >  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> > @@ -1038,8 +1040,10 @@ int __pm_runtime_suspend(struct device *dev, int rpmflags)
> >  	int retval;
> >  
> >  	if (rpmflags & RPM_GET_PUT) {
> > -		if (!atomic_dec_and_test(&dev->power.usage_count))
> > +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> > +			trace_rpm_usage_rcuidle(dev, rpmflags);
> >  			return 0;
> > +		}
> >  	}
> >  
> >  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> > @@ -1101,6 +1105,7 @@ int pm_runtime_get_if_in_use(struct device *dev)
> >  	retval = dev->power.disable_depth > 0 ? -EINVAL :
> >  		dev->power.runtime_status == RPM_ACTIVE
> >  			&& atomic_inc_not_zero(&dev->power.usage_count);
> > +	trace_rpm_usage_rcuidle(dev, 0);
> 
> Why this one?
> 
> 
> >  	spin_unlock_irqrestore(&dev->power.lock, flags);
> >  	return retval;
> >  }
> > @@ -1434,6 +1439,8 @@ void pm_runtime_allow(struct device *dev)
> >  	dev->power.runtime_auto = true;
> >  	if (atomic_dec_and_test(&dev->power.usage_count))
> >  		rpm_idle(dev, RPM_AUTO | RPM_ASYNC);
> > +	else
> > +		trace_rpm_usage_rcuidle(dev, RPM_AUTO | RPM_ASYNC);
> 
> Are you sure this is correct?
> 
> These feel odd...

This covers all places where power.usage_count might have changed.
If atomic_dec_and_test() decrements usage_count but not to zero,
the new value will be traced in rpm_idle(). But if the value drops to
zero, then we need to trace it explicitly to be able to have all changes
accounted for in the trace.

I actually used this patch to track down why USB storage device was
not autosuspending correctly.

Best Regards,
Michał Mirosław

Re: [PATCH] PM-runtime: add tracepoints for usage_count changes

[Rafael J. Wysocki]

On Monday, January 6, 2020 11:00:04 AM CET Michał Mirosław wrote:
> On Sat, Jan 04, 2020 at 07:21:23PM +0100, Greg Kroah-Hartman wrote:
> > On Sat, Jan 04, 2020 at 05:27:57PM +0100, Michał Mirosław wrote:
> > > Add tracepoints to remaining places where device's power.usage_count
> > > is changed. This helps debugging where and why autosuspend is prevented.
> > > 
> > > Signed-off-by: Michał Mirosław <mirq-linux@rere.qmqm.pl>
> > > ---
> > >  drivers/base/power/runtime.c | 13 +++++++++++--
> > >  include/trace/events/rpm.h   |  6 ++++++
> > >  2 files changed, 17 insertions(+), 2 deletions(-)
> > > 
> > > diff --git a/drivers/base/power/runtime.c b/drivers/base/power/runtime.c
> > > index 48616f358854..16134a69bf6f 100644
> > > --- a/drivers/base/power/runtime.c
> > > +++ b/drivers/base/power/runtime.c
> > > @@ -1006,8 +1006,10 @@ int __pm_runtime_idle(struct device *dev, int rpmflags)
> > >  	int retval;
> > >  
> > >  	if (rpmflags & RPM_GET_PUT) {
> > > -		if (!atomic_dec_and_test(&dev->power.usage_count))
> > > +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> > > +			trace_rpm_usage_rcuidle(dev, rpmflags);
> > 
> > Who and what is really going to use these tracepoints?
> > 
> > And putting them in these if statements seems odd, are you sure that's
> > the correct place?  What do these show to userspace?
> > 
> > >  			return 0;
> > > +		}
> > >  	}
> > >  
> > >  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> > > @@ -1038,8 +1040,10 @@ int __pm_runtime_suspend(struct device *dev, int rpmflags)
> > >  	int retval;
> > >  
> > >  	if (rpmflags & RPM_GET_PUT) {
> > > -		if (!atomic_dec_and_test(&dev->power.usage_count))
> > > +		if (!atomic_dec_and_test(&dev->power.usage_count)) {
> > > +			trace_rpm_usage_rcuidle(dev, rpmflags);
> > >  			return 0;
> > > +		}
> > >  	}
> > >  
> > >  	might_sleep_if(!(rpmflags & RPM_ASYNC) && !dev->power.irq_safe);
> > > @@ -1101,6 +1105,7 @@ int pm_runtime_get_if_in_use(struct device *dev)
> > >  	retval = dev->power.disable_depth > 0 ? -EINVAL :
> > >  		dev->power.runtime_status == RPM_ACTIVE
> > >  			&& atomic_inc_not_zero(&dev->power.usage_count);
> > > +	trace_rpm_usage_rcuidle(dev, 0);
> > 
> > Why this one?
> > 
> > 
> > >  	spin_unlock_irqrestore(&dev->power.lock, flags);
> > >  	return retval;
> > >  }
> > > @@ -1434,6 +1439,8 @@ void pm_runtime_allow(struct device *dev)
> > >  	dev->power.runtime_auto = true;
> > >  	if (atomic_dec_and_test(&dev->power.usage_count))
> > >  		rpm_idle(dev, RPM_AUTO | RPM_ASYNC);
> > > +	else
> > > +		trace_rpm_usage_rcuidle(dev, RPM_AUTO | RPM_ASYNC);
> > 
> > Are you sure this is correct?
> > 
> > These feel odd...
> 
> This covers all places where power.usage_count might have changed.
> If atomic_dec_and_test() decrements usage_count but not to zero,
> the new value will be traced in rpm_idle(). But if the value drops to
> zero, then we need to trace it explicitly to be able to have all changes
> accounted for in the trace.
> 
> I actually used this patch to track down why USB storage device was
> not autosuspending correctly.

Fair enough, and the patch makes sense to me, so I'm queuing it up as 5.6
material.

Thanks!