| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <1374176956.6458.265.camel@gandalf.local.home>
Date: Thu, 18 Jul 2013 15:49:16 -0400
From: Steven Rostedt <rostedt@...dmis.org>
To: Shuah Khan <shuah.kh@...sung.com>
Cc: len.brown@...el.com, pavel@....cz, rjw@...k.pl,
gregkh@...uxfoundation.org, fweisbec@...il.com, mingo@...hat.com,
paul.gortmaker@...driver.com, joe@...ches.com,
linux-pm@...r.kernel.org, linux-kernel@...r.kernel.org,
shuahkhan@...il.com
Subject: Re: [PATCH v4] power: new trace event to print device suspend and
resume time
On Thu, 2013-07-18 at 13:22 -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-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
>
I think I'm the thorn in your side.
> Signed-off-by: Shuah Khan <shuah.kh@...sung.com>
> ---
> drivers/base/power/main.c | 33 +++++++++++++++++++++++----------
> include/trace/events/power.h | 35 +++++++++++++++++++++++++++++++++++
> 2 files changed, 58 insertions(+), 10 deletions(-)
>
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 5a9b656..e7401c6 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;
> + ktime_t rettime;
> + s64 nsecs;
> +
> + rettime = ktime_get();
> + nsecs = (s64) ktime_to_ns(ktime_sub(rettime, calltime));
You still are calling this from the fast path. Why not put the
conversion into TP_printk()? Or is this just called once in a while and
you don't really care?
>
> 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_name(dev), dev_driver_string(dev),
> + dev->parent ? dev_name(dev->parent) : "none",
> + info ? info : "none ",
> + nsecs, pm_verb(state.event), error);
I'd like to see this disassembled.
The tracepoints use jump-labels which is basically a code modification
of a branch.
[ code ]
nop
back:
[ code ]
return;
tracepoint:
[ tracepoint code ]
jmp back;
And when we enable the tracepoint, the code is modified to be:
[ code ]
jmp tracepoint
[ code ]
tracepoint:
[ tracepoint code ]
jmp back;
Cool, eh?
But we sometimes have seen gcc getting confused it its optimization, and
process some of the work of the tracepoint parameters in the [ code ]
part, which is bad, because that's just overhead even when the
tracepoint is disabled.
Thus, it's usually better to do as much work in the TRACE_EVENT() macro
as possible. In otherwords:
trace_device_pm_report_time(dev, info, nsecs,
pm_verb(state.event), error);
And in the TP_fast_assign, have:
TP_fast_assign(
char *tmp_dev = dev->parent ? dev_name(dev->parent) : "none";
char *tmp_info = info ? info : "none ";
__assign_str(tmp_dev, parent);
__assign_str(tmp_info, info);
[...]
Of course, that's only if gcc screws this up. And if this is just called
at boot up only a hand full of times, it may not be worth the trouble.
I just happen to be in a micro optimization mood.
-- Steve
> }
>
> /**
> @@ -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),
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists