| Message ID | 1374076659-3444-1-git-send-email-shuah.kh@samsung.com (mailing list archive) |
|---|---|
| State | Superseded, archived |
| Headers | show |
On Wed, 2013-07-17 at 09:57 -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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 > > bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 Hi again Shuah. A few things: > diff --git a/include/trace/events/power.h b/include/trace/events/power.h [] > + TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n", As I wrote before, do not end a TP_printk with "\n", All TP_printks are self-contained and are not possible to use a thing like pr_cont so no newline is ever used. Use: TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d", Given the data is in nsecs, why use usecs for the time? I think full resolution would be better. Why are there two spaces after "ops=class"? One would be more normal. -- 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 10:09 AM, Joe Perches wrote: > On Wed, 2013-07-17 at 09:57 -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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 >> >> bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 > Hi Joe, > Hi again Shuah. > > A few things: > >> diff --git a/include/trace/events/power.h b/include/trace/events/power.h > [] >> + TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n", > > As I wrote before, do not end a TP_printk with "\n", > > All TP_printks are self-contained and are not possible > to use a thing like pr_cont so no newline is ever used. > > Use: > > TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d", Sorry. Missed that one. Not intentional, just an oversight. :) I should fix that one. > > Given the data is in nsecs, why use usecs for the time? > I think full resolution would be better. My intent to was to match the time units to the original pm_print_times. Rafael! Do you have any preference as to usecs vs. nsecs? > > Why are there two spaces after "ops=class"? One would be more normal. > > This one is tough. The ops string that gets generated in conditionals in __device_suspend() and device_resume() routines, has an extra space at the end. I am not sure why that was done and the subsequent pr_* that print that string also depend on that extra space at the end. I don't have an easy way to fix it without changing lots of code where this string is generated. Hence, I chose to leave the extra space in. I also didn't want to propagate that assumption that there is an extra space into this new tracepoint. I could truncate the string before I pass it to the new tracepoint routine, however I don't like that idea. One thing I can do is, generate separate patch that fixes the extra space issue. That would address the extra space in all cases. -- 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 Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote: > +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(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 = ktime_to_ns(ops_time) >> 10; You may want to just record the ops_time, and do the conversion in the TP_printk(). This is the fast path, and any calculations done here just increases the overhead of the trace point. -- Steve > + __entry->error = error; > + ), > + > + TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n", > + __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-pm" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, 2013-07-17 at 16:30 +0000, Shuah Khan wrote: > On 07/17/2013 10:09 AM, Joe Perches wrote: > > On Wed, 2013-07-17 at 09:57 -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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 > >> > >> bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 [] > > Given the data is in nsecs, why use usecs for the time? > > I think full resolution would be better. > > My intent to was to match the time units to the original pm_print_times. I don't think that maintaining consistency is useful in a new facility when you lose precision. Also the accuracy is suspect as it's calculated with >>10 rather than an actual divide by 1000. > Rafael! Do you have any preference as to usecs vs. nsecs? > > Why are there two spaces after "ops=class"? One would be more normal. > This one is tough. The ops string that gets generated in conditionals in > __device_suspend() and device_resume() routines, has an extra space at > the end. I am not sure why that was done and the subsequent pr_* that > print that string also depend on that extra space at the end. I don't > have an easy way to fix it without changing lots of code where this > string is generated. I think the easiest way to "fix" it is to change the TP_printk format to: TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d", > Hence, I chose to leave the extra space in. I also > didn't want to propagate that assumption that there is an extra space > into this new tracepoint. It's a big deal, it just seemed untidy. There are a couple of places in drivers/base/power/main.c where info is set to NULL. I didn't look hard to see if any of those are propagated through to this point, but there are uses of 'info ?: ""' for some of the logging messages. That _might_ an issue. It looks like all the other logging message uses of info have "%s%s" so that proper word spacing is done when info is "" or NULL. -- 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 Wed, 2013-07-17 at 09:41 -0700, Joe Perches wrote:
> It's a big deal, it just seemed untidy.
No, it's not true, that's silly.
I dropped a "not" there.
It's _not_ a big deal.
--
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 10:35 AM, Steven Rostedt wrote: > On Wed, 2013-07-17 at 09:57 -0600, Shuah Khan wrote: > >> +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(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 = ktime_to_ns(ops_time) >> 10; > > You may want to just record the ops_time, and do the conversion in the > TP_printk(). This is the fast path, and any calculations done here just > increases the overhead of the trace point. > > -- Steve Thanks for the review and pointing the overhead out. Will fix that. -- Shuah
On 07/17/2013 10:41 AM, Joe Perches wrote: > I think the easiest way to "fix" it is to change > the TP_printk format to: > > TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d", I will just adjust for the space and add a comment. > >> Hence, I chose to leave the extra space in. I also >> didn't want to propagate that assumption that there is an extra space >> into this new tracepoint. > > It's a big deal, it just seemed untidy. > > There are a couple of places in drivers/base/power/main.c > where info is set to NULL. I didn't look hard to see if > any of those are propagated through to this point, but > there are uses of 'info ?: ""' for some of the logging > messages. That _might_ an issue. > > It looks like all the other logging message uses of info > have "%s%s" so that proper word spacing is done when > info is "" or NULL. > Yeah that would be bad. The safe thing might me to add a info null check. Working on v3 that includes Steve's review comment as well. thanks, -- 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 Wednesday, July 17, 2013 09:41:08 AM Joe Perches wrote: > On Wed, 2013-07-17 at 16:30 +0000, Shuah Khan wrote: > > On 07/17/2013 10:09 AM, Joe Perches wrote: > > > On Wed, 2013-07-17 at 09:57 -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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 > > >> > > >> bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 > [] > > > Given the data is in nsecs, why use usecs for the time? > > > I think full resolution would be better. > > > > My intent to was to match the time units to the original pm_print_times. > > I don't think that maintaining consistency is > useful in a new facility when you lose precision. > > Also the accuracy is suspect as it's calculated with > >>10 rather than an actual divide by 1000. It's because that is way faster and we don't need great precision here. > > Rafael! Do you have any preference as to usecs vs. nsecs? The numbers in microseconds are easier to read, but I guess we can just use nanoseconds and then process the output. Thanks, Rafael > > > Why are there two spaces after "ops=class"? One would be more normal. > > > This one is tough. The ops string that gets generated in conditionals in > > __device_suspend() and device_resume() routines, has an extra space at > > the end. I am not sure why that was done and the subsequent pr_* that > > print that string also depend on that extra space at the end. I don't > > have an easy way to fix it without changing lots of code where this > > string is generated. > > I think the easiest way to "fix" it is to change > the TP_printk format to: > > TP_printk("%s %s parent=%s state=%s ops=%susecs=%lld err=%d", > > > Hence, I chose to leave the extra space in. I also > > didn't want to propagate that assumption that there is an extra space > > into this new tracepoint. > > It's a big deal, it just seemed untidy. > > There are a couple of places in drivers/base/power/main.c > where info is set to NULL. I didn't look hard to see if > any of those are propagated through to this point, but > there are uses of 'info ?: ""' for some of the logging > messages. That _might_ an issue. > > It looks like all the other logging message uses of info > have "%s%s" so that proper word spacing is done when > info is "" or NULL. > > >
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..6240541 100644 --- a/include/trace/events/power.h +++ b/include/trace/events/power.h @@ -66,6 +66,40 @@ 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(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 = ktime_to_ns(ops_time) >> 10; + __entry->error = error; + ), + + TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n", + __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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 bash-2484 [001] .... 907.330155: device_pm_report_time: rfkill rfkill3 parent=phy0 state=freeze ops=legacy class usecs=0 err=0 bash-2484 [001] .... 909.906739: device_pm_report_time: rfkill rfkill3 parent=phy0 state=restore ops=legacy class usecs=1 err=0 bash-2484 [000] .... 907.389079: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=freeze ops=legacy class usecs=57497 err=0 bash-2484 [001] .... 909.906731: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=restore ops=legacy class usecs=95119 err=0 Signed-off-by: Shuah Khan <shuah.kh@samsung.com> --- drivers/base/power/main.c | 27 +++++++++++++++++++-------- include/trace/events/power.h | 34 ++++++++++++++++++++++++++++++++++ 2 files changed, 53 insertions(+), 8 deletions(-)