* [PATCH v2] power: Include additional information in pm_print_times
@ 2013-06-14 20:35 Shuah Khan
2013-06-14 20:40 ` Greg KH
2013-06-14 20:55 ` Joe Perches
0 siblings, 2 replies; 4+ messages in thread
From: Shuah Khan @ 2013-06-14 20:35 UTC (permalink / raw)
To: pavel, rjw, len.brown, gregkh, joe
Cc: Shuah Khan, linux-pm, linux-kernel, shuahkhan
Change __device_suspend() path to include driver name and the ops that
get run for a device. This additional information helps associate the
driver and the type of pm_ops the device uses in the suspend path very
quickly which will aid in debugging problems in suspend and resume paths.
Changed both start and end debug messages to include pm_ops information
and use dev_info() instead of pr_info().
dmesg output before the change:
[ 164.390032] calling 1-1+ @ 69, parent: usb1
[ 164.390035] call 1-1+ returned 0 after 0 usecs
[ 164.390352] calling 00:0a+ @ 2457, parent: pnp0
[ 164.390357] call 00:0a+ returned 0 after 3 usecs
[ 164.390361] calling 00:09+ @ 2457, parent: pnp0
[ 164.496458] call 00:09+ returned 0 after 103500 usecs
[ 164.496494] calling 00:05+ @ 2457, parent: pnp0
[ 164.496511] call 00:05+ returned 0 after 14 usecs
dmesg output after the change:
[ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
[ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
[ 58.702014] system 00:0a: calling legacy bus pm ops @ 2173, parent: pnp0
[ 58.702018] system 00:0a: call legacy bus pm ops returned 0 after 2 usecs
[ 58.702023] tpm_tis 00:09: calling legacy bus pm ops @ 2173, parent: pnp0
[ 58.806909] tpm_tis 00:09: call legacy bus pm ops returned 0 after 102425 usecs
[ 58.806927] rtc_cmos 00:05: calling legacy bus pm ops @ 2173, parent: pnp0
[ 58.806935] rtc_cmos 00:05: call legacy bus pm ops returned 0 after 5 usecs
Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
---
drivers/base/power/main.c | 44 +++++++++++++++++++++++++-------------------
1 file changed, 25 insertions(+), 19 deletions(-)
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 5a9b656..e8d2de7 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -157,13 +157,14 @@ void device_pm_move_last(struct device *dev)
list_move_tail(&dev->power.entry, &dpm_list);
}
-static ktime_t initcall_debug_start(struct device *dev)
+static ktime_t initcall_debug_start(struct device *dev, char *info)
{
ktime_t calltime = ktime_set(0, 0);
if (pm_print_times_enabled) {
- pr_info("calling %s+ @ %i, parent: %s\n",
- dev_name(dev), task_pid_nr(current),
+ /* string in info has an extra space at the end */
+ dev_info(dev, "calling %s@ %i, parent: %s\n",
+ info, task_pid_nr(current),
dev->parent ? dev_name(dev->parent) : "none");
calltime = ktime_get();
}
@@ -172,14 +173,15 @@ static ktime_t initcall_debug_start(struct device *dev)
}
static void initcall_debug_report(struct device *dev, ktime_t calltime,
- int error)
+ int error, char *info)
{
ktime_t delta, rettime;
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),
+ /* string in info has an extra space at the end */
+ dev_info(dev, "call %sreturned %d after %llu usecs\n", info,
error, (unsigned long long)ktime_to_ns(delta) >> 10);
}
}
@@ -373,13 +375,13 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
if (!cb)
return 0;
- calltime = initcall_debug_start(dev);
+ calltime = initcall_debug_start(dev, info);
pm_dev_dbg(dev, state, info);
error = cb(dev);
suspend_report_result(cb, error);
- initcall_debug_report(dev, calltime, error);
+ initcall_debug_report(dev, calltime, error, info);
return error;
}
@@ -1027,17 +1029,19 @@ 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;
- calltime = initcall_debug_start(dev);
+ calltime = initcall_debug_start(dev, info);
+ pm_dev_dbg(dev, state, info);
error = cb(dev, state);
suspend_report_result(cb, error);
- initcall_debug_report(dev, calltime, error);
+ initcall_debug_report(dev, calltime, error, info);
return error;
}
@@ -1079,43 +1083,45 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async)
device_lock(dev);
if (dev->pm_domain) {
- info = "power domain ";
+ info = "power domain pm ops ";
callback = pm_op(&dev->pm_domain->ops, state);
goto Run;
}
if (dev->type && dev->type->pm) {
- info = "type ";
+ info = "type pm ops ";
callback = pm_op(dev->type->pm, state);
goto Run;
}
if (dev->class) {
if (dev->class->pm) {
- info = "class ";
+ info = "class pm ops ";
callback = pm_op(dev->class->pm, state);
goto Run;
} else if (dev->class->suspend) {
- pm_dev_dbg(dev, state, "legacy class ");
- error = legacy_suspend(dev, state, dev->class->suspend);
+ info = "legacy class pm ops ";
+ error = legacy_suspend(dev, state, dev->class->suspend,
+ info);
goto End;
}
}
if (dev->bus) {
if (dev->bus->pm) {
- info = "bus ";
+ info = "bus pm ops ";
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);
+ info = "legacy bus pm ops ";
+ error = legacy_suspend(dev, state, dev->bus->suspend,
+ info);
goto End;
}
}
Run:
if (!callback && dev->driver && dev->driver->pm) {
- info = "driver ";
+ info = "driver pm ops ";
callback = pm_op(dev->driver->pm, state);
}
--
1.7.10.4
^ permalink raw reply related [flat|nested] 4+ messages in thread* Re: [PATCH v2] power: Include additional information in pm_print_times
2013-06-14 20:35 [PATCH v2] power: Include additional information in pm_print_times Shuah Khan
@ 2013-06-14 20:40 ` Greg KH
2013-06-14 20:55 ` Joe Perches
1 sibling, 0 replies; 4+ messages in thread
From: Greg KH @ 2013-06-14 20:40 UTC (permalink / raw)
To: Shuah Khan; +Cc: pavel, rjw, len.brown, joe, linux-pm, linux-kernel, shuahkhan
On Fri, Jun 14, 2013 at 02:35:24PM -0600, Shuah Khan wrote:
> Change __device_suspend() path to include driver name and the ops that
> get run for a device. This additional information helps associate the
> driver and the type of pm_ops the device uses in the suspend path very
> quickly which will aid in debugging problems in suspend and resume paths.
> Changed both start and end debug messages to include pm_ops information
> and use dev_info() instead of pr_info().
>
> dmesg output before the change:
>
> [ 164.390032] calling 1-1+ @ 69, parent: usb1
> [ 164.390035] call 1-1+ returned 0 after 0 usecs
>
> [ 164.390352] calling 00:0a+ @ 2457, parent: pnp0
> [ 164.390357] call 00:0a+ returned 0 after 3 usecs
>
> [ 164.390361] calling 00:09+ @ 2457, parent: pnp0
> [ 164.496458] call 00:09+ returned 0 after 103500 usecs
>
> [ 164.496494] calling 00:05+ @ 2457, parent: pnp0
> [ 164.496511] call 00:05+ returned 0 after 14 usecs
>
> dmesg output after the change:
>
> [ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
> [ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
>
> [ 58.702014] system 00:0a: calling legacy bus pm ops @ 2173, parent: pnp0
> [ 58.702018] system 00:0a: call legacy bus pm ops returned 0 after 2 usecs
>
> [ 58.702023] tpm_tis 00:09: calling legacy bus pm ops @ 2173, parent: pnp0
> [ 58.806909] tpm_tis 00:09: call legacy bus pm ops returned 0 after 102425 usecs
>
> [ 58.806927] rtc_cmos 00:05: calling legacy bus pm ops @ 2173, parent: pnp0
> [ 58.806935] rtc_cmos 00:05: call legacy bus pm ops returned 0 after 5 usecs
>
> Signed-off-by: Shuah Khan <shuah.kh@samsung.com>
> ---
> drivers/base/power/main.c | 44 +++++++++++++++++++++++++-------------------
> 1 file changed, 25 insertions(+), 19 deletions(-)
I'm assuming this will go through Rafael's tree:
Acked-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH v2] power: Include additional information in pm_print_times
2013-06-14 20:35 [PATCH v2] power: Include additional information in pm_print_times Shuah Khan
2013-06-14 20:40 ` Greg KH
@ 2013-06-14 20:55 ` Joe Perches
2013-06-17 15:06 ` Shuah Khan
1 sibling, 1 reply; 4+ messages in thread
From: Joe Perches @ 2013-06-14 20:55 UTC (permalink / raw)
To: Shuah Khan
Cc: pavel, rjw, len.brown, gregkh, linux-pm, linux-kernel, shuahkhan
On Fri, 2013-06-14 at 14:35 -0600, Shuah Khan wrote:
> Change __device_suspend() path to include driver name and the ops that
> get run for a device. This additional information helps associate the
> driver and the type of pm_ops the device uses in the suspend path very
> quickly which will aid in debugging problems in suspend and resume paths.
> Changed both start and end debug messages to include pm_ops information
> and use dev_info() instead of pr_info().
>
> dmesg output before the change:
>
> [ 164.390032] calling 1-1+ @ 69, parent: usb1
> [ 164.390035] call 1-1+ returned 0 after 0 usecs
> dmesg output after the change:
>
> [ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
> [ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
[]
> +static ktime_t initcall_debug_start(struct device *dev, char *info)
[]
> + /* string in info has an extra space at the end */
> + dev_info(dev, "calling %s@ %i, parent: %s\n",
> + info, task_pid_nr(current),
> dev->parent ? dev_name(dev->parent) : "none");
> static void initcall_debug_report(struct device *dev, ktime_t calltime,
[]
> - pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
> + /* string in info has an extra space at the end */
> + dev_info(dev, "call %sreturned %d after %llu usecs\n", info,
> error, (unsigned long long)ktime_to_ns(delta) >> 10);
Perhaps align the "calling and "call" and include
task_pid_nr(current)?
[ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
[ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
so it's:
[ 58.707002] usb usb1: enter 'type pm ops' @ 57, parent: 0000:00:1d.0
[ 58.707641] usb usb1: exit 'type pm ops' @ 57, parent: 0000:00:1d.0, error: 0 (611 usecs)
or:
[ 58.707002] usb usb1: enter 'type pm ops' @ 57, parent: 0000:00:1d.0
[ 58.707641] usb usb1: exit 'type pm ops' @ 57, error: 0 (611 usecs)
^ permalink raw reply [flat|nested] 4+ messages in thread* Re: [PATCH v2] power: Include additional information in pm_print_times
2013-06-14 20:55 ` Joe Perches
@ 2013-06-17 15:06 ` Shuah Khan
0 siblings, 0 replies; 4+ messages in thread
From: Shuah Khan @ 2013-06-17 15:06 UTC (permalink / raw)
To: Joe Perches
Cc: pavel@ucw.cz, rjw@sisk.pl, len.brown@intel.com,
gregkh@linuxfoundation.org, linux-pm@vger.kernel.org,
linux-kernel@vger.kernel.org, shuahkhan@gmail.com, Shuah Khan
On 06/14/2013 02:55 PM, Joe Perches wrote:
> On Fri, 2013-06-14 at 14:35 -0600, Shuah Khan wrote:
>> Change __device_suspend() path to include driver name and the ops that
>> get run for a device. This additional information helps associate the
>> driver and the type of pm_ops the device uses in the suspend path very
>> quickly which will aid in debugging problems in suspend and resume paths.
>> Changed both start and end debug messages to include pm_ops information
>> and use dev_info() instead of pr_info().
>>
>> dmesg output before the change:
>>
>> [ 164.390032] calling 1-1+ @ 69, parent: usb1
>> [ 164.390035] call 1-1+ returned 0 after 0 usecs
>
>> dmesg output after the change:
>>
>> [ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
>> [ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
>
>> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> []
>> +static ktime_t initcall_debug_start(struct device *dev, char *info)
> []
>> + /* string in info has an extra space at the end */
>> + dev_info(dev, "calling %s@ %i, parent: %s\n",
>> + info, task_pid_nr(current),
>> dev->parent ? dev_name(dev->parent) : "none");
>
>> static void initcall_debug_report(struct device *dev, ktime_t calltime,
> []
>> - pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
>> + /* string in info has an extra space at the end */
>> + dev_info(dev, "call %sreturned %d after %llu usecs\n", info,
>> error, (unsigned long long)ktime_to_ns(delta) >> 10);
>
> Perhaps align the "calling and "call" and include
> task_pid_nr(current)?
>
> [ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0
> [ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs
>
> so it's:
>
> [ 58.707002] usb usb1: enter 'type pm ops' @ 57, parent: 0000:00:1d.0
> [ 58.707641] usb usb1: exit 'type pm ops' @ 57, parent: 0000:00:1d.0, error: 0 (611 usecs)
>
> or:
>
> [ 58.707002] usb usb1: enter 'type pm ops' @ 57, parent: 0000:00:1d.0
> [ 58.707641] usb usb1: exit 'type pm ops' @ 57, error: 0 (611 usecs)
>
>
>
Including parent id and task id in the debug_report makes sense to have
a tighter association between start and end messages. Let me re-work it
and send another revision of the patch. I will use Start/end or
Begin/end pairing.
thanks,
-- Shuah
Shuah Khan, Linux Kernel Developer - Open Source Group Samsung Research
America (Silicon Valley) shuah.kh@samsung.com | (970) 672-0658
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2013-06-17 15:06 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-06-14 20:35 [PATCH v2] power: Include additional information in pm_print_times Shuah Khan
2013-06-14 20:40 ` Greg KH
2013-06-14 20:55 ` Joe Perches
2013-06-17 15:06 ` Shuah Khan
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox