[PATCH v2] power: new trace event to print device suspend and resume time

[PATCH v2] power: new trace event to print device suspend and resume time

[Shuah Khan]

A new trace event is added to pm events to print time it takes to suspend and
resume a device. It generates trace message that includes device, driver,
parent information in addition to the type of pm ops invoked as well as the
pm event and error status from the pm ops. Example trace below:

bash-2484  [001] ....   907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class  usecs=0 err=0

bash-2484  [001] ....   909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class  usecs=0 err=0

bash-2484  [001] ....   907.330155: device_pm_report_time: rfkill rfkill3 parent=phy0 state=freeze ops=legacy class  usecs=0 err=0

bash-2484  [001] ....   909.906739: device_pm_report_time: rfkill rfkill3 parent=phy0 state=restore ops=legacy class  usecs=1 err=0

bash-2484  [000] ....   907.389079: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=freeze ops=legacy class  usecs=57497 err=0

bash-2484  [001] ....   909.906731: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=restore ops=legacy class  usecs=95119 err=0

Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
---
 drivers/base/power/main.c    |   27 +++++++++++++++++++--------
 include/trace/events/power.h |   34 ++++++++++++++++++++++++++++++++++
 2 files changed, 53 insertions(+), 8 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 5a9b656..d268c45 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 <linux/cpuidle.h>
 #include "../base.h"
 #include "power.h"
@@ -56,6 +57,8 @@ static pm_message_t pm_transition;
 
 static int async_error;
 
+static char *pm_verb(int);
+
 /**
  * device_pm_sleep_init - Initialize system suspend-related device fields.
  * @dev: Device object being initialized.
@@ -172,16 +175,21 @@ static ktime_t initcall_debug_start(struct device *dev)
 }
 
 static void initcall_debug_report(struct device *dev, ktime_t calltime,
-				  int error)
+				  int error, pm_message_t state, char *info)
 {
 	ktime_t delta, rettime;
 
+	rettime = ktime_get();
+	delta = ktime_sub(rettime, calltime);
+
 	if (pm_print_times_enabled) {
-		rettime = ktime_get();
-		delta = ktime_sub(rettime, calltime);
 		pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
 			error, (unsigned long long)ktime_to_ns(delta) >> 10);
 	}
+
+	trace_device_pm_report_time(dev_name(dev), dev_driver_string(dev),
+				dev->parent ? dev_name(dev->parent) : "none",
+				info, delta, pm_verb(state.event), error);
 }
 
 /**
@@ -379,7 +387,7 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
 	error = cb(dev);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, error, state, info);
 
 	return error;
 }
@@ -1027,7 +1035,8 @@ EXPORT_SYMBOL_GPL(dpm_suspend_end);
  * @cb: Suspend callback to execute.
  */
 static int legacy_suspend(struct device *dev, pm_message_t state,
-			  int (*cb)(struct device *dev, pm_message_t state))
+			  int (*cb)(struct device *dev, pm_message_t state),
+			  char *info)
 {
 	int error;
 	ktime_t calltime;
@@ -1037,7 +1046,7 @@ static int legacy_suspend(struct device *dev, pm_message_t state,
 	error = cb(dev, state);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, error, state, info);
 
 	return error;
 }
@@ -1097,7 +1106,8 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async)
 			goto Run;
 		} else if (dev->class->suspend) {
 			pm_dev_dbg(dev, state, "legacy class ");
-			error = legacy_suspend(dev, state, dev->class->suspend);
+			error = legacy_suspend(dev, state, dev->class->suspend,
+						"legacy class ");
 			goto End;
 		}
 	}
@@ -1108,7 +1118,8 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async)
 			callback = pm_op(dev->bus->pm, state);
 		} else if (dev->bus->suspend) {
 			pm_dev_dbg(dev, state, "legacy bus ");
-			error = legacy_suspend(dev, state, dev->bus->suspend);
+			error = legacy_suspend(dev, state, dev->bus->suspend,
+						"legacy bus ");
 			goto End;
 		}
 	}
diff --git a/include/trace/events/power.h b/include/trace/events/power.h
index 8e42410..6240541 100644
--- a/include/trace/events/power.h
+++ b/include/trace/events/power.h
@@ -66,6 +66,40 @@ TRACE_EVENT(machine_suspend,
 	TP_printk("state=%lu", (unsigned long)__entry->state)
 );
 
+TRACE_EVENT(device_pm_report_time,
+
+	TP_PROTO(const char *device, const char *driver, const char *parent,
+		 const char *pm_ops, ktime_t ops_time, char *pm_event_str,
+		 int error),
+
+	TP_ARGS(device, driver, parent, pm_ops, ops_time, pm_event_str, error),
+
+	TP_STRUCT__entry(
+		__string(device, device)
+		__string(driver, driver)
+		__string(parent, parent)
+		__string(pm_ops, pm_ops)
+		__string(pm_event_str, pm_event_str)
+		__field(s64, ops_time)
+		__field(int, error)
+	),
+
+	TP_fast_assign(
+		__assign_str(device, device);
+		__assign_str(driver, driver);
+		__assign_str(parent, parent);
+		__assign_str(pm_ops, pm_ops);
+		__assign_str(pm_event_str, pm_event_str);
+		__entry->ops_time = ktime_to_ns(ops_time) >> 10;
+		__entry->error = error;
+	),
+
+	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n",
+		__get_str(driver), __get_str(device), __get_str(parent),
+		__get_str(pm_event_str), __get_str(pm_ops),
+		__entry->ops_time, __entry->error)
+);
+
 DECLARE_EVENT_CLASS(wakeup_source,
 
 	TP_PROTO(const char *name, unsigned int state),
-- 
1.7.10.4

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Joe Perches]

On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:
> A new trace event is added to pm events to print time it takes to suspend and
> resume a device. It generates trace message that includes device, driver,
> parent information in addition to the type of pm ops invoked as well as the
> pm event and error status from the pm ops. Example trace below:
> 
> bash-2484  [001] ....   907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class  usecs=0 err=0
> 
> bash-2484  [001] ....   909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class  usecs=0 err=0

Hi again Shuah.

A few things:

> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
[]
> +	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n",

As I wrote before, do not end a TP_printk with "\n",

All TP_printks are self-contained and are not possible
to use a thing like pr_cont so no newline is ever used.

Use:

	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d",

Given the data is in nsecs, why use usecs for the time?
I think full resolution would be better.

Why are there two spaces after "ops=class"? One would be more normal.

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Shuah Khan]

On 07/17/2013 10:09 AM, Joe Perches wrote:
> On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:
>> A new trace event is added to pm events to print time it takes to suspend and
>> resume a device. It generates trace message that includes device, driver,
>> parent information in addition to the type of pm ops invoked as well as the
>> pm event and error status from the pm ops. Example trace below:
>>
>> bash-2484  [001] ....   907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class  usecs=0 err=0
>>
>> bash-2484  [001] ....   909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class  usecs=0 err=0
>

Hi Joe,

> Hi again Shuah.
>
> A few things:
>
>> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
> []
>> +	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n",
>
> As I wrote before, do not end a TP_printk with "\n",
>
> All TP_printks are self-contained and are not possible
> to use a thing like pr_cont so no newline is ever used.
>
> Use:
>
> 	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d",

Sorry. Missed that one. Not intentional, just an oversight. :) I should 
fix that one.

>
> Given the data is in nsecs, why use usecs for the time?
> I think full resolution would be better.

My intent to was to match the time units to the original pm_print_times.

Rafael! Do you have any preference as to usecs vs. nsecs?

>
> Why are there two spaces after "ops=class"? One would be more normal.
>
>

This one is tough. The ops string that gets generated in conditionals in 
__device_suspend() and device_resume() routines, has an extra space at 
the end. I am not sure why that was done and the subsequent pr_* that 
print that string also depend on that extra space at the end. I don't 
have an easy way to fix it without changing lots of code where this 
string is generated. Hence, I chose to leave the extra space in. I also 
didn't want to propagate that assumption that there is an extra space 
into this new tracepoint.

I could truncate the string before I pass it to the new tracepoint 
routine, however I don't like that idea. One thing I can do is, generate 
separate patch that fixes the extra space issue. That would address the 
extra space in all cases.

-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Joe Perches]

On Wed, 2013-07-17 at 16:30 +0000, Shuah Khan wrote:
> On 07/17/2013 10:09 AM, Joe Perches wrote:
> > On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:
> >> A new trace event is added to pm events to print time it takes to suspend and
> >> resume a device. It generates trace message that includes device, driver,
> >> parent information in addition to the type of pm ops invoked as well as the
> >> pm event and error status from the pm ops. Example trace below:
> >>
> >> bash-2484  [001] ....   907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class  usecs=0 err=0
> >>
> >> bash-2484  [001] ....   909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class  usecs=0 err=0
[]
> > Given the data is in nsecs, why use usecs for the time?
> > I think full resolution would be better.
> 
> My intent to was to match the time units to the original pm_print_times.

I don't think that maintaining consistency is
useful in a new facility when you lose precision.

Also the accuracy is suspect as it's calculated with
>>10 rather than an actual divide by 1000.

> Rafael! Do you have any preference as to usecs vs. nsecs?

> > Why are there two spaces after "ops=class"? One would be more normal.

> This one is tough. The ops string that gets generated in conditionals in 
> __device_suspend() and device_resume() routines, has an extra space at 
> the end. I am not sure why that was done and the subsequent pr_* that 
> print that string also depend on that extra space at the end. I don't 
> have an easy way to fix it without changing lots of code where this 
> string is generated.

I think the easiest way to "fix" it is to change
the TP_printk format to:

	TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d",

> Hence, I chose to leave the extra space in. I also 
> didn't want to propagate that assumption that there is an extra space 
> into this new tracepoint.

It's a big deal, it just seemed untidy.

There are a couple of places in drivers/base/power/main.c
where info is set to NULL.  I didn't look hard to see if
any of those are propagated through to this point, but
there are uses of 'info ?: ""' for some of the logging
messages.  That _might_ an issue.

It looks like all the other logging message uses of info
have "%s%s" so that proper word spacing is done when
info is "" or NULL.

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Joe Perches]

On Wed, 2013-07-17 at 09:41 -0700, Joe Perches wrote:
> It's a big deal, it just seemed untidy.

No, it's not true, that's silly.

I dropped a "not" there.

It's _not_ a big deal.

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Shuah Khan]

On 07/17/2013 10:41 AM, Joe Perches wrote:

> I think the easiest way to "fix" it is to change
> the TP_printk format to:
>
> 	TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d",

I will just adjust for the space and add a comment.

>
>> Hence, I chose to leave the extra space in. I also
>> didn't want to propagate that assumption that there is an extra space
>> into this new tracepoint.
>
> It's a big deal, it just seemed untidy.
>
> There are a couple of places in drivers/base/power/main.c
> where info is set to NULL.  I didn't look hard to see if
> any of those are propagated through to this point, but
> there are uses of 'info ?: ""' for some of the logging
> messages.  That _might_ an issue.
>
> It looks like all the other logging message uses of info
> have "%s%s" so that proper word spacing is done when
> info is "" or NULL.
>

Yeah that would be bad. The safe thing might me to add a info null 
check. Working on v3 that includes Steve's review comment as well.

thanks,
-- Shuah

Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Rafael J. Wysocki]

On Wednesday, July 17, 2013 09:41:08 AM Joe Perches wrote:
> On Wed, 2013-07-17 at 16:30 +0000, Shuah Khan wrote:
> > On 07/17/2013 10:09 AM, Joe Perches wrote:
> > > On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:
> > >> A new trace event is added to pm events to print time it takes to suspend and
> > >> resume a device. It generates trace message that includes device, driver,
> > >> parent information in addition to the type of pm ops invoked as well as the
> > >> pm event and error status from the pm ops. Example trace below:
> > >>
> > >> bash-2484  [001] ....   907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class  usecs=0 err=0
> > >>
> > >> bash-2484  [001] ....   909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class  usecs=0 err=0
> []
> > > Given the data is in nsecs, why use usecs for the time?
> > > I think full resolution would be better.
> > 
> > My intent to was to match the time units to the original pm_print_times.
> 
> I don't think that maintaining consistency is
> useful in a new facility when you lose precision.
> 
> Also the accuracy is suspect as it's calculated with
> >>10 rather than an actual divide by 1000.

It's because that is way faster and we don't need great precision here.

> > Rafael! Do you have any preference as to usecs vs. nsecs?

The numbers in microseconds are easier to read, but I guess we can just
use nanoseconds and then process the output.

Thanks,
Rafael


> > > Why are there two spaces after "ops=class"? One would be more normal.
> 
> > This one is tough. The ops string that gets generated in conditionals in 
> > __device_suspend() and device_resume() routines, has an extra space at 
> > the end. I am not sure why that was done and the subsequent pr_* that 
> > print that string also depend on that extra space at the end. I don't 
> > have an easy way to fix it without changing lots of code where this 
> > string is generated.
> 
> I think the easiest way to "fix" it is to change
> the TP_printk format to:
> 
> 	TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d",
> 
> > Hence, I chose to leave the extra space in. I also 
> > didn't want to propagate that assumption that there is an extra space 
> > into this new tracepoint.
> 
> It's a big deal, it just seemed untidy.
> 
> There are a couple of places in drivers/base/power/main.c
> where info is set to NULL.  I didn't look hard to see if
> any of those are propagated through to this point, but
> there are uses of 'info ?: ""' for some of the logging
> messages.  That _might_ an issue.
> 
> It looks like all the other logging message uses of info
> have "%s%s" so that proper word spacing is done when
> info is "" or NULL.
> 
> 
> 
-- 
I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Steven Rostedt]

On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:

> +TRACE_EVENT(device_pm_report_time,
> +
> +	TP_PROTO(const char *device, const char *driver, const char *parent,
> +		 const char *pm_ops, ktime_t ops_time, char *pm_event_str,
> +		 int error),
> +
> +	TP_ARGS(device, driver, parent, pm_ops, ops_time, pm_event_str, error),
> +
> +	TP_STRUCT__entry(
> +		__string(device, device)
> +		__string(driver, driver)
> +		__string(parent, parent)
> +		__string(pm_ops, pm_ops)
> +		__string(pm_event_str, pm_event_str)
> +		__field(s64, ops_time)
> +		__field(int, error)
> +	),
> +
> +	TP_fast_assign(
> +		__assign_str(device, device);
> +		__assign_str(driver, driver);
> +		__assign_str(parent, parent);
> +		__assign_str(pm_ops, pm_ops);
> +		__assign_str(pm_event_str, pm_event_str);
> +		__entry->ops_time = ktime_to_ns(ops_time) >> 10;

You may want to just record the ops_time, and do the conversion in the
TP_printk(). This is the fast path, and any calculations done here just
increases the overhead of the trace point.

-- Steve

> +		__entry->error = error;
> +	),
> +
> +	TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n",
> +		__get_str(driver), __get_str(device), __get_str(parent),
> +		__get_str(pm_event_str), __get_str(pm_ops),
> +		__entry->ops_time, __entry->error)
> +);
> +
>  DECLARE_EVENT_CLASS(wakeup_source,
>  
>  	TP_PROTO(const char *name, unsigned int state),

Re: [PATCH v2] power: new trace event to print device suspend and resume time

[Shuah Khan]

On 07/17/2013 10:35 AM, Steven Rostedt wrote:
> On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote:
>
>> +TRACE_EVENT(device_pm_report_time,
>> +
>> +	TP_PROTO(const char *device, const char *driver, const char *parent,
>> +		 const char *pm_ops, ktime_t ops_time, char *pm_event_str,
>> +		 int error),
>> +
>> +	TP_ARGS(device, driver, parent, pm_ops, ops_time, pm_event_str, error),
>> +
>> +	TP_STRUCT__entry(
>> +		__string(device, device)
>> +		__string(driver, driver)
>> +		__string(parent, parent)
>> +		__string(pm_ops, pm_ops)
>> +		__string(pm_event_str, pm_event_str)
>> +		__field(s64, ops_time)
>> +		__field(int, error)
>> +	),
>> +
>> +	TP_fast_assign(
>> +		__assign_str(device, device);
>> +		__assign_str(driver, driver);
>> +		__assign_str(parent, parent);
>> +		__assign_str(pm_ops, pm_ops);
>> +		__assign_str(pm_event_str, pm_event_str);
>> +		__entry->ops_time = ktime_to_ns(ops_time) >> 10;
>
> You may want to just record the ops_time, and do the conversion in the
> TP_printk(). This is the fast path, and any calculations done here just
> increases the overhead of the trace point.
>
> -- Steve

Thanks for the review and pointing the overhead out. Will fix that.

-- Shuah

-- 
Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research 
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658