diff mbox series

PM-runtime: add tracepoints for usage_count changes

Message ID cb199a03895f8a11d9039209e6ac1cd92b1d1fb9.1578155207.git.mirq-linux@rere.qmqm.pl (mailing list archive)
State Mainlined, archived
Headers show
Series PM-runtime: add tracepoints for usage_count changes | expand

Commit Message

Michał Mirosław Jan. 4, 2020, 4:27 p.m. UTC
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(-)

Comments

Greg KH Jan. 4, 2020, 6:21 p.m. UTC | #1
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
Michał Mirosław Jan. 6, 2020, 10 a.m. UTC | #2
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
Rafael J. Wysocki Jan. 13, 2020, 11:29 a.m. UTC | #3
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!
diff mbox series

Patch

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),