| Message ID | 1374102201-2937-1-git-send-email-shuah.kh@samsung.com (mailing list archive) |
|---|---|
| State | Superseded, archived |
| Headers | show |
On Wed, 2013-07-17 at 17:03 -0600, Shuah Khan wrote: > diff --git a/include/trace/events/power.h b/include/trace/events/power.h > index 8e42410..24afd22 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, s64 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 = ops_time; > + __entry->error = error; > + ), > + > + /* ops_str has an extra space at the end */ > + TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", > + __get_str(driver), __get_str(device), __get_str(parent), > + __get_str(pm_event_str), __get_str(pm_ops), > + __entry->ops_time, __entry->error) Don't you want to convert the ops_time on display? You can have: TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", __get_str(driver), __get_str(device), __get_str(parent), __get_str(pm_event_str), __get_str(pm_ops), ktime_to_ns(__entry->ops_time), __entry->error) -- Steve > +); > + > DECLARE_EVENT_CLASS(wakeup_source, > > TP_PROTO(const char *name, unsigned int state), -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On 07/17/2013 07:23 PM, Steven Rostedt wrote: > On Wed, 2013-07-17 at 17:03 -0600, Shuah Khan wrote: > >> diff --git a/include/trace/events/power.h b/include/trace/events/power.h >> index 8e42410..24afd22 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, s64 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 = ops_time; >> + __entry->error = error; >> + ), >> + >> + /* ops_str has an extra space at the end */ >> + TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", >> + __get_str(driver), __get_str(device), __get_str(parent), >> + __get_str(pm_event_str), __get_str(pm_ops), >> + __entry->ops_time, __entry->error) > > > Don't you want to convert the ops_time on display? You can have: > > TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", > __get_str(driver), __get_str(device), __get_str(parent), > __get_str(pm_event_str), __get_str(pm_ops), > ktime_to_ns(__entry->ops_time), __entry->error) > > > -- Steve I decided to pass in the converted value to the tracepoint. Please see the drivers/base/power/main.c call to trace_device_pm_report_time() + + trace_device_pm_report_time(dev_name(dev), dev_driver_string(dev), + dev->parent ? dev_name(dev->parent) : "none", + info ? info : "none ", + (s64) ktime_to_ns(delta), pm_verb(state.event), + error); -- Shuah Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658 -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, 2013-07-18 at 14:00 +0000, Shuah Khan wrote: > > > > Don't you want to convert the ops_time on display? You can have: > > > > TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", > > __get_str(driver), __get_str(device), __get_str(parent), > > __get_str(pm_event_str), __get_str(pm_ops), > > ktime_to_ns(__entry->ops_time), __entry->error) > > > > > > -- Steve > > I decided to pass in the converted value to the tracepoint. Please see > the drivers/base/power/main.c call to trace_device_pm_report_time() But why? You are still doing the calculation in the fast path. The TP_printk() is in the slow path. Why add overhead to the execution of the code? -- Steve > > + > + trace_device_pm_report_time(dev_name(dev), dev_driver_string(dev), > + dev->parent ? dev_name(dev->parent) : "none", > + info ? info : "none ", > + (s64) ktime_to_ns(delta), pm_verb(state.event), > + error); > > -- Shuah > > Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research > America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658 -- To unsubscribe from this list: send the line "unsubscribe linux-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On 07/18/2013 08:21 AM, Steven Rostedt wrote: > On Thu, 2013-07-18 at 14:00 +0000, Shuah Khan wrote: > >>> >>> Don't you want to convert the ops_time on display? You can have: >>> >>> TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", >>> __get_str(driver), __get_str(device), __get_str(parent), >>> __get_str(pm_event_str), __get_str(pm_ops), >>> ktime_to_ns(__entry->ops_time), __entry->error) >>> >>> >>> -- Steve >> >> I decided to pass in the converted value to the tracepoint. Please see >> the drivers/base/power/main.c call to trace_device_pm_report_time() > > But why? You are still doing the calculation in the fast path. The > TP_printk() is in the slow path. Why add overhead to the execution of > the code? > > -- Steve Yes. You are right. I want to avoid passing in ktime_t, I can still do that without doing the conversion in fast path. I could pass in tv64 value and do the conversion in TP_printk. Hopefully I will get this right this time. This is my first tracepoint. Thanks for your patience. -- Shuah
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..63c58d7 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,23 @@ 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 ? info : "none ", + (s64) ktime_to_ns(delta), pm_verb(state.event), + error); } /** @@ -379,7 +389,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 +1037,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 +1048,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 +1108,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 +1120,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..24afd22 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, s64 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 = ops_time; + __entry->error = error; + ), + + /* ops_str has an extra space at the end */ + TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", + __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),
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-2239 [000] .... 290.883035: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class nsecs=332 err=0 bash-2239 [000] .... 290.883041: device_pm_report_time: rfkill rf kill3 parent=phy0 state=freeze ops=legacy class nsecs=216 err=0 bash-2239 [001] .... 290.973892: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=freeze ops=legacy class nsecs=90846477 err=0 bash-2239 [001] .... 293.660129: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=restore ops=legacy class nsecs=101295162 err=0 bash-2239 [001] .... 293.660147: device_pm_report_time: rfkill rfkill3 parent=phy0 state=restore ops=legacy class nsecs=1804 err=0 bash-2239 [001] .... 293.660157: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class nsecs=757 err=0 Signed-off-by: Shuah Khan <shuah.kh@samsung.com> --- drivers/base/power/main.c | 29 +++++++++++++++++++++-------- include/trace/events/power.h | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+), 8 deletions(-)