LinuxLists.cc - [PATCH] power, trace: add tracing for device

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 11:27:23AM -0700, Sameer Nanda wrote:
> Added event tracing for device_resume. This helps quickly pinpoint which
> devices take a long time to resume.
>
> Signed-off-by: Sameer Nanda <[email protected]>
> ---
> Documentation/trace/events-power.txt | 20 +++++++++++
> drivers/base/power/main.c | 10 ++++++
> include/trace/events/power.h | 59 ++++++++++++++++++++++++++++++++++
> 3 files changed, 89 insertions(+), 0 deletions(-)
>
> diff --git a/Documentation/trace/events-power.txt b/Documentation/trace/events-power.txt
> index cf794af..dbfb7f0 100644
> --- a/Documentation/trace/events-power.txt
> +++ b/Documentation/trace/events-power.txt
> @@ -88,3 +88,23 @@ power_domain_target "%s state=%lu cpu_id=%lu"
> The first parameter gives the power domain name (e.g. "mpu_pwrdm").
> The second parameter is the power domain target state.
>
> +4. Device resume events
> +=======================
> +The device resume events are used for measuring the time taken to resume
> +devices.
> +
> +device_resume_in "device=%s driver=%s"
> +device_resume_waited "device=%s driver=%s time_delta=%lld"
> +device_resume_out "device=%s driver=%s time_delta=%lld"
> +
> +The first parameter is the device that is being resumed.
> +
> +The second parameter is the driver associated with the device being resumed.
> +
> +The third parameter in device_resume_waited is the time delta from the entry
> +point of device_resume to the wait completion of parent device being resumed.
> +The unit for time_delta is us.
> +
> +The third parameter in device_resume_out is the time delta from the wait
> +completion of parent device being resumed to device_resume being completed.
> +The unit for time_delta is us.
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index b462c0e..3ed01cd 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 "../base.h"
> #include "power.h"
> @@ -565,11 +566,19 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
> char *info = NULL;
> int error = 0;
> bool put = false;
> + s64 in_time = ktime_to_us(ktime_get());
> + s64 wait_done_time;
> +
> + trace_device_resume_in(dev);
>
> TRACE_DEVICE(dev);
> TRACE_RESUME(0);

Don't these TRACE_DEVICE() and TRACE_RESUME() calls already provide you
the same information you are wanting to determine above if you look at
the timestamps of the events? Can you not do time processing in
userspace?

confused,

greg k-h

2012-05-18 18:58:23

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 11:37 AM, Greg KH <[email protected]> wrote:
> On Fri, May 18, 2012 at 11:27:23AM -0700, Sameer Nanda wrote:
>> Added event tracing for device_resume. This helps quickly pinpoint which
>> devices take a long time to resume.
>>
>> Signed-off-by: Sameer Nanda <[email protected]>
>> ---
>> Documentation/trace/events-power.txt | 20 +++++++++++
>> drivers/base/power/main.c | 10 ++++++
>> include/trace/events/power.h | 59 ++++++++++++++++++++++++++++++++++
>> 3 files changed, 89 insertions(+), 0 deletions(-)
>>
>> diff --git a/Documentation/trace/events-power.txt b/Documentation/trace/events-power.txt
>> index cf794af..dbfb7f0 100644
>> --- a/Documentation/trace/events-power.txt
>> +++ b/Documentation/trace/events-power.txt
>> @@ -88,3 +88,23 @@ power_domain_target "%s state=%lu cpu_id=%lu"
>> The first parameter gives the power domain name (e.g. "mpu_pwrdm").
>> The second parameter is the power domain target state.
>>
>> +4. Device resume events
>> +=======================
>> +The device resume events are used for measuring the time taken to resume
>> +devices.
>> +
>> +device_resume_in "device=%s driver=%s"
>> +device_resume_waited "device=%s driver=%s time_delta=%lld"
>> +device_resume_out "device=%s driver=%s time_delta=%lld"
>> +
>> +The first parameter is the device that is being resumed.
>> +
>> +The second parameter is the driver associated with the device being resumed.
>> +
>> +The third parameter in device_resume_waited is the time delta from the entry
>> +point of device_resume to the wait completion of parent device being resumed.
>> +The unit for time_delta is us.
>> +
>> +The third parameter in device_resume_out is the time delta from the wait
>> +completion of parent device being resumed to device_resume being completed.
>> +The unit for time_delta is us.
>> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
>> index b462c0e..3ed01cd 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 "../base.h"
>> #include "power.h"
>> @@ -565,11 +566,19 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
>> char *info = NULL;
>> int error = 0;
>> bool put = false;
>> + s64 in_time = ktime_to_us(ktime_get());
>> + s64 wait_done_time;
>> +
>> + trace_device_resume_in(dev);
>>
>> TRACE_DEVICE(dev);
>> TRACE_RESUME(0);
>
> Don't these TRACE_DEVICE() and TRACE_RESUME() calls already provide you
> the same information you are wanting to determine above if you look at
> the timestamps of the events?

AFAICT, they are used for something completely different -- help solve
suspend/resume issues by saving a hash in the RTC of the last device
that suspended/resumed. They don't use the perf tracing mechanism at
all.

> Can you not do time processing in
> userspace?

Did you mean by using the TRACE_DEVICE/TRACE_RESUME functionality or
something else?

>
> confused,
>
> greg k-h

--
Sameer

2012-05-18 19:14:58

by Steven Rostedt

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:

> AFAICT, they are used for something completely different -- help solve
> suspend/resume issues by saving a hash in the RTC of the last device
> that suspended/resumed. They don't use the perf tracing mechanism at
> all.
>

Also note that all tracepoints have timestamps attached to them. You do
not need to add deltas. Do that in the userspace tools that read the
timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
three DEFINE_EVENTs. This will save space.

-- Steve

2012-05-18 20:58:35

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
>
>> AFAICT, they are used for something completely different -- help solve
>> suspend/resume issues by saving a hash in the RTC of the last device
>> that suspended/resumed. They don't use the perf tracing mechanism at
>> all.
>>
>
> Also note that all tracepoints have timestamps attached to them. You do
> not need to add deltas. Do that in the userspace tools that read the
> timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> three DEFINE_EVENTs. This will save space.

Agreed on the space savings. However, with the time_delta in the
trace message itself, a one line shell script [1] that sorts on the
time_delta field is sufficient to quickly spot the devices that take a
long time to resume. Without the time_delta field, the user tool is
more complex since it needs to first match up the device_resume_in,
device_resume_waited and device_resume_out traces and then calculate
time deltas.

Seems like a worthwhile trade-off to me but I can take out the
time_delta if the general consensus is otherwise.

[1]: here's an example script I use for sorting the device resume times:
cat /sys/kernel/debug/tracing/trace | grep device_resume_out | awk
'BEGIN { FS = "time_delta=" } ; { print $2 $0 }' | sort -n

>
> -- Steve
>
>

--
Sameer

2012-05-18 21:19:12

by Steven Rostedt

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> >
> >> AFAICT, they are used for something completely different -- help solve
> >> suspend/resume issues by saving a hash in the RTC of the last device
> >> that suspended/resumed. They don't use the perf tracing mechanism at
> >> all.
> >>
> >
> > Also note that all tracepoints have timestamps attached to them. You do
> > not need to add deltas. Do that in the userspace tools that read the
> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> > three DEFINE_EVENTs. This will save space.
>
> Agreed on the space savings. However, with the time_delta in the
> trace message itself, a one line shell script [1] that sorts on the
> time_delta field is sufficient to quickly spot the devices that take a
> long time to resume. Without the time_delta field, the user tool is
> more complex since it needs to first match up the device_resume_in,
> device_resume_waited and device_resume_out traces and then calculate
> time deltas.
>
> Seems like a worthwhile trade-off to me but I can take out the
> time_delta if the general consensus is otherwise.

Just note that every TRACE_EVENT() adds around 5k or more code. Every
DEFINE_EVENT adds just about 300 bytes.

> [1]: here's an example script I use for sorting the device resume times:
> cat /sys/kernel/debug/tracing/trace | grep device_resume_out | awk
> 'BEGIN { FS = "time_delta=" } ; { print $2 $0 }' | sort -n
>

Question is, how often is this done? And that 5k is permanent for all
users.

-- Steve

2012-05-18 21:23:01

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Friday, May 18, 2012, Sameer Nanda wrote:
> Added event tracing for device_resume. This helps quickly pinpoint which
> devices take a long time to resume.

There is some code already for that in the PM core. You have to boot the
kernel with initcall_debug in the command line to activate it.

Thanks,
Rafael

> Signed-off-by: Sameer Nanda <[email protected]>
> ---
> Documentation/trace/events-power.txt | 20 +++++++++++
> drivers/base/power/main.c | 10 ++++++
> include/trace/events/power.h | 59 ++++++++++++++++++++++++++++++++++
> 3 files changed, 89 insertions(+), 0 deletions(-)
>
> diff --git a/Documentation/trace/events-power.txt b/Documentation/trace/events-power.txt
> index cf794af..dbfb7f0 100644
> --- a/Documentation/trace/events-power.txt
> +++ b/Documentation/trace/events-power.txt
> @@ -88,3 +88,23 @@ power_domain_target "%s state=%lu cpu_id=%lu"
> The first parameter gives the power domain name (e.g. "mpu_pwrdm").
> The second parameter is the power domain target state.
>
> +4. Device resume events
> +=======================
> +The device resume events are used for measuring the time taken to resume
> +devices.
> +
> +device_resume_in "device=%s driver=%s"
> +device_resume_waited "device=%s driver=%s time_delta=%lld"
> +device_resume_out "device=%s driver=%s time_delta=%lld"
> +
> +The first parameter is the device that is being resumed.
> +
> +The second parameter is the driver associated with the device being resumed.
> +
> +The third parameter in device_resume_waited is the time delta from the entry
> +point of device_resume to the wait completion of parent device being resumed.
> +The unit for time_delta is us.
> +
> +The third parameter in device_resume_out is the time delta from the wait
> +completion of parent device being resumed to device_resume being completed.
> +The unit for time_delta is us.
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index b462c0e..3ed01cd 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 "../base.h"
> #include "power.h"
> @@ -565,11 +566,19 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
> char *info = NULL;
> int error = 0;
> bool put = false;
> + s64 in_time = ktime_to_us(ktime_get());
> + s64 wait_done_time;
> +
> + trace_device_resume_in(dev);
>
> TRACE_DEVICE(dev);
> TRACE_RESUME(0);
>
> dpm_wait(dev->parent, async);
> +
> + wait_done_time = ktime_to_us(ktime_get());
> + trace_device_resume_waited(dev, wait_done_time - in_time);
> +
> device_lock(dev);
>
> /*
> @@ -638,6 +647,7 @@ static int device_resume(struct device *dev, pm_message_t state, bool async)
> if (put)
> pm_runtime_put_sync(dev);
>
> + trace_device_resume_out(dev, ktime_to_us(ktime_get()) - wait_done_time);
> return error;
> }
>
> diff --git a/include/trace/events/power.h b/include/trace/events/power.h
> index cae9a94..9601419 100644
> --- a/include/trace/events/power.h
> +++ b/include/trace/events/power.h
> @@ -4,6 +4,7 @@
> #if !defined(_TRACE_POWER_H) || defined(TRACE_HEADER_MULTI_READ)
> #define _TRACE_POWER_H
>
> +#include <linux/device.h>
> #include <linux/ktime.h>
> #include <linux/tracepoint.h>
>
> @@ -48,6 +49,64 @@ DEFINE_EVENT(cpu, cpu_frequency,
> TP_ARGS(frequency, cpu_id)
> );
>
> +#define get_driver_name(dev) dev->driver && dev->driver->name ? \
> + dev->driver->name : ""
> +
> +TRACE_EVENT(device_resume_in,
> +
> + TP_PROTO(struct device *dev),
> +
> + TP_ARGS(dev),
> +
> + TP_STRUCT__entry(
> + __string( device_name, dev_name(dev) )
> + __string( driver_name, get_driver_name(dev) )
> + ),
> +
> + TP_fast_assign(
> + __assign_str(device_name, dev_name(dev));
> + __assign_str(driver_name, get_driver_name(dev));
> + ),
> +
> + TP_printk("device=%s driver=%s", __get_str(device_name), __get_str(driver_name))
> +);
> +
> +DECLARE_EVENT_CLASS(device_resume_internal,
> +
> + TP_PROTO(struct device *dev, s64 time_delta),
> +
> + TP_ARGS(dev, time_delta),
> +
> + TP_STRUCT__entry(
> + __field( s64, time_delta )
> + __string( device_name, dev_name(dev) )
> + __string( driver_name, get_driver_name(dev) )
> + ),
> +
> + TP_fast_assign(
> + __entry->time_delta = time_delta;
> + __assign_str(device_name, dev_name(dev));
> + __assign_str(driver_name, get_driver_name(dev));
> + ),
> +
> + TP_printk("device=%s driver=%s time_delta=%lld", __get_str(device_name),
> + __get_str(driver_name), __entry->time_delta)
> +);
> +
> +DEFINE_EVENT(device_resume_internal, device_resume_waited,
> +
> + TP_PROTO(struct device *dev, s64 time_delta),
> +
> + TP_ARGS(dev, time_delta)
> +);
> +
> +DEFINE_EVENT(device_resume_internal, device_resume_out,
> +
> + TP_PROTO(struct device *dev, s64 time_delta),
> +
> + TP_ARGS(dev, time_delta)
> +);
> +
> TRACE_EVENT(machine_suspend,
>
> TP_PROTO(unsigned int state),
>

2012-05-18 21:39:26

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
>> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
>> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
>> >
>> >> AFAICT, they are used for something completely different -- help solve
>> >> suspend/resume issues by saving a hash in the RTC of the last device
>> >> that suspended/resumed. They don't use the perf tracing mechanism at
>> >> all.
>> >>
>> >
>> > Also note that all tracepoints have timestamps attached to them. You do
>> > not need to add deltas. Do that in the userspace tools that read the
>> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
>> > three DEFINE_EVENTs. This will save space.
>>
>> Agreed on the space savings. However, with the time_delta in the
>> trace message itself, a one line shell script [1] that sorts on the
>> time_delta field is sufficient to quickly spot the devices that take a
>> long time to resume. Without the time_delta field, the user tool is
>> more complex since it needs to first match up the device_resume_in,
>> device_resume_waited and device_resume_out traces and then calculate
>> time deltas.
>>
>> Seems like a worthwhile trade-off to me but I can take out the
>> time_delta if the general consensus is otherwise.
>
> Just note that every TRACE_EVENT() adds around 5k or more code. Every
> DEFINE_EVENT adds just about 300 bytes.

Ok, let me respin the patch. I am thinking of adding time_delta to
all three traces. That way we should get the space saving while still
allowing quick spotting of devices that take long time to resume.

>
>> [1]: here's an example script I use for sorting the device resume times:
>> cat /sys/kernel/debug/tracing/trace | grep device_resume_out | awk
>> 'BEGIN { FS = "time_delta=" } ; { print $2 $0 }' | sort -n
>>
>
> Question is, how often is this done? And that 5k is permanent for all
> users.
>
> -- Steve
>
>

--
Sameer

2012-05-18 21:41:10

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Friday, May 18, 2012, Sameer Nanda wrote:
> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> >> >
> >> >> AFAICT, they are used for something completely different -- help solve
> >> >> suspend/resume issues by saving a hash in the RTC of the last device
> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
> >> >> all.
> >> >>
> >> >
> >> > Also note that all tracepoints have timestamps attached to them. You do
> >> > not need to add deltas. Do that in the userspace tools that read the
> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> >> > three DEFINE_EVENTs. This will save space.
> >>
> >> Agreed on the space savings. However, with the time_delta in the
> >> trace message itself, a one line shell script [1] that sorts on the
> >> time_delta field is sufficient to quickly spot the devices that take a
> >> long time to resume. Without the time_delta field, the user tool is
> >> more complex since it needs to first match up the device_resume_in,
> >> device_resume_waited and device_resume_out traces and then calculate
> >> time deltas.
> >>
> >> Seems like a worthwhile trade-off to me but I can take out the
> >> time_delta if the general consensus is otherwise.
> >
> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
> > DEFINE_EVENT adds just about 300 bytes.
>
> Ok, let me respin the patch. I am thinking of adding time_delta to
> all three traces. That way we should get the space saving while still
> allowing quick spotting of devices that take long time to resume.

Well, what's wrong with the code in drivers/base/power/main.c that
is activated by adding initcall_debug to the kernel command line?

Rafael

2012-05-18 22:17:56

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
> On Friday, May 18, 2012, Sameer Nanda wrote:
>> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
>> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
>> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
>> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
>> >> >
>> >> >> AFAICT, they are used for something completely different -- help solve
>> >> >> suspend/resume issues by saving a hash in the RTC of the last device
>> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
>> >> >> all.
>> >> >>
>> >> >
>> >> > Also note that all tracepoints have timestamps attached to them. You do
>> >> > not need to add deltas. Do that in the userspace tools that read the
>> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
>> >> > three DEFINE_EVENTs. This will save space.
>> >>
>> >> Agreed on the space savings. However, with the time_delta in the
>> >> trace message itself, a one line shell script [1] that sorts on the
>> >> time_delta field is sufficient to quickly spot the devices that take a
>> >> long time to resume. Without the time_delta field, the user tool is
>> >> more complex since it needs to first match up the device_resume_in,
>> >> device_resume_waited and device_resume_out traces and then calculate
>> >> time deltas.
>> >>
>> >> Seems like a worthwhile trade-off to me but I can take out the
>> >> time_delta if the general consensus is otherwise.
>> >
>> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
>> > DEFINE_EVENT adds just about 300 bytes.
>>
>> Ok, let me respin the patch. I am thinking of adding time_delta to
>> all three traces. That way we should get the space saving while still
>> allowing quick spotting of devices that take long time to resume.
>
> Well, what's wrong with the code in drivers/base/power/main.c that
> is activated by adding initcall_debug to the kernel command line?

Mostly that I hadn't looked closely at initcall_debug before writing my patch :)

Now that I have taken a look at it, the main issue is that the kernel
command line needs to be modified to activate it. We cannot do this
for our automated regression suites since the kernel command line is
protected on Chrome OS systems.

Does it make sense to merge these tracepoints with initcall_debug
then? The initcall_debug prints will still be conditional on the
kernel command line flag but the tracepoints wouldn't be.

Another possibility is to convert initcall_debug to use tracepoints
instead of printks. But I am not sure if this would break any
existing tools that depend on initcall_debug on resume path?

>
> Rafael

--
Sameer

2012-05-18 23:01:26

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
> > On Friday, May 18, 2012, Sameer Nanda wrote:
> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> >> >> >
> >> >> >> AFAICT, they are used for something completely different -- help solve
> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
> >> >> >> that suspended/resumed. ?They don't use the perf tracing mechanism at
> >> >> >> all.
> >> >> >>
> >> >> >
> >> >> > Also note that all tracepoints have timestamps attached to them. You do
> >> >> > not need to add deltas. Do that in the userspace tools that read the
> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> >> >> > three DEFINE_EVENTs. This will save space.
> >> >>
> >> >> Agreed on the space savings. ?However, with the time_delta in the
> >> >> trace message itself, a one line shell script [1] that sorts on the
> >> >> time_delta field is sufficient to quickly spot the devices that take a
> >> >> long time to resume. ?Without the time_delta field, the user tool is
> >> >> more complex since it needs to first match up the device_resume_in,
> >> >> device_resume_waited and device_resume_out traces and then calculate
> >> >> time deltas.
> >> >>
> >> >> Seems like a worthwhile trade-off to me but I can take out the
> >> >> time_delta if the general consensus is otherwise.
> >> >
> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
> >> > DEFINE_EVENT adds just about 300 bytes.
> >>
> >> Ok, let me respin the patch. ?I am thinking of adding time_delta to
> >> all three traces. ?That way we should get the space saving while still
> >> allowing quick spotting of devices that take long time to resume.
> >
> > Well, what's wrong with the code in drivers/base/power/main.c that
> > is activated by adding initcall_debug to the kernel command line?
>
> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
>
> Now that I have taken a look at it, the main issue is that the kernel
> command line needs to be modified to activate it. We cannot do this
> for our automated regression suites since the kernel command line is
> protected on Chrome OS systems.

You are kidding, right? You have control over your test systems, don't
bloat everyone's kernel by 5k just because your infrastructure is
somehow something that you feel you can't change.

> Does it make sense to merge these tracepoints with initcall_debug
> then? The initcall_debug prints will still be conditional on the
> kernel command line flag but the tracepoints wouldn't be.
>
> Another possibility is to convert initcall_debug to use tracepoints
> instead of printks. But I am not sure if this would break any
> existing tools that depend on initcall_debug on resume path?

We have tools that use the existing printks, don't change them.

greg k-h

2012-05-18 23:16:15

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, May 18, 2012 at 4:01 PM, Greg KH <[email protected]> wrote:
> On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
>> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
>> > On Friday, May 18, 2012, Sameer Nanda wrote:
>> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
>> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
>> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
>> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
>> >> >> >
>> >> >> >> AFAICT, they are used for something completely different -- help solve
>> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
>> >> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
>> >> >> >> all.
>> >> >> >>
>> >> >> >
>> >> >> > Also note that all tracepoints have timestamps attached to them. You do
>> >> >> > not need to add deltas. Do that in the userspace tools that read the
>> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
>> >> >> > three DEFINE_EVENTs. This will save space.
>> >> >>
>> >> >> Agreed on the space savings. However, with the time_delta in the
>> >> >> trace message itself, a one line shell script [1] that sorts on the
>> >> >> time_delta field is sufficient to quickly spot the devices that take a
>> >> >> long time to resume. Without the time_delta field, the user tool is
>> >> >> more complex since it needs to first match up the device_resume_in,
>> >> >> device_resume_waited and device_resume_out traces and then calculate
>> >> >> time deltas.
>> >> >>
>> >> >> Seems like a worthwhile trade-off to me but I can take out the
>> >> >> time_delta if the general consensus is otherwise.
>> >> >
>> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
>> >> > DEFINE_EVENT adds just about 300 bytes.
>> >>
>> >> Ok, let me respin the patch. I am thinking of adding time_delta to
>> >> all three traces. That way we should get the space saving while still
>> >> allowing quick spotting of devices that take long time to resume.
>> >
>> > Well, what's wrong with the code in drivers/base/power/main.c that
>> > is activated by adding initcall_debug to the kernel command line?
>>
>> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
>>
>> Now that I have taken a look at it, the main issue is that the kernel
>> command line needs to be modified to activate it. We cannot do this
>> for our automated regression suites since the kernel command line is
>> protected on Chrome OS systems.
>
> You are kidding, right? You have control over your test systems, don't
> bloat everyone's kernel by 5k just because your infrastructure is
> somehow something that you feel you can't change.

Fair enough. But having to modify the kernel command line to do this
is clunky. How about exposing the ability to turn on these
initcall_debug prints through a knob under /sys/power?

>
>> Does it make sense to merge these tracepoints with initcall_debug
>> then? The initcall_debug prints will still be conditional on the
>> kernel command line flag but the tracepoints wouldn't be.
>>
>> Another possibility is to convert initcall_debug to use tracepoints
>> instead of printks. But I am not sure if this would break any
>> existing tools that depend on initcall_debug on resume path?
>
> We have tools that use the existing printks, don't change them.
>
> greg k-h

--
Sameer

2012-05-19 00:24:36

by Steven Rostedt

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Fri, 2012-05-18 at 16:01 -0700, Greg KH wrote:
> You are kidding, right? You have control over your test systems, don't
> bloat everyone's kernel by 5k just because your infrastructure is
> somehow something that you feel you can't change.
>

It has been a while since I've done the trace point bloat check. I
should do it again to see where it stands. It may be less than 5k today,
but then again, it may be more.

-- Steve

2012-05-19 11:54:25

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Saturday, May 19, 2012, Sameer Nanda wrote:
> On Fri, May 18, 2012 at 4:01 PM, Greg KH <[email protected]> wrote:
> > On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
> >> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
> >> > On Friday, May 18, 2012, Sameer Nanda wrote:
> >> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> >> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> >> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> >> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> >> >> >> >
> >> >> >> >> AFAICT, they are used for something completely different -- help solve
> >> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
> >> >> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
> >> >> >> >> all.
> >> >> >> >>
> >> >> >> >
> >> >> >> > Also note that all tracepoints have timestamps attached to them. You do
> >> >> >> > not need to add deltas. Do that in the userspace tools that read the
> >> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> >> >> >> > three DEFINE_EVENTs. This will save space.
> >> >> >>
> >> >> >> Agreed on the space savings. However, with the time_delta in the
> >> >> >> trace message itself, a one line shell script [1] that sorts on the
> >> >> >> time_delta field is sufficient to quickly spot the devices that take a
> >> >> >> long time to resume. Without the time_delta field, the user tool is
> >> >> >> more complex since it needs to first match up the device_resume_in,
> >> >> >> device_resume_waited and device_resume_out traces and then calculate
> >> >> >> time deltas.
> >> >> >>
> >> >> >> Seems like a worthwhile trade-off to me but I can take out the
> >> >> >> time_delta if the general consensus is otherwise.
> >> >> >
> >> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
> >> >> > DEFINE_EVENT adds just about 300 bytes.
> >> >>
> >> >> Ok, let me respin the patch. I am thinking of adding time_delta to
> >> >> all three traces. That way we should get the space saving while still
> >> >> allowing quick spotting of devices that take long time to resume.
> >> >
> >> > Well, what's wrong with the code in drivers/base/power/main.c that
> >> > is activated by adding initcall_debug to the kernel command line?
> >>
> >> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
> >>
> >> Now that I have taken a look at it, the main issue is that the kernel
> >> command line needs to be modified to activate it. We cannot do this
> >> for our automated regression suites since the kernel command line is
> >> protected on Chrome OS systems.
> >
> > You are kidding, right? You have control over your test systems, don't
> > bloat everyone's kernel by 5k just because your infrastructure is
> > somehow something that you feel you can't change.
>
> Fair enough. But having to modify the kernel command line to do this
> is clunky. How about exposing the ability to turn on these
> initcall_debug prints through a knob under /sys/power?

This might work, but first you'd need to make them depend on something
different from initcall_debug (and make that thing in turn be set if
initcall_debug is put into the kernel command line). Then, you could
export the new variable.

Greg, does that make sense to you?

Rafael

2012-05-19 16:32:34

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Sat, May 19, 2012 at 01:59:20PM +0200, Rafael J. Wysocki wrote:
> On Saturday, May 19, 2012, Sameer Nanda wrote:
> > On Fri, May 18, 2012 at 4:01 PM, Greg KH <[email protected]> wrote:
> > > On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
> > >> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
> > >> > On Friday, May 18, 2012, Sameer Nanda wrote:
> > >> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> > >> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> > >> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> > >> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> > >> >> >> >
> > >> >> >> >> AFAICT, they are used for something completely different -- help solve
> > >> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
> > >> >> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
> > >> >> >> >> all.
> > >> >> >> >>
> > >> >> >> >
> > >> >> >> > Also note that all tracepoints have timestamps attached to them. You do
> > >> >> >> > not need to add deltas. Do that in the userspace tools that read the
> > >> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> > >> >> >> > three DEFINE_EVENTs. This will save space.
> > >> >> >>
> > >> >> >> Agreed on the space savings. However, with the time_delta in the
> > >> >> >> trace message itself, a one line shell script [1] that sorts on the
> > >> >> >> time_delta field is sufficient to quickly spot the devices that take a
> > >> >> >> long time to resume. Without the time_delta field, the user tool is
> > >> >> >> more complex since it needs to first match up the device_resume_in,
> > >> >> >> device_resume_waited and device_resume_out traces and then calculate
> > >> >> >> time deltas.
> > >> >> >>
> > >> >> >> Seems like a worthwhile trade-off to me but I can take out the
> > >> >> >> time_delta if the general consensus is otherwise.
> > >> >> >
> > >> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
> > >> >> > DEFINE_EVENT adds just about 300 bytes.
> > >> >>
> > >> >> Ok, let me respin the patch. I am thinking of adding time_delta to
> > >> >> all three traces. That way we should get the space saving while still
> > >> >> allowing quick spotting of devices that take long time to resume.
> > >> >
> > >> > Well, what's wrong with the code in drivers/base/power/main.c that
> > >> > is activated by adding initcall_debug to the kernel command line?
> > >>
> > >> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
> > >>
> > >> Now that I have taken a look at it, the main issue is that the kernel
> > >> command line needs to be modified to activate it. We cannot do this
> > >> for our automated regression suites since the kernel command line is
> > >> protected on Chrome OS systems.
> > >
> > > You are kidding, right? You have control over your test systems, don't
> > > bloat everyone's kernel by 5k just because your infrastructure is
> > > somehow something that you feel you can't change.
> >
> > Fair enough. But having to modify the kernel command line to do this
> > is clunky. How about exposing the ability to turn on these
> > initcall_debug prints through a knob under /sys/power?
>
> This might work, but first you'd need to make them depend on something
> different from initcall_debug (and make that thing in turn be set if
> initcall_debug is put into the kernel command line). Then, you could
> export the new variable.
>
> Greg, does that make sense to you?

Maybe, I'd like to see a patch first before agreeing with it though :)

2012-05-19 19:25:14

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Saturday, May 19, 2012, Greg KH wrote:
> On Sat, May 19, 2012 at 01:59:20PM +0200, Rafael J. Wysocki wrote:
> > On Saturday, May 19, 2012, Sameer Nanda wrote:
> > > On Fri, May 18, 2012 at 4:01 PM, Greg KH <[email protected]> wrote:
> > > > On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
> > > >> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
> > > >> > On Friday, May 18, 2012, Sameer Nanda wrote:
> > > >> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
> > > >> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
> > > >> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
> > > >> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
> > > >> >> >> >
> > > >> >> >> >> AFAICT, they are used for something completely different -- help solve
> > > >> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
> > > >> >> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
> > > >> >> >> >> all.
> > > >> >> >> >>
> > > >> >> >> >
> > > >> >> >> > Also note that all tracepoints have timestamps attached to them. You do
> > > >> >> >> > not need to add deltas. Do that in the userspace tools that read the
> > > >> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
> > > >> >> >> > three DEFINE_EVENTs. This will save space.
> > > >> >> >>
> > > >> >> >> Agreed on the space savings. However, with the time_delta in the
> > > >> >> >> trace message itself, a one line shell script [1] that sorts on the
> > > >> >> >> time_delta field is sufficient to quickly spot the devices that take a
> > > >> >> >> long time to resume. Without the time_delta field, the user tool is
> > > >> >> >> more complex since it needs to first match up the device_resume_in,
> > > >> >> >> device_resume_waited and device_resume_out traces and then calculate
> > > >> >> >> time deltas.
> > > >> >> >>
> > > >> >> >> Seems like a worthwhile trade-off to me but I can take out the
> > > >> >> >> time_delta if the general consensus is otherwise.
> > > >> >> >
> > > >> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
> > > >> >> > DEFINE_EVENT adds just about 300 bytes.
> > > >> >>
> > > >> >> Ok, let me respin the patch. I am thinking of adding time_delta to
> > > >> >> all three traces. That way we should get the space saving while still
> > > >> >> allowing quick spotting of devices that take long time to resume.
> > > >> >
> > > >> > Well, what's wrong with the code in drivers/base/power/main.c that
> > > >> > is activated by adding initcall_debug to the kernel command line?
> > > >>
> > > >> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
> > > >>
> > > >> Now that I have taken a look at it, the main issue is that the kernel
> > > >> command line needs to be modified to activate it. We cannot do this
> > > >> for our automated regression suites since the kernel command line is
> > > >> protected on Chrome OS systems.
> > > >
> > > > You are kidding, right? You have control over your test systems, don't
> > > > bloat everyone's kernel by 5k just because your infrastructure is
> > > > somehow something that you feel you can't change.
> > >
> > > Fair enough. But having to modify the kernel command line to do this
> > > is clunky. How about exposing the ability to turn on these
> > > initcall_debug prints through a knob under /sys/power?
> >
> > This might work, but first you'd need to make them depend on something
> > different from initcall_debug (and make that thing in turn be set if
> > initcall_debug is put into the kernel command line). Then, you could
> > export the new variable.
> >
> > Greg, does that make sense to you?
>
> Maybe, I'd like to see a patch first before agreeing with it though :)

Sure.

2012-05-22 19:17:08

[permalink] [raw]

Subject: [PATCH] power: add knob for printing device resume times

Added a new knob called /sys/powe/pm_print_times. Setting it to 1
enables printing of time taken by devices to suspend and resume.
Setting it to 0 disables this printing (unless overridden by
initcall_debug kernel command line option).

Signed-off-by: Sameer Nanda <[email protected]>
cc: Greg KH <[email protected]>
cc: Rafael J. Wysocki <[email protected]>
cc: Steven Rostedt <[email protected]>
---
drivers/base/power/main.c | 4 ++--
drivers/base/power/power.h | 11 +++++++++++
kernel/power/main.c | 34 ++++++++++++++++++++++++++++++++++
3 files changed, 47 insertions(+), 2 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index b462c0e..ca8b2b5 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -166,7 +166,7 @@ static ktime_t initcall_debug_start(struct device *dev)
{
ktime_t calltime = ktime_set(0, 0);

- if (initcall_debug) {
+ if (pm_print_times) {
pr_info("calling %s+ @ %i, parent: %s\n",
dev_name(dev), task_pid_nr(current),
dev->parent ? dev_name(dev->parent) : "none");
@@ -181,7 +181,7 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
{
ktime_t delta, rettime;

- if (initcall_debug) {
+ if (pm_print_times) {
rettime = ktime_get();
delta = ktime_sub(rettime, calltime);
pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
diff --git a/drivers/base/power/power.h b/drivers/base/power/power.h
index eeb4bff..12c77b7 100644
--- a/drivers/base/power/power.h
+++ b/drivers/base/power/power.h
@@ -85,3 +85,14 @@ static inline int pm_qos_sysfs_add(struct device *dev) { return 0; }
static inline void pm_qos_sysfs_remove(struct device *dev) {}

#endif
+
+#ifdef CONFIG_PM_DEBUG
+
+extern int pm_print_times_enabled;
+#define pm_print_times (initcall_debug || pm_print_times_enabled)
+
+#else /* CONFIG_PM_DEBUG */
+
+#define pm_print_times initcall_debug
+
+#endif /* CONFIG_PM_DEBUG */
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 1c12581..602f617 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -132,6 +132,39 @@ static ssize_t pm_test_store(struct kobject *kobj, struct kobj_attribute *attr,
}

power_attr(pm_test);
+
+/*
+ * pm_print_times: print time taken by devices to suspend and resume.
+ *
+ * show() returns whether printing of suspend and resume times is enabled.
+ *
+ * store() accepts 0 or 1. O disables printing and 1 enables it.
+ */
+int pm_print_times_enabled;
+
+static ssize_t pm_print_times_show(struct kobject *kobj,
+ struct kobj_attribute *attr, char *buf)
+{
+ return sprintf(buf, "%d\n", pm_print_times_enabled);
+}
+
+static ssize_t pm_print_times_store(struct kobject *kobj,
+ struct kobj_attribute *attr,
+ const char *buf, size_t n)
+{
+ unsigned long val;
+
+ if (kstrtoul(buf, 10, &val))
+ return -EINVAL;
+
+ if (val > 1)
+ return -EINVAL;
+
+ pm_print_times_enabled = val;
+ return n;
+}
+
+power_attr(pm_print_times);
#endif /* CONFIG_PM_DEBUG */

#ifdef CONFIG_DEBUG_FS
@@ -411,6 +444,7 @@ static struct attribute * g[] = {
&wakeup_count_attr.attr,
#ifdef CONFIG_PM_DEBUG
&pm_test_attr.attr,
+ &pm_print_times_attr.attr,
#endif
#endif
NULL,
--
1.7.7.3

2012-05-22 19:19:06

[permalink] [raw]

Subject: Re: [PATCH] power, trace: add tracing for device_resume

On Sat, May 19, 2012 at 12:30 PM, Rafael J. Wysocki <[email protected]> wrote:
> On Saturday, May 19, 2012, Greg KH wrote:
>> On Sat, May 19, 2012 at 01:59:20PM +0200, Rafael J. Wysocki wrote:
>> > On Saturday, May 19, 2012, Sameer Nanda wrote:
>> > > On Fri, May 18, 2012 at 4:01 PM, Greg KH <[email protected]> wrote:
>> > > > On Fri, May 18, 2012 at 03:17:32PM -0700, Sameer Nanda wrote:
>> > > >> On Fri, May 18, 2012 at 2:46 PM, Rafael J. Wysocki <[email protected]> wrote:
>> > > >> > On Friday, May 18, 2012, Sameer Nanda wrote:
>> > > >> >> On Fri, May 18, 2012 at 2:19 PM, Steven Rostedt <[email protected]> wrote:
>> > > >> >> > On Fri, 2012-05-18 at 13:58 -0700, Sameer Nanda wrote:
>> > > >> >> >> On Fri, May 18, 2012 at 12:14 PM, Steven Rostedt <[email protected]> wrote:
>> > > >> >> >> > On Fri, 2012-05-18 at 11:57 -0700, Sameer Nanda wrote:
>> > > >> >> >> >
>> > > >> >> >> >> AFAICT, they are used for something completely different -- help solve
>> > > >> >> >> >> suspend/resume issues by saving a hash in the RTC of the last device
>> > > >> >> >> >> that suspended/resumed. They don't use the perf tracing mechanism at
>> > > >> >> >> >> all.
>> > > >> >> >> >>
>> > > >> >> >> >
>> > > >> >> >> > Also note that all tracepoints have timestamps attached to them. You do
>> > > >> >> >> > not need to add deltas. Do that in the userspace tools that read the
>> > > >> >> >> > timestamps and events. This way you can have one DECLARE_EVENT_CLASS and
>> > > >> >> >> > three DEFINE_EVENTs. This will save space.
>> > > >> >> >>
>> > > >> >> >> Agreed on the space savings. However, with the time_delta in the
>> > > >> >> >> trace message itself, a one line shell script [1] that sorts on the
>> > > >> >> >> time_delta field is sufficient to quickly spot the devices that take a
>> > > >> >> >> long time to resume. Without the time_delta field, the user tool is
>> > > >> >> >> more complex since it needs to first match up the device_resume_in,
>> > > >> >> >> device_resume_waited and device_resume_out traces and then calculate
>> > > >> >> >> time deltas.
>> > > >> >> >>
>> > > >> >> >> Seems like a worthwhile trade-off to me but I can take out the
>> > > >> >> >> time_delta if the general consensus is otherwise.
>> > > >> >> >
>> > > >> >> > Just note that every TRACE_EVENT() adds around 5k or more code. Every
>> > > >> >> > DEFINE_EVENT adds just about 300 bytes.
>> > > >> >>
>> > > >> >> Ok, let me respin the patch. I am thinking of adding time_delta to
>> > > >> >> all three traces. That way we should get the space saving while still
>> > > >> >> allowing quick spotting of devices that take long time to resume.
>> > > >> >
>> > > >> > Well, what's wrong with the code in drivers/base/power/main.c that
>> > > >> > is activated by adding initcall_debug to the kernel command line?
>> > > >>
>> > > >> Mostly that I hadn't looked closely at initcall_debug before writing my patch :)
>> > > >>
>> > > >> Now that I have taken a look at it, the main issue is that the kernel
>> > > >> command line needs to be modified to activate it. We cannot do this
>> > > >> for our automated regression suites since the kernel command line is
>> > > >> protected on Chrome OS systems.
>> > > >
>> > > > You are kidding, right? You have control over your test systems, don't
>> > > > bloat everyone's kernel by 5k just because your infrastructure is
>> > > > somehow something that you feel you can't change.
>> > >
>> > > Fair enough. But having to modify the kernel command line to do this
>> > > is clunky. How about exposing the ability to turn on these
>> > > initcall_debug prints through a knob under /sys/power?
>> >
>> > This might work, but first you'd need to make them depend on something
>> > different from initcall_debug (and make that thing in turn be set if
>> > initcall_debug is put into the kernel command line). Then, you could
>> > export the new variable.
>> >
>> > Greg, does that make sense to you?
>>
>> Maybe, I'd like to see a patch first before agreeing with it though :)
>
> Sure.

New patch uploaded that uses the existing initcall_debug functionality.

--
Sameer

2012-05-22 20:25:21

[permalink] [raw]

Subject: Re: [PATCH] power: add knob for printing device resume times

On Tue, May 22, 2012 at 12:16:45PM -0700, Sameer Nanda wrote:
> Added a new knob called /sys/powe/pm_print_times. Setting it to 1
> enables printing of time taken by devices to suspend and resume.
> Setting it to 0 disables this printing (unless overridden by
> initcall_debug kernel command line option).
>
> Signed-off-by: Sameer Nanda <[email protected]>
> cc: Greg KH <[email protected]>
> cc: Rafael J. Wysocki <[email protected]>
> cc: Steven Rostedt <[email protected]>
> ---
> drivers/base/power/main.c | 4 ++--
> drivers/base/power/power.h | 11 +++++++++++
> kernel/power/main.c | 34 ++++++++++++++++++++++++++++++++++
> 3 files changed, 47 insertions(+), 2 deletions(-)

Not getting into if this patch is correct or not, it's obviously wrong
in that you are adding a new sysfs file to the system, yet you did not
add a Documentation/ABI/ file documenting exactly what this file does
and how to use it.

Please redo it with that added, and fix the obvious typo in the
changelog body as well :)

thanks,

greg k-h

2012-05-23 16:46:27

[permalink] [raw]

Subject: [PATCH v2] power: add knob for printing device resume times

Added a new knob called /sys/power/pm_print_times. Setting it to 1
enables printing of time taken by devices to suspend and resume.
Setting it to 0 disables this printing (unless overridden by
initcall_debug kernel command line option).

Signed-off-by: Sameer Nanda <[email protected]>
cc: Greg KH <[email protected]>
cc: Rafael J. Wysocki <[email protected]>
cc: Steven Rostedt <[email protected]>
---
Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
drivers/base/power/main.c | 4 +-
drivers/base/power/power.h | 11 ++++++++++
kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
4 files changed, 60 insertions(+), 2 deletions(-)

diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
index b464d12..79210d1 100644
--- a/Documentation/ABI/testing/sysfs-power
+++ b/Documentation/ABI/testing/sysfs-power
@@ -172,3 +172,16 @@ Description:

Reading from this file will display the current value, which is
set to 1 MB by default.
+
+What: /sys/power/pm_print_times
+Date: May 2012
+Contact: Sameer Nanda <[email protected]>
+Description:
+ The /sys/power/pm_print_times file allows user space to
+ control whether the time taken by devices to suspend and
+ resume is printed. These prints are useful for hunting down
+ devices that take too long to suspend or resume.
+
+ Writing a "1" enables this printing while writing a "0"
+ disables it. The default value is "0". Reading from this file
+ will display the current value.
diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index b462c0e..ca8b2b5 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -166,7 +166,7 @@ static ktime_t initcall_debug_start(struct device *dev)
{
ktime_t calltime = ktime_set(0, 0);

- if (initcall_debug) {
+ if (pm_print_times) {
pr_info("calling %s+ @ %i, parent: %s\n",
dev_name(dev), task_pid_nr(current),
dev->parent ? dev_name(dev->parent) : "none");
@@ -181,7 +181,7 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
{
ktime_t delta, rettime;

- if (initcall_debug) {
+ if (pm_print_times) {
rettime = ktime_get();
delta = ktime_sub(rettime, calltime);
pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
diff --git a/drivers/base/power/power.h b/drivers/base/power/power.h
index eeb4bff..12c77b7 100644
--- a/drivers/base/power/power.h
+++ b/drivers/base/power/power.h
@@ -85,3 +85,14 @@ static inline int pm_qos_sysfs_add(struct device *dev) { return 0; }
static inline void pm_qos_sysfs_remove(struct device *dev) {}

#endif
+
+#ifdef CONFIG_PM_DEBUG
+
+extern int pm_print_times_enabled;
+#define pm_print_times (initcall_debug || pm_print_times_enabled)
+
+#else /* CONFIG_PM_DEBUG */
+
+#define pm_print_times initcall_debug
+
+#endif /* CONFIG_PM_DEBUG */
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 1c12581..97eea04 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -132,6 +132,39 @@ static ssize_t pm_test_store(struct kobject *kobj, struct kobj_attribute *attr,
}

power_attr(pm_test);
+
+/*
+ * pm_print_times: print time taken by devices to suspend and resume.
+ *
+ * show() returns whether printing of suspend and resume times is enabled.
+ *
+ * store() accepts 0 or 1. 0 disables printing and 1 enables it.
+ */
+int pm_print_times_enabled;
+
+static ssize_t pm_print_times_show(struct kobject *kobj,
+ struct kobj_attribute *attr, char *buf)
+{
+ return sprintf(buf, "%d\n", pm_print_times_enabled);
+}
+
+static ssize_t pm_print_times_store(struct kobject *kobj,
+ struct kobj_attribute *attr,
+ const char *buf, size_t n)
+{
+ unsigned long val;
+
+ if (kstrtoul(buf, 10, &val))
+ return -EINVAL;
+
+ if (val > 1)
+ return -EINVAL;
+
+ pm_print_times_enabled = val;
+ return n;
+}
+
+power_attr(pm_print_times);
#endif /* CONFIG_PM_DEBUG */

#ifdef CONFIG_DEBUG_FS
@@ -411,6 +444,7 @@ static struct attribute * g[] = {
&wakeup_count_attr.attr,
#ifdef CONFIG_PM_DEBUG
&pm_test_attr.attr,
+ &pm_print_times_attr.attr,
#endif
#endif
NULL,
--
1.7.7.3

2012-05-24 10:27:17

by Pavel Machek

[permalink] [raw]

Subject: Re: [PATCH] power: add knob for printing device resume times

On Tue 2012-05-22 12:16:45, Sameer Nanda wrote:
> Added a new knob called /sys/powe/pm_print_times. Setting it to 1
> enables printing of time taken by devices to suspend and resume.
> Setting it to 0 disables this printing (unless overridden by
> initcall_debug kernel command line option).

Did not we have nice module_param() interface that had kernel command
line parameter _and_ sysfs file created with .. one line IIRC?

Could that be used?

--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

2012-05-29 17:08:24

[permalink] [raw]

Subject: Re: [PATCH] power: add knob for printing device resume times

On Thu, May 24, 2012 at 3:27 AM, Pavel Machek <[email protected]> wrote:
> On Tue 2012-05-22 12:16:45, Sameer Nanda wrote:
>> Added a new knob called /sys/powe/pm_print_times. Setting it to 1
>> enables printing of time taken by devices to suspend and resume.
>> Setting it to 0 disables this printing (unless overridden by
>> initcall_debug kernel command line option).
>
> Did not we have nice module_param() interface that had kernel command
> line parameter _and_ sysfs file created with .. one line IIRC?
>
> Could that be used?

Not sure how/if that would help here? The patch is adding a new sysfs
knob and not a a new kernel command line or module parameter.

>
> --
> (english) http://www.livejournal.com/~pavelmachek
> (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

--
Sameer

2012-06-04 22:42:09

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Wed, May 23, 2012 at 9:45 AM, Sameer Nanda <[email protected]> wrote:
> Added a new knob called /sys/power/pm_print_times. Setting it to 1
> enables printing of time taken by devices to suspend and resume.
> Setting it to 0 disables this printing (unless overridden by
> initcall_debug kernel command line option).
>
> Signed-off-by: Sameer Nanda <[email protected]>
> cc: Greg KH <[email protected]>
> cc: Rafael J. Wysocki <[email protected]>
> cc: Steven Rostedt <[email protected]>
> ---
> Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> drivers/base/power/main.c | 4 +-
> drivers/base/power/power.h | 11 ++++++++++
> kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> 4 files changed, 60 insertions(+), 2 deletions(-)
>
> diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
> index b464d12..79210d1 100644
> --- a/Documentation/ABI/testing/sysfs-power
> +++ b/Documentation/ABI/testing/sysfs-power
> @@ -172,3 +172,16 @@ Description:
>
> Reading from this file will display the current value, which is
> set to 1 MB by default.
> +
> +What: /sys/power/pm_print_times
> +Date: May 2012
> +Contact: Sameer Nanda <[email protected]>
> +Description:
> + The /sys/power/pm_print_times file allows user space to
> + control whether the time taken by devices to suspend and
> + resume is printed. These prints are useful for hunting down
> + devices that take too long to suspend or resume.
> +
> + Writing a "1" enables this printing while writing a "0"
> + disables it. The default value is "0". Reading from this file
> + will display the current value.
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index b462c0e..ca8b2b5 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -166,7 +166,7 @@ static ktime_t initcall_debug_start(struct device *dev)
> {
> ktime_t calltime = ktime_set(0, 0);
>
> - if (initcall_debug) {
> + if (pm_print_times) {
> pr_info("calling %s+ @ %i, parent: %s\n",
> dev_name(dev), task_pid_nr(current),
> dev->parent ? dev_name(dev->parent) : "none");
> @@ -181,7 +181,7 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
> {
> ktime_t delta, rettime;
>
> - if (initcall_debug) {
> + if (pm_print_times) {
> rettime = ktime_get();
> delta = ktime_sub(rettime, calltime);
> pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
> diff --git a/drivers/base/power/power.h b/drivers/base/power/power.h
> index eeb4bff..12c77b7 100644
> --- a/drivers/base/power/power.h
> +++ b/drivers/base/power/power.h
> @@ -85,3 +85,14 @@ static inline int pm_qos_sysfs_add(struct device *dev) { return 0; }
> static inline void pm_qos_sysfs_remove(struct device *dev) {}
>
> #endif
> +
> +#ifdef CONFIG_PM_DEBUG
> +
> +extern int pm_print_times_enabled;
> +#define pm_print_times (initcall_debug || pm_print_times_enabled)
> +
> +#else /* CONFIG_PM_DEBUG */
> +
> +#define pm_print_times initcall_debug
> +
> +#endif /* CONFIG_PM_DEBUG */
> diff --git a/kernel/power/main.c b/kernel/power/main.c
> index 1c12581..97eea04 100644
> --- a/kernel/power/main.c
> +++ b/kernel/power/main.c
> @@ -132,6 +132,39 @@ static ssize_t pm_test_store(struct kobject *kobj, struct kobj_attribute *attr,
> }
>
> power_attr(pm_test);
> +
> +/*
> + * pm_print_times: print time taken by devices to suspend and resume.
> + *
> + * show() returns whether printing of suspend and resume times is enabled.
> + *
> + * store() accepts 0 or 1. 0 disables printing and 1 enables it.
> + */
> +int pm_print_times_enabled;
> +
> +static ssize_t pm_print_times_show(struct kobject *kobj,
> + struct kobj_attribute *attr, char *buf)
> +{
> + return sprintf(buf, "%d\n", pm_print_times_enabled);
> +}
> +
> +static ssize_t pm_print_times_store(struct kobject *kobj,
> + struct kobj_attribute *attr,
> + const char *buf, size_t n)
> +{
> + unsigned long val;
> +
> + if (kstrtoul(buf, 10, &val))
> + return -EINVAL;
> +
> + if (val > 1)
> + return -EINVAL;
> +
> + pm_print_times_enabled = val;
> + return n;
> +}
> +
> +power_attr(pm_print_times);
> #endif /* CONFIG_PM_DEBUG */
>
> #ifdef CONFIG_DEBUG_FS
> @@ -411,6 +444,7 @@ static struct attribute * g[] = {
> &wakeup_count_attr.attr,
> #ifdef CONFIG_PM_DEBUG
> &pm_test_attr.attr,
> + &pm_print_times_attr.attr,
> #endif
> #endif
> NULL,
> --
> 1.7.7.3
>

Greg KH, Rafael: any feedback on this patch? Questions I can help
answer to help push this along?

2012-06-05 06:56:29

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Mon, Jun 04, 2012 at 03:41:44PM -0700, Sameer Nanda wrote:
> On Wed, May 23, 2012 at 9:45 AM, Sameer Nanda <[email protected]> wrote:
>
> Greg KH, Rafael: any feedback on this patch? Questions I can help
> answer to help push this along?

No, you sent this in the middle of the huge merge window, where
maintainers are busy, and don't have time or even the ability to apply
new patches like this. Now that 3.5-rc1 is out, we will slowly dig out
from our patch queues and respond to patches eventually.

Patience please,

greg k-h

2012-06-10 11:25:34

by Pavel Machek

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

Hi!

> > ?#ifdef CONFIG_DEBUG_FS
> > @@ -411,6 +444,7 @@ static struct attribute * g[] = {
> > ? ? ? ?&wakeup_count_attr.attr,
> > ?#ifdef CONFIG_PM_DEBUG
> > ? ? ? ?&pm_test_attr.attr,
> > + ? ? ? &pm_print_times_attr.attr,
> > ?#endif
> > ?#endif
> > ? ? ? ?NULL,
> > --
> > 1.7.7.3
> >
>
> Greg KH, Rafael: any feedback on this patch? Questions I can help
> answer to help push this along?

Yes; it should be possible to use something like module_parm() to make
this one-liner...
Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

2012-06-15 00:19:32

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> Added a new knob called /sys/power/pm_print_times. Setting it to 1
> enables printing of time taken by devices to suspend and resume.
> Setting it to 0 disables this printing (unless overridden by
> initcall_debug kernel command line option).
>
> Signed-off-by: Sameer Nanda <[email protected]>
> cc: Greg KH <[email protected]>
> cc: Rafael J. Wysocki <[email protected]>
> cc: Steven Rostedt <[email protected]>
> ---
> Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> drivers/base/power/main.c | 4 +-
> drivers/base/power/power.h | 11 ++++++++++
> kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> 4 files changed, 60 insertions(+), 2 deletions(-)

This patch fails against the linux-next tree, care to fix it up so that
I can apply it?

thanks,

greg k-h

2012-06-15 09:55:05

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Friday, June 15, 2012, Greg KH wrote:
> On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> > Added a new knob called /sys/power/pm_print_times. Setting it to 1
> > enables printing of time taken by devices to suspend and resume.
> > Setting it to 0 disables this printing (unless overridden by
> > initcall_debug kernel command line option).
> >
> > Signed-off-by: Sameer Nanda <[email protected]>
> > cc: Greg KH <[email protected]>
> > cc: Rafael J. Wysocki <[email protected]>
> > cc: Steven Rostedt <[email protected]>
> > ---
> > Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> > drivers/base/power/main.c | 4 +-
> > drivers/base/power/power.h | 11 ++++++++++
> > kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> > 4 files changed, 60 insertions(+), 2 deletions(-)
>
> This patch fails against the linux-next tree, care to fix it up so that
> I can apply it?

I'd prefer it to go through my tree if you don't mind.

Rafael

2012-06-15 14:09:31

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Fri, Jun 15, 2012 at 12:00:20PM +0200, Rafael J. Wysocki wrote:
> On Friday, June 15, 2012, Greg KH wrote:
> > On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> > > Added a new knob called /sys/power/pm_print_times. Setting it to 1
> > > enables printing of time taken by devices to suspend and resume.
> > > Setting it to 0 disables this printing (unless overridden by
> > > initcall_debug kernel command line option).
> > >
> > > Signed-off-by: Sameer Nanda <[email protected]>
> > > cc: Greg KH <[email protected]>
> > > cc: Rafael J. Wysocki <[email protected]>
> > > cc: Steven Rostedt <[email protected]>
> > > ---
> > > Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> > > drivers/base/power/main.c | 4 +-
> > > drivers/base/power/power.h | 11 ++++++++++
> > > kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> > > 4 files changed, 60 insertions(+), 2 deletions(-)
> >
> > This patch fails against the linux-next tree, care to fix it up so that
> > I can apply it?
>
> I'd prefer it to go through my tree if you don't mind.

Not at all, feel free to put:

Acked-by: Greg Kroah-Hartman <[email protected]>

When it shows up again.

thanks,

greg k-h

2012-06-16 13:52:21

[permalink] [raw]

Subject: Re: [PATCH v2] power: add knob for printing device resume times

On Friday, June 15, 2012, Greg KH wrote:
> On Fri, Jun 15, 2012 at 12:00:20PM +0200, Rafael J. Wysocki wrote:
> > On Friday, June 15, 2012, Greg KH wrote:
> > > On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> > > > Added a new knob called /sys/power/pm_print_times. Setting it to 1
> > > > enables printing of time taken by devices to suspend and resume.
> > > > Setting it to 0 disables this printing (unless overridden by
> > > > initcall_debug kernel command line option).
> > > >
> > > > Signed-off-by: Sameer Nanda <[email protected]>
> > > > cc: Greg KH <[email protected]>
> > > > cc: Rafael J. Wysocki <[email protected]>
> > > > cc: Steven Rostedt <[email protected]>
> > > > ---
> > > > Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> > > > drivers/base/power/main.c | 4 +-
> > > > drivers/base/power/power.h | 11 ++++++++++
> > > > kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> > > > 4 files changed, 60 insertions(+), 2 deletions(-)
> > >
> > > This patch fails against the linux-next tree, care to fix it up so that
> > > I can apply it?
> >
> > I'd prefer it to go through my tree if you don't mind.
>
> Not at all, feel free to put:
>
> Acked-by: Greg Kroah-Hartman <[email protected]>
>
> When it shows up again.

I've just used the original one, it only needed a documentation merge conflict
fixed.

Queued up for 3.6.

Thanks,
Rafael

2012-06-16 20:31:06

[permalink] [raw]

Subject: [PATCH] (was: Re: [PATCH v2] power: add knob for printing device resume times)

On Saturday, June 16, 2012, Rafael J. Wysocki wrote:
> On Friday, June 15, 2012, Greg KH wrote:
> > On Fri, Jun 15, 2012 at 12:00:20PM +0200, Rafael J. Wysocki wrote:
> > > On Friday, June 15, 2012, Greg KH wrote:
> > > > On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> > > > > Added a new knob called /sys/power/pm_print_times. Setting it to 1
> > > > > enables printing of time taken by devices to suspend and resume.
> > > > > Setting it to 0 disables this printing (unless overridden by
> > > > > initcall_debug kernel command line option).
> > > > >
> > > > > Signed-off-by: Sameer Nanda <[email protected]>
> > > > > cc: Greg KH <[email protected]>
> > > > > cc: Rafael J. Wysocki <[email protected]>
> > > > > cc: Steven Rostedt <[email protected]>
> > > > > ---
> > > > > Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> > > > > drivers/base/power/main.c | 4 +-
> > > > > drivers/base/power/power.h | 11 ++++++++++
> > > > > kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> > > > > 4 files changed, 60 insertions(+), 2 deletions(-)
> > > >
> > > > This patch fails against the linux-next tree, care to fix it up so that
> > > > I can apply it?
> > >
> > > I'd prefer it to go through my tree if you don't mind.
> >
> > Not at all, feel free to put:
> >
> > Acked-by: Greg Kroah-Hartman <[email protected]>
> >
> > When it shows up again.
>
> I've just used the original one, it only needed a documentation merge conflict
> fixed.
>
> Queued up for 3.6.

I propose the following patch on top of this one. The details are in the
changelog.

If anyone has any objections, please let me know.

Thanks,
Rafael

---
From: Rafael J. Wysocki <[email protected]>
Subject: PM / Sleep: Separate printing suspend times from initcall_debug

Change the behavior of the newly introduced
/sys/power/pm_print_times attribute so that its initial value
depends on initcall_debug, but setting it to 0 will cause device
suspend/resume times not to be printed, even if initcall_debug has
been set. This way, the people who use initcall_debug for reasons
other than PM debugging will be able to switch the suspend/resume
times printing off, if need be.

Signed-off-by: Rafael J. Wysocki <[email protected]>
---
drivers/base/power/main.c | 4 ++--
drivers/base/power/power.h | 11 -----------
include/linux/suspend.h | 4 ++++
kernel/power/main.c | 14 +++++++++++---
4 files changed, 17 insertions(+), 16 deletions(-)

Index: linux/kernel/power/main.c
===================================================================
--- linux.orig/kernel/power/main.c
+++ linux/kernel/power/main.c
@@ -139,7 +139,7 @@ power_attr(pm_test);
* show() returns whether printing of suspend and resume times is enabled.
* store() accepts 0 or 1. 0 disables printing and 1 enables it.
*/
-int pm_print_times_enabled;
+bool pm_print_times_enabled;

static ssize_t pm_print_times_show(struct kobject *kobj,
struct kobj_attribute *attr, char *buf)
@@ -159,12 +159,19 @@ static ssize_t pm_print_times_store(stru
if (val > 1)
return -EINVAL;

- pm_print_times_enabled = val;
+ pm_print_times_enabled = !!val;
return n;
}

+static inline void pm_print_times_init(void)
+{
+ pm_print_times_enabled = !!initcall_debug;
+}
+
power_attr(pm_print_times);
-#endif /* CONFIG_PM_DEBUG */
+#else /* !CONFIG_PM_DEBUG */
+static inline void pm_print_times_init(void) {}
+#endif /* !CONFIG_PM_DEBUG */

#ifdef CONFIG_DEBUG_FS
static char *suspend_step_name(enum suspend_stat_step step)
@@ -599,6 +606,7 @@ static int __init pm_init(void)
error = sysfs_create_group(power_kobj, &attr_group);
if (error)
return error;
+ pm_print_times_init();
return pm_autosleep_init();
}

Index: linux/include/linux/suspend.h
===================================================================
--- linux.orig/include/linux/suspend.h
+++ linux/include/linux/suspend.h
@@ -387,6 +387,8 @@ static inline void unlock_system_sleep(v
mutex_unlock(&pm_mutex);
}

+extern bool pm_print_times_enabled;
+
#else /* !CONFIG_PM_SLEEP */

static inline int register_pm_notifier(struct notifier_block *nb)
@@ -406,6 +408,8 @@ static inline bool pm_wakeup_pending(voi
static inline void lock_system_sleep(void) {}
static inline void unlock_system_sleep(void) {}

+#define pm_print_times_enabled (false)
+
#endif /* !CONFIG_PM_SLEEP */

#ifdef CONFIG_PM_AUTOSLEEP
Index: linux/drivers/base/power/main.c
===================================================================
--- linux.orig/drivers/base/power/main.c
+++ linux/drivers/base/power/main.c
@@ -166,7 +166,7 @@ static ktime_t initcall_debug_start(stru
{
ktime_t calltime = ktime_set(0, 0);

- if (pm_print_times) {
+ if (pm_print_times_enabled) {
pr_info("calling %s+ @ %i, parent: %s\n",
dev_name(dev), task_pid_nr(current),
dev->parent ? dev_name(dev->parent) : "none");
@@ -181,7 +181,7 @@ static void initcall_debug_report(struct
{
ktime_t delta, rettime;

- if (pm_print_times) {
+ 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),
Index: linux/drivers/base/power/power.h
===================================================================
--- linux.orig/drivers/base/power/power.h
+++ linux/drivers/base/power/power.h
@@ -85,14 +85,3 @@ static inline int pm_qos_sysfs_add(struc
static inline void pm_qos_sysfs_remove(struct device *dev) {}

#endif
-
-#ifdef CONFIG_PM_DEBUG
-
-extern int pm_print_times_enabled;
-#define pm_print_times (initcall_debug || pm_print_times_enabled)
-
-#else /* CONFIG_PM_DEBUG */
-
-#define pm_print_times initcall_debug
-
-#endif /* CONFIG_PM_DEBUG */

2012-06-18 01:26:51

[permalink] [raw]

Subject: Re: [PATCH] (was: Re: [PATCH v2] power: add knob for printing device resume times)

On Sat, Jun 16, 2012 at 10:36:21PM +0200, Rafael J. Wysocki wrote:
> On Saturday, June 16, 2012, Rafael J. Wysocki wrote:
> > On Friday, June 15, 2012, Greg KH wrote:
> > > On Fri, Jun 15, 2012 at 12:00:20PM +0200, Rafael J. Wysocki wrote:
> > > > On Friday, June 15, 2012, Greg KH wrote:
> > > > > On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
> > > > > > Added a new knob called /sys/power/pm_print_times. Setting it to 1
> > > > > > enables printing of time taken by devices to suspend and resume.
> > > > > > Setting it to 0 disables this printing (unless overridden by
> > > > > > initcall_debug kernel command line option).
> > > > > >
> > > > > > Signed-off-by: Sameer Nanda <[email protected]>
> > > > > > cc: Greg KH <[email protected]>
> > > > > > cc: Rafael J. Wysocki <[email protected]>
> > > > > > cc: Steven Rostedt <[email protected]>
> > > > > > ---
> > > > > > Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
> > > > > > drivers/base/power/main.c | 4 +-
> > > > > > drivers/base/power/power.h | 11 ++++++++++
> > > > > > kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
> > > > > > 4 files changed, 60 insertions(+), 2 deletions(-)
> > > > >
> > > > > This patch fails against the linux-next tree, care to fix it up so that
> > > > > I can apply it?
> > > >
> > > > I'd prefer it to go through my tree if you don't mind.
> > >
> > > Not at all, feel free to put:
> > >
> > > Acked-by: Greg Kroah-Hartman <[email protected]>
> > >
> > > When it shows up again.
> >
> > I've just used the original one, it only needed a documentation merge conflict
> > fixed.
> >
> > Queued up for 3.6.
>
> I propose the following patch on top of this one. The details are in the
> changelog.
>
> If anyone has any objections, please let me know.

No objection from me at all, thanks for cleaning this up:

Acked-by: Greg Kroah-Hartman <[email protected]>

2012-06-18 05:46:18

by Srivatsa S. Bhat

[permalink] [raw]

Subject: Re: [PATCH] (was: Re: [PATCH v2] power: add knob for printing device resume times)

On 06/17/2012 02:06 AM, Rafael J. Wysocki wrote:

> On Saturday, June 16, 2012, Rafael J. Wysocki wrote:
>> On Friday, June 15, 2012, Greg KH wrote:
>>> On Fri, Jun 15, 2012 at 12:00:20PM +0200, Rafael J. Wysocki wrote:
>>>> On Friday, June 15, 2012, Greg KH wrote:
>>>>> On Wed, May 23, 2012 at 09:45:32AM -0700, Sameer Nanda wrote:
>>>>>> Added a new knob called /sys/power/pm_print_times. Setting it to 1
>>>>>> enables printing of time taken by devices to suspend and resume.
>>>>>> Setting it to 0 disables this printing (unless overridden by
>>>>>> initcall_debug kernel command line option).
>>>>>>
>>>>>> Signed-off-by: Sameer Nanda <[email protected]>
>>>>>> cc: Greg KH <[email protected]>
>>>>>> cc: Rafael J. Wysocki <[email protected]>
>>>>>> cc: Steven Rostedt <[email protected]>
>>>>>> ---
>>>>>> Documentation/ABI/testing/sysfs-power | 13 ++++++++++++
>>>>>> drivers/base/power/main.c | 4 +-
>>>>>> drivers/base/power/power.h | 11 ++++++++++
>>>>>> kernel/power/main.c | 34 +++++++++++++++++++++++++++++++++
>>>>>> 4 files changed, 60 insertions(+), 2 deletions(-)
>>>>>
>>>>> This patch fails against the linux-next tree, care to fix it up so that
>>>>> I can apply it?
>>>>
>>>> I'd prefer it to go through my tree if you don't mind.
>>>
>>> Not at all, feel free to put:
>>>
>>> Acked-by: Greg Kroah-Hartman <[email protected]>
>>>
>>> When it shows up again.
>>
>> I've just used the original one, it only needed a documentation merge conflict
>> fixed.
>>
>> Queued up for 3.6.
>
> I propose the following patch on top of this one. The details are in the
> changelog.
>
> If anyone has any objections, please let me know.
>
> Thanks,
> Rafael
>
> ---
> From: Rafael J. Wysocki <[email protected]>
> Subject: PM / Sleep: Separate printing suspend times from initcall_debug
>
> Change the behavior of the newly introduced
> /sys/power/pm_print_times attribute so that its initial value
> depends on initcall_debug, but setting it to 0 will cause device
> suspend/resume times not to be printed, even if initcall_debug has
> been set. This way, the people who use initcall_debug for reasons
> other than PM debugging will be able to switch the suspend/resume
> times printing off, if need be.
>
> Signed-off-by: Rafael J. Wysocki <[email protected]>

Reviewed-by: Srivatsa S. Bhat <[email protected]>

Regards,
Srivatsa S. Bhat

> ---
> drivers/base/power/main.c | 4 ++--
> drivers/base/power/power.h | 11 -----------
> include/linux/suspend.h | 4 ++++
> kernel/power/main.c | 14 +++++++++++---
> 4 files changed, 17 insertions(+), 16 deletions(-)
>
> Index: linux/kernel/power/main.c
> ===================================================================
> --- linux.orig/kernel/power/main.c
> +++ linux/kernel/power/main.c
> @@ -139,7 +139,7 @@ power_attr(pm_test);
> * show() returns whether printing of suspend and resume times is enabled.
> * store() accepts 0 or 1. 0 disables printing and 1 enables it.
> */
> -int pm_print_times_enabled;
> +bool pm_print_times_enabled;
>
> static ssize_t pm_print_times_show(struct kobject *kobj,
> struct kobj_attribute *attr, char *buf)
> @@ -159,12 +159,19 @@ static ssize_t pm_print_times_store(stru
> if (val > 1)
> return -EINVAL;
>
> - pm_print_times_enabled = val;
> + pm_print_times_enabled = !!val;
> return n;
> }
>
> +static inline void pm_print_times_init(void)
> +{
> + pm_print_times_enabled = !!initcall_debug;
> +}
> +
> power_attr(pm_print_times);
> -#endif /* CONFIG_PM_DEBUG */
> +#else /* !CONFIG_PM_DEBUG */
> +static inline void pm_print_times_init(void) {}
> +#endif /* !CONFIG_PM_DEBUG */
>
> #ifdef CONFIG_DEBUG_FS
> static char *suspend_step_name(enum suspend_stat_step step)
> @@ -599,6 +606,7 @@ static int __init pm_init(void)
> error = sysfs_create_group(power_kobj, &attr_group);
> if (error)
> return error;
> + pm_print_times_init();
> return pm_autosleep_init();
> }
>
> Index: linux/include/linux/suspend.h
> ===================================================================
> --- linux.orig/include/linux/suspend.h
> +++ linux/include/linux/suspend.h
> @@ -387,6 +387,8 @@ static inline void unlock_system_sleep(v
> mutex_unlock(&pm_mutex);
> }
>
> +extern bool pm_print_times_enabled;
> +
> #else /* !CONFIG_PM_SLEEP */
>
> static inline int register_pm_notifier(struct notifier_block *nb)
> @@ -406,6 +408,8 @@ static inline bool pm_wakeup_pending(voi
> static inline void lock_system_sleep(void) {}
> static inline void unlock_system_sleep(void) {}
>
> +#define pm_print_times_enabled (false)
> +
> #endif /* !CONFIG_PM_SLEEP */
>
> #ifdef CONFIG_PM_AUTOSLEEP
> Index: linux/drivers/base/power/main.c
> ===================================================================
> --- linux.orig/drivers/base/power/main.c
> +++ linux/drivers/base/power/main.c
> @@ -166,7 +166,7 @@ static ktime_t initcall_debug_start(stru
> {
> ktime_t calltime = ktime_set(0, 0);
>
> - if (pm_print_times) {
> + if (pm_print_times_enabled) {
> pr_info("calling %s+ @ %i, parent: %s\n",
> dev_name(dev), task_pid_nr(current),
> dev->parent ? dev_name(dev->parent) : "none");
> @@ -181,7 +181,7 @@ static void initcall_debug_report(struct
> {
> ktime_t delta, rettime;
>
> - if (pm_print_times) {
> + 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),
> Index: linux/drivers/base/power/power.h
> ===================================================================
> --- linux.orig/drivers/base/power/power.h
> +++ linux/drivers/base/power/power.h
> @@ -85,14 +85,3 @@ static inline int pm_qos_sysfs_add(struc
> static inline void pm_qos_sysfs_remove(struct device *dev) {}
>
> #endif
> -
> -#ifdef CONFIG_PM_DEBUG
> -
> -extern int pm_print_times_enabled;
> -#define pm_print_times (initcall_debug || pm_print_times_enabled)
> -
> -#else /* CONFIG_PM_DEBUG */
> -
> -#define pm_print_times initcall_debug
> -
> -#endif /* CONFIG_PM_DEBUG */

2012-06-28 21:29:57