| 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
| ||
|
Date: Thu, 18 Jul 2013 20:31:11 +0000
From: Shuah Khan <shuah.kh@...sung.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: "len.brown@...el.com" <len.brown@...el.com>,
"pavel@....cz" <pavel@....cz>, "rjw@...k.pl" <rjw@...k.pl>,
"gregkh@...uxfoundation.org" <gregkh@...uxfoundation.org>,
"fweisbec@...il.com" <fweisbec@...il.com>,
"mingo@...hat.com" <mingo@...hat.com>,
"paul.gortmaker@...driver.com" <paul.gortmaker@...driver.com>,
"joe@...ches.com" <joe@...ches.com>,
"linux-pm@...r.kernel.org" <linux-pm@...r.kernel.org>,
"linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
"shuahkhan@...il.com" <shuahkhan@...il.com>,
Shuah Khan <shuah.kh@...sung.com>
Subject: Re: [PATCH v4] power: new trace event to print device suspend and
resume time
On 07/18/2013 01:49 PM, Steven Rostedt wrote:
> 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.
No worries. I do want to do this right. Since I plan to add a few more
trace-points, it will be worth your while teaching me :) Thanks for this
detailed email.
>
>> 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 enabled, this code will execute several times in suspend and resume
path. So it does make perfect sense to optimize it.
>
>>
>> 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);
> [...]
>
The very first version I started testing was in fact passing in struct
device *dev and do all calculations in the trace-point code itself:
TP_STRUCT__entry(
__string(driver_name, dev_driver_string(dev))
__string(device_name, dev_name(dev))
__string(parent, dev->parent ? dev_name(dev->parent) :
"none")
__string(pm_ops, pm_ops)
__field(unsigned long long, ops_time)
__field(int, event)
__field(int, error)
),
TP_fast_assign(
__assign_str(driver_name, dev_driver_string(dev));
__assign_str(device_name, dev_name(dev));
__assign_str(parent, dev->parent ?
dev_name(dev->parent) : "none");
__assign_str(pm_ops, pm_ops);
What I was missing was the tmp_dev, tmp_info in my TP_fast_assign and
started seeing hangs. Of course, now it all makes sense.
I decided to simplify the logic in trace-point code, and pass in the
strings instead. It does become hard to figure out compilation errors in
this framework.
I am glad you took the time to explain. :) I have this older version
saved and I am going to back to it and get it to work and move all the
work into the TP code.
-- Shuah
Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research
America (Silicon Valley) shuah.kh@...sung.com | (970) 672-0658
--
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