Re: [PATCH] power, trace: add tracing for device_resume

["Rafael J. Wysocki" <rjw@sisk.pl>]

On Friday, May 18, 2012, Sameer Nanda wrote:
> Added event tracing for device_resume. This helps quickly pinpoint which
> devices take a long time to resume.

There is some code already for that in the PM core.  You have to boot the
kernel with initcall_debug in the command line to activate it.

Thanks,
Rafael


> Signed-off-by: Sameer Nanda <snanda@chromium.org>
> ---
>  Documentation/trace/events-power.txt |   20 +++++++++++
>  drivers/base/power/main.c            |   10 ++++++
>  include/trace/events/power.h         |   59 ++++++++++++++++++++++++++++++++++
>  3 files changed, 89 insertions(+), 0 deletions(-)
> 
> diff --git a/Documentation/trace/events-power.txt b/Documentation/trace/events-power.txt
> index cf794af..dbfb7f0 100644
> --- a/Documentation/trace/events-power.txt
> +++ b/Documentation/trace/events-power.txt
> @@ -88,3 +88,23 @@ power_domain_target	"%s state=%lu cpu_id=%lu"
>  The first parameter gives the power domain name (e.g. "mpu_pwrdm").
>  The second parameter is the power domain target state.
>  
> +4. Device resume events
> +=======================
> +The device resume events are used for measuring the time taken to resume
> +devices.
> +
> +device_resume_in	"device=%s driver=%s"
> +device_resume_waited	"device=%s driver=%s time_delta=%lld"
> +device_resume_out	"device=%s driver=%s time_delta=%lld"
> +
> +The first parameter is the device that is being resumed.
> +
> +The second parameter is the driver associated with the device being resumed.
> +
> +The third parameter in device_resume_waited is the time delta from the entry
> +point of device_resume to the wait completion of parent device being resumed.
> +The unit for time_delta is us.
> +
> +The third parameter in device_resume_out is the time delta from the wait
> +completion of parent device being resumed to device_resume being completed.
> +The unit for time_delta is us.
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index b462c0e..3ed01cd 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -28,6 +28,7 @@
>  #include <linux/sched.h>
>  #include <linux/async.h>
>  #include <linux/suspend.h>
> +#include <trace/events/power.h>
>  
>  #include "../base.h"
>  #include "power.h"
> @@ -565,11 +566,19 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
>  	char *info = NULL;
>  	int error = 0;
>  	bool put = false;
> +	s64 in_time = ktime_to_us(ktime_get());
> +	s64 wait_done_time;
> +
> +	trace_device_resume_in(dev);
>  
>  	TRACE_DEVICE(dev);
>  	TRACE_RESUME(0);
>  
>  	dpm_wait(dev->parent, async);
> +
> +	wait_done_time = ktime_to_us(ktime_get());
> +	trace_device_resume_waited(dev, wait_done_time - in_time);
> +
>  	device_lock(dev);
>  
>  	/*
> @@ -638,6 +647,7 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
>  	if (put)
>  		pm_runtime_put_sync(dev);
>  
> +	trace_device_resume_out(dev, ktime_to_us(ktime_get()) - wait_done_time);
>  	return error;
>  }
>  
> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
> index cae9a94..9601419 100644
> --- a/include/trace/events/power.h
> +++ b/include/trace/events/power.h
> @@ -4,6 +4,7 @@
>  #if !defined(_TRACE_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
>  #define _TRACE_POWER_H
>  
> +#include <linux/device.h>
>  #include <linux/ktime.h>
>  #include <linux/tracepoint.h>
>  
> @@ -48,6 +49,64 @@ DEFINE_EVENT(cpu, cpu_frequency,
>  	TP_ARGS(frequency, cpu_id)
>  );
>  
> +#define get_driver_name(dev) dev->driver && dev->driver->name ? \
> +		dev->driver->name : ""
> +
> +TRACE_EVENT(device_resume_in,
> +
> +	TP_PROTO(struct device *dev),
> +
> +	TP_ARGS(dev),
> +
> +	TP_STRUCT__entry(
> +		__string(	device_name,	dev_name(dev)		)
> +		__string(	driver_name,	get_driver_name(dev)	)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(device_name, dev_name(dev));
> +		__assign_str(driver_name, get_driver_name(dev));
> +	),
> +
> +	TP_printk("device=%s driver=%s", __get_str(device_name), __get_str(driver_name))
> +);
> +
> +DECLARE_EVENT_CLASS(device_resume_internal,
> +
> +	TP_PROTO(struct device *dev, s64 time_delta),
> +
> +	TP_ARGS(dev, time_delta),
> +
> +	TP_STRUCT__entry(
> +		__field(	s64,		time_delta		)
> +		__string(	device_name,	dev_name(dev)		)
> +		__string(	driver_name,	get_driver_name(dev)	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->time_delta = time_delta;
> +		__assign_str(device_name, dev_name(dev));
> +		__assign_str(driver_name, get_driver_name(dev));
> +	),
> +
> +	TP_printk("device=%s driver=%s time_delta=%lld", __get_str(device_name),
> +		  __get_str(driver_name), __entry->time_delta)
> +);
> +
> +DEFINE_EVENT(device_resume_internal, device_resume_waited,
> +
> +	TP_PROTO(struct device *dev, s64 time_delta),
> +
> +	TP_ARGS(dev, time_delta)
> +);
> +
> +DEFINE_EVENT(device_resume_internal, device_resume_out,
> +
> +	TP_PROTO(struct device *dev, s64 time_delta),
> +
> +	TP_ARGS(dev, time_delta)
> +);
> +
>  TRACE_EVENT(machine_suspend,
>  
>  	TP_PROTO(unsigned int state),
>