From 3831261eb08557a1390b29c1038a0217232d8fdb Mon Sep 17 00:00:00 2001 From: "Brandt, Todd E" Date: Thu, 11 Jul 2013 07:44:35 +0000 Subject: PM / Sleep: increase ftrace coverage in suspend/resume Change where ftrace is disabled and re-enabled during system suspend/resume to allow tracing of device driver pm callbacks. Ftrace will now be turned off when suspend reaches disable_nonboot_cpus() instead of at the very beginning of system suspend. Ftrace was disabled during suspend/resume back in 2008 by Steven Rostedt as he discovered there was a conflict in the enable_nonboot_cpus() call (see commit f42ac38 "ftrace: disable tracing for suspend to ram"). This change preserves his fix by disabling ftrace, but only at the function where it is known to cause problems. The new change allows tracing of the device level code for better debug. [rjw: Changelog] Signed-off-by: Todd Brandt Signed-off-by: Rafael J. Wysocki --- kernel/power/suspend.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c index ece0422..62ee437 100644 --- a/kernel/power/suspend.c +++ b/kernel/power/suspend.c @@ -210,6 +210,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup) goto Platform_wake; } + ftrace_stop(); error = disable_nonboot_cpus(); if (error || suspend_test(TEST_CPUS)) goto Enable_cpus; @@ -232,6 +233,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup) Enable_cpus: enable_nonboot_cpus(); + ftrace_start(); Platform_wake: if (need_suspend_ops(state) && suspend_ops->wake) @@ -265,7 +267,6 @@ int suspend_devices_and_enter(suspend_state_t state) goto Close; } suspend_console(); - ftrace_stop(); suspend_test_start(); error = dpm_suspend_start(PMSG_SUSPEND); if (error) { @@ -285,7 +286,6 @@ int suspend_devices_and_enter(suspend_state_t state) suspend_test_start(); dpm_resume_end(PMSG_RESUME); suspend_test_finish("resume devices"); - ftrace_start(); resume_console(); Close: if (need_suspend_ops(state) && suspend_ops->end) -- cgit v1.1 From 536446772f1181f3afdf332780b5325d1b6980c6 Mon Sep 17 00:00:00 2001 From: Shuah Khan Date: Fri, 26 Jul 2013 13:30:20 -0600 Subject: PM / Sleep: new trace event to print device suspend and resume times A new trace event is added to PM events to print the time it takes to suspend and resume a device. It generates trace messages that include 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 Signed-off-by: Rafael J. Wysocki --- drivers/base/power/main.c | 77 +++++++++++++++++++++++++------------------- include/trace/events/power.h | 37 +++++++++++++++++++++ 2 files changed, 80 insertions(+), 34 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..9f098a8 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -28,6 +28,7 @@ #include #include #include +#include #include #include "../base.h" #include "power.h" @@ -56,6 +57,30 @@ static pm_message_t pm_transition; static int async_error; +static char *pm_verb(int event) +{ + switch (event) { + case PM_EVENT_SUSPEND: + return "suspend"; + case PM_EVENT_RESUME: + return "resume"; + case PM_EVENT_FREEZE: + return "freeze"; + case PM_EVENT_QUIESCE: + return "quiesce"; + case PM_EVENT_HIBERNATE: + return "hibernate"; + case PM_EVENT_THAW: + return "thaw"; + case PM_EVENT_RESTORE: + return "restore"; + case PM_EVENT_RECOVER: + return "recover"; + default: + return "(unknown PM event)"; + } +} + /** * device_pm_sleep_init - Initialize system suspend-related device fields. * @dev: Device object being initialized. @@ -172,16 +197,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; + ktime_t rettime; + s64 nsecs; + + rettime = ktime_get(); + nsecs = (s64) ktime_to_ns(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); + error, (unsigned long long)nsecs >> 10); } + + trace_device_pm_report_time(dev, info, nsecs, pm_verb(state.event), + error); } /** @@ -309,30 +339,6 @@ static pm_callback_t pm_noirq_op(const struct dev_pm_ops *ops, pm_message_t stat return NULL; } -static char *pm_verb(int event) -{ - switch (event) { - case PM_EVENT_SUSPEND: - return "suspend"; - case PM_EVENT_RESUME: - return "resume"; - case PM_EVENT_FREEZE: - return "freeze"; - case PM_EVENT_QUIESCE: - return "quiesce"; - case PM_EVENT_HIBERNATE: - return "hibernate"; - case PM_EVENT_THAW: - return "thaw"; - case PM_EVENT_RESTORE: - return "restore"; - case PM_EVENT_RECOVER: - return "recover"; - default: - return "(unknown PM event)"; - } -} - static void pm_dev_dbg(struct device *dev, pm_message_t state, char *info) { dev_dbg(dev, "%s%s%s\n", info, pm_verb(state.event), @@ -379,7 +385,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 +1033,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 +1044,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 +1104,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 +1116,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..cda100d 100644 --- a/include/trace/events/power.h +++ b/include/trace/events/power.h @@ -66,6 +66,43 @@ TRACE_EVENT(machine_suspend, TP_printk("state=%lu", (unsigned long)__entry->state) ); +TRACE_EVENT(device_pm_report_time, + + TP_PROTO(struct device *dev, const char *pm_ops, s64 ops_time, + char *pm_event_str, int error), + + TP_ARGS(dev, pm_ops, ops_time, pm_event_str, error), + + TP_STRUCT__entry( + __string(device, dev_name(dev)) + __string(driver, dev_driver_string(dev)) + __string(parent, dev->parent ? dev_name(dev->parent) : "none") + __string(pm_ops, pm_ops ? pm_ops : "none ") + __string(pm_event_str, pm_event_str) + __field(s64, ops_time) + __field(int, error) + ), + + TP_fast_assign( + const char *tmp = dev->parent ? dev_name(dev->parent) : "none"; + const char *tmp_i = pm_ops ? pm_ops : "none "; + + __assign_str(device, dev_name(dev)); + __assign_str(driver, dev_driver_string(dev)); + __assign_str(parent, tmp); + __assign_str(pm_ops, tmp_i); + __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), -- cgit v1.1