Re: [PATCH 10] PM: Measure suspend and resume times for individual devices (was: Re: [PATCH 2/6] PM: Asynchronous resume of devices)

[Ingo Molnar <mingo@elte.hu>]

* Rafael J. Wysocki <rjw@sisk.pl> wrote:

> On Sunday 30 August 2009, Rafael J. Wysocki wrote:
> > On Sunday 30 August 2009, Alan Stern wrote:
> > > On Sat, 29 Aug 2009, Rafael J. Wysocki wrote:
> > > 
> > > > I only wanted to say that the advantage is not really that "big". :-)
> > > > 
> > > > > I must agree, 14 threads isn't a lot.  But at the moment that number is 
> > > > > random, not under your control.
> > > > 
> > > > It's not directly controlled, but there are some interactions between the
> > > > async threads, the main threads and the async framework that don't allow this
> > > > number to grow too much.
> > > > 
> > > > IMO it sometimes is better to allow things to work themselves out, as long as
> > > > they don't explode, than to try to keep everything under strict control.  YMMV.
> > > 
> > > For testing purposes it would be nice to have a one-line summary for
> > > each device containing a thread ID, start timestamp, end timestamp, and
> > > elapsed time.  With that information you could evaluate the amount of
> > > parallelism and determine where the bottlenecks are.  It would give a
> > > much more detailed picture of the entire process than the total time of
> > > your recent patch 9.
> > 
> > Of course it would.  I think I'll implement it.
> 
> OK, below is a patch for that.  It only prints the time elapsed, because the
> timestamps themselves can be obtained from the usual kernel timestamping.
> 
> It's on top of all the previous patches.
> 
> Thanks,
> Rafael
> 
> ---
> From: Rafael J. Wysocki <rjw@sisk.pl>
> Subject: PM: Measure suspend and resume times for individual devices
> 
> If verbose PM debugging is enabled, measure and print the time of
> suspending and resuming of individual devices.
> 
> Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
> ---
>  drivers/base/power/main.c |   51 +++++++++++++++++++++++++++++++++++++++++-----
>  kernel/power/swsusp.c     |    2 -
>  2 files changed, 47 insertions(+), 6 deletions(-)
> 
> Index: linux-2.6/drivers/base/power/main.c
> ===================================================================
> --- linux-2.6.orig/drivers/base/power/main.c
> +++ linux-2.6/drivers/base/power/main.c
> @@ -442,11 +442,11 @@ static bool pm_op_started(struct device 
>   */
>  int pm_time_elapsed(struct timeval *start, struct timeval *stop)
>  {
> -	s64 elapsed_centisecs64;
> +	s64 elapsed_msecs64;
>  
> -	elapsed_centisecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
> -	do_div(elapsed_centisecs64, NSEC_PER_SEC / 100);
> -	return elapsed_centisecs64;
> +	elapsed_msecs64 = timeval_to_ns(stop) - timeval_to_ns(start);
> +	do_div(elapsed_msecs64, NSEC_PER_SEC / 1000);
> +	return elapsed_msecs64;
>  }
>  
>  static char *pm_verb(int event)
> @@ -476,7 +476,7 @@ static char *pm_verb(int event)
>  static void dpm_show_time(struct timeval *start, struct timeval *stop,
>  			  pm_message_t state, const char *info)
>  {
> -	int centisecs = pm_time_elapsed(start, stop);
> +	int centisecs = pm_time_elapsed(start, stop) / 10;
>  
>  	printk(KERN_INFO "PM: %s%s%s of devices complete in %d.%02d seconds\n",
>  		info ? info : "", info ? " " : "", pm_verb(state.event),
> @@ -497,6 +497,33 @@ static void pm_dev_err(struct device *de
>  		kobject_name(&dev->kobj), pm_verb(state.event), info, error);
>  }
>  
> +#ifdef DEBUG
> +static void device_show_time(struct timeval *start, struct device *dev,
> +			     pm_message_t state, char *info)
> +{
> +	struct timeval stop;
> +	int msecs;
> +
> +	do_gettimeofday(&stop);
> +	msecs = pm_time_elapsed(start, &stop);
> +	dev_dbg(dev, "PID %d: %s%s%s complete in %d.%03d seconds\n",
> +		task_pid_nr(current), info ? info : "", info ? " " : "",
> +		pm_verb(state.event), msecs / 1000, msecs % 1000);
> +}
> +
> +#define TIMER_DECLARE(timer)	struct timeval timer
> +#define TIMER_START(timer)	do { \
> +		do_gettimeofday(&timer); \
> +	} while (0)
> +#define TIMER_STOP(timer, dev, state, info)	do { \
> +		device_show_time(&timer, dev, state, info); \
> +	} while (0)
> +#else /* !DEBUG */
> +#define TIMER_DECLARE(timer)
> +#define TIMER_START(timer)	do { } while (0)
> +#define TIMER_STOP(timer, dev, state, info)	do { } while (0)
> +#endif /* !DEBUG */
> +
>  /*------------------------- Resume routines -------------------------*/
>  
>  /**
> @@ -510,7 +537,9 @@ static void pm_dev_err(struct device *de
>  static int __device_resume_noirq(struct device *dev, pm_message_t state)
>  {
>  	int error = 0;
> +	TIMER_DECLARE(timer);
>  
> +	TIMER_START(timer);
>  	TRACE_DEVICE(dev);
>  	TRACE_RESUME(0);
>  
> @@ -523,6 +552,7 @@ static int __device_resume_noirq(struct 
>  	wake_up_all(&dev->power.wait_queue);
>  
>  	TRACE_RESUME(error);
> +	TIMER_STOP(timer, dev, state, "EARLY");
>  	return error;

Hm, these CPP macros are rather ugly. Why is there a need for the 
TIMER_DECLARE() wrapper - if a proper inline function is used 
there's no need for that. There's other all-capitals macros in that 
code implementing code (and not constants) - is that really 
justified/clean?

	Ingo