* [PATCH] power: new trace event to print device suspend and resume time
@ 2013-07-16 21:23 Shuah Khan
2013-07-16 21:39 ` Joe Perches
0 siblings, 1 reply; 5+ messages in thread
From: Shuah Khan @ 2013-07-16 21:23 UTC (permalink / raw)
To: len.brown, pavel, rjw, gregkh, rostedt, fweisbec, mingo, paul.gortmaker
Cc: Shuah Khan, linux-pm, linux-kernel, joe, shuahkhan
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-2356 [000] .... 1512.375576: device_pm_report_time: acpi_video0 driver(backlight) parent(0000:00:02.0) freeze class (0 usecs) err (0)
bash-2356 [000] .... 1512.375582: device_pm_report_time: rfkill3 driver(rfkill) parent(phy0) freeze legacy class (0 usecs) err (0)
bash-2356 [001] .... 1513.046559: device_pm_report_time: 0000:00:00.0 driver(pci) parent(pci0000:00) restore noirq bus (10 usecs) err (0)
bash-2356 [001] .... 1513.046580: device_pm_report_time: 0000:00:02.0 driver(i915) parent(pci0000:00) restore noirq bus (16 usecs) err (0)
Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
---
drivers/base/power/main.c | 27 +++++++++++++++++++--------
include/trace/events/power.h | 35 +++++++++++++++++++++++++++++++++++
2 files changed, 54 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..d8eded6 100644
--- a/include/trace/events/power.h
+++ b/include/trace/events/power.h
@@ -66,6 +66,41 @@ 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(unsigned long long, 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 = (unsigned long long)
+ ktime_to_ns(ops_time) >> 10;
+ __entry->error = error;
+ ),
+
+ TP_printk("%s driver(%s) parent(%s) %s %s (%llu usecs) err(%d)\n",
+ __get_str(device), __get_str(driver), __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
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] power: new trace event to print device suspend and resume time
2013-07-16 21:23 [PATCH] power: new trace event to print device suspend and resume time Shuah Khan
@ 2013-07-16 21:39 ` Joe Perches
2013-07-16 22:04 ` Shuah Khan
0 siblings, 1 reply; 5+ messages in thread
From: Joe Perches @ 2013-07-16 21:39 UTC (permalink / raw)
To: Shuah Khan
Cc: len.brown, pavel, rjw, gregkh, rostedt, fweisbec, mingo,
paul.gortmaker, linux-pm, linux-kernel, shuahkhan
On Tue, 2013-07-16 at 15:23 -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:
> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
[]
> @@ -66,6 +66,41 @@ 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(unsigned long long, ops_time)
s64
> + __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 = (unsigned long long)
> + ktime_to_ns(ops_time) >> 10;
so no need for cast.
> + __entry->error = error;
> + ),
> +
> + TP_printk("%s driver(%s) parent(%s) %s %s (%llu usecs) err(%d)\n",
%lld and no newline
> + __get_str(device), __get_str(driver), __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),
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] power: new trace event to print device suspend and resume time
2013-07-16 21:39 ` Joe Perches
@ 2013-07-16 22:04 ` Shuah Khan
2013-07-16 22:16 ` Joe Perches
0 siblings, 1 reply; 5+ messages in thread
From: Shuah Khan @ 2013-07-16 22:04 UTC (permalink / raw)
To: Joe Perches
Cc: len.brown, pavel, rjw, gregkh, rostedt, fweisbec, mingo,
paul.gortmaker, linux-pm, linux-kernel, shuahkhan, Shuah Khan
On 07/16/2013 03:39 PM, Joe Perches wrote:
> On Tue, 2013-07-16 at 15:23 -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:
>
>> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
> []
>> @@ -66,6 +66,41 @@ 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(unsigned long long, ops_time)
>
> s64
Followed the ktime_t example in include/trace/events/timer.h - thinking
it would be the correct way to cast ktime_t :) I can change it to s64.
>
>> + __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 = (unsigned long long)
>> + ktime_to_ns(ops_time) >> 10;
Followed the ktime_t example in include/trace/events/timer.h - figured
it would be the right one. I can change it.
>
> so no need for cast.
>
>> + __entry->error = error;
>> + ),
>> +
>> + TP_printk("%s driver(%s) parent(%s) %s %s (%llu usecs) err(%d)\n",
>
> %lld and no newline
>
>> + __get_str(device), __get_str(driver), __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),
>
>
>
-- Shuah
Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] power: new trace event to print device suspend and resume time
2013-07-16 22:04 ` Shuah Khan
@ 2013-07-16 22:16 ` Joe Perches
2013-07-16 22:27 ` Shuah Khan
0 siblings, 1 reply; 5+ messages in thread
From: Joe Perches @ 2013-07-16 22:16 UTC (permalink / raw)
To: Shuah Khan
Cc: len.brown, pavel, rjw, gregkh, rostedt, fweisbec, mingo,
paul.gortmaker, linux-pm, linux-kernel, shuahkhan
On Tue, 2013-07-16 at 22:04 +0000, Shuah Khan wrote:
> On 07/16/2013 03:39 PM, Joe Perches wrote:
> > On Tue, 2013-07-16 at 15:23 -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:
> >
> >> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
> > []
> >> @@ -66,6 +66,41 @@ 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(unsigned long long, ops_time)
> >
> > s64
>
> Followed the ktime_t example in include/trace/events/timer.h - thinking
> it would be the correct way to cast ktime_t :) I can change it to s64.
You mean this one below where s64 is used for the
variable type?
I do think the %llu is odd below here and it should be
%lld without the casts.
I prefer the TP_printk style of "foo=val" over "foo(val)"
but there's no requirement for one style over another.
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 166) TP_STRUCT__entry(
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 167) __field( void *, hrtimer )
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 168) __field( void *, function )
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 169) __field( s64, expires )
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 170) __field( s64, softexpires )
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 171) ),
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 172)
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 173) TP_fast_assign(
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 174) __entry->hrtimer = hrtimer;
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 175) __entry->function = hrtimer->function;
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 176) __entry->expires = hrtimer_get_expires(hrtimer).tv64;
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 177) __entry->softexpires = hrtimer_get_softexpires(hrtimer).tv64;
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 178) ),
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 179)
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 180) TP_printk("hrtimer=%p function=%pf expires=%llu softexpires=%llu",
434a83c3f (Ingo Molnar 2009-10-15 11:50:39 +0200 181) __entry->hrtimer, __entry->function,
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 182) (unsigned long long)ktime_to_ns((ktime_t) {
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 183) .tv64 = __entry->expires }),
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 184) (unsigned long long)ktime_to_ns((ktime_t) {
c6a2a1770 (Xiao Guangrong 2009-08-10 10:51:23 +0800 185) .tv64 = __entry->softexpires }))
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] power: new trace event to print device suspend and resume time
2013-07-16 22:16 ` Joe Perches
@ 2013-07-16 22:27 ` Shuah Khan
0 siblings, 0 replies; 5+ messages in thread
From: Shuah Khan @ 2013-07-16 22:27 UTC (permalink / raw)
To: Joe Perches
Cc: len.brown, pavel, rjw, gregkh, rostedt, fweisbec, mingo,
paul.gortmaker, linux-pm, linux-kernel, shuahkhan, Shuah Khan
On 07/16/2013 04:17 PM, Joe Perches wrote:
> On Tue, 2013-07-16 at 22:04 +0000, Shuah Khan wrote:
>> On 07/16/2013 03:39 PM, Joe Perches wrote:
>>> On Tue, 2013-07-16 at 15:23 -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:
>>>
>>>> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
>>> []
>>>> @@ -66,6 +66,41 @@ 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(unsigned long long, ops_time)
>>>
>>> s64
>>
>> Followed the ktime_t example in include/trace/events/timer.h - thinking
>> it would be the correct way to cast ktime_t :) I can change it to s64.
>
> You mean this one below where s64 is used for the
> variable type?
oh yeah it does have s64.
>
> I do think the %llu is odd below here and it should be
> %lld without the casts.
ok.
>
> I prefer the TP_printk style of "foo=val" over "foo(val)"
> but there's no requirement for one style over another.
>
Existing events in power.h use foo=val convention - I will make the
change to be consistent.
thanks for the review.
-- Shuah
Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2013-07-16 22:27 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-07-16 21:23 [PATCH] power: new trace event to print device suspend and resume time Shuah Khan
2013-07-16 21:39 ` Joe Perches
2013-07-16 22:04 ` Shuah Khan
2013-07-16 22:16 ` Joe Perches
2013-07-16 22:27 ` Shuah Khan
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®