[RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Jiejing Zhang]

From: Zhang Jiejing <jiejing.zhang@freescale.com>

This patch add function to check each device's suspend time
consumption. If any driver takes more time that the threshold (default
0.5 ms), it will print a warnning message including the device and bus
name on the console.  You can change the threshold on-the-fly by
modify file '/sys/power/device_suspend_time_threshold' to adjust this
value,the unit is in microsecond.

The output is like:
PM: device (bus)   :(device name) suspend/resume too slow, takes (time) msencs.
PM: device platform:soc-audio.2 suspend too slow, takes          606.696 msecs
PM: device platform:mxc_sdc_fb.1 suspend too slow, takes         7.708 msecs

Signed-off-by: Zhang Jiejing <jiejing.zhang@freescale.com>
---
 drivers/base/power/main.c  |   40 +++++++++++++++++++++++++++++++++++++++-
 drivers/base/power/power.h |    3 +++
 kernel/power/Kconfig       |   15 +++++++++++++++
 kernel/power/main.c        |   32 ++++++++++++++++++++++++++++++++
 4 files changed, 89 insertions(+), 1 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 052dc53..000243c 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -178,6 +178,40 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
 	}
 }
 
+#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
+static void suspend_time_debug_start(ktime_t *start)
+{
+	*start = ktime_get();
+}
+
+static void suspend_time_debug_report(const char *name, struct device *dev,
+				      ktime_t starttime)
+{
+	ktime_t rettime;
+	s64 usecs64;
+	int usecs;
+
+	if (!dev->driver)
+		return;
+
+	rettime = ktime_get();
+	usecs64 = ktime_to_us(ktime_sub(rettime, starttime));
+	usecs = usecs64;
+	if (usecs == 0)
+		usecs = 1;
+
+	if (device_suspend_time_threshold
+	    && usecs > device_suspend_time_threshold)
+		pr_info("PM: device %s:%s %s too slow, it takes \t %ld.%03ld mses\n",
+			dev->bus->name, dev_name(dev), name,
+			usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
+}
+#else
+static void suspend_time_debug_start(ktime_t *start) {}
+static void suspend_time_debug_report(const char *name, struct device *dev,
+				      ktime_t starttime) {}
+#endif /* CONFIG_SUSPEND_DEVICE_TIME_DEBUG */
+
 /**
  * dpm_wait - Wait for a PM operation to complete.
  * @dev: Device to wait for.
@@ -214,7 +248,7 @@ static int pm_op(struct device *dev,
 		 pm_message_t state)
 {
 	int error = 0;
-	ktime_t calltime;
+	ktime_t calltime, starttime;
 
 	calltime = initcall_debug_start(dev);
 
@@ -222,13 +256,17 @@ static int pm_op(struct device *dev,
 #ifdef CONFIG_SUSPEND
 	case PM_EVENT_SUSPEND:
 		if (ops->suspend) {
+			suspend_time_debug_start(&starttime);
 			error = ops->suspend(dev);
+			suspend_time_debug_report("suspend", dev, starttime);
 			suspend_report_result(ops->suspend, error);
 		}
 		break;
 	case PM_EVENT_RESUME:
 		if (ops->resume) {
+			suspend_time_debug_start(&starttime);
 			error = ops->resume(dev);
+			suspend_time_debug_report("resume", dev, starttime);
 			suspend_report_result(ops->resume, error);
 		}
 		break;
diff --git a/drivers/base/power/power.h b/drivers/base/power/power.h
index f2a25f1..72d5963 100644
--- a/drivers/base/power/power.h
+++ b/drivers/base/power/power.h
@@ -18,6 +18,9 @@ extern int pm_async_enabled;
 /* drivers/base/power/main.c */
 extern struct list_head dpm_list;	/* The active device list */
 
+/* driver/base/power/main.c */
+extern int device_suspend_time_threshold;
+
 static inline struct device *to_device(struct list_head *entry)
 {
 	return container_of(entry, struct device, power.entry);
diff --git a/kernel/power/Kconfig b/kernel/power/Kconfig
index 4603f08..9b82c4b 100644
--- a/kernel/power/Kconfig
+++ b/kernel/power/Kconfig
@@ -87,6 +87,21 @@ config PM_SLEEP
 	def_bool y
 	depends on SUSPEND || HIBERNATION || XEN_SAVE_RESTORE
 
+config SUSPEND_DEVICE_TIME_DEBUG
+        bool "Warnning device suspend/resume takes too much time"
+	depends on SUSPEND && PM_DEBUG
+	default n
+	---help---
+
+	This option will enable a timing function to check each device
+        suspend time consumption, If the device takes more time that
+        the threshold (default 0.5 ms), it will print the device and
+        bus name on the console.  You can change the threshold
+        on-the-fly by modify "/sys/power/device_suspend_time_threshold"
+        the unit is in microsecond.
+
+	This options only for debug proprose, If in doubt, say N.
+
 config PM_SLEEP_SMP
 	def_bool y
 	depends on SMP
diff --git a/kernel/power/main.c b/kernel/power/main.c
index 8eaba5f..d2e734f 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -297,12 +297,44 @@ power_attr(pm_trace_dev_match);
 
 #endif /* CONFIG_PM_TRACE */
 
+#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
+/*
+ * threshold of device suspend time consumption in microsecond(0.5ms), the
+ * driver suspend/resume time longer than this threshold will be
+ * print to console, 0 to disable */
+int device_suspend_time_threshold = 500;
+
+static ssize_t
+device_suspend_time_threshold_show(struct kobject *kobj,
+				   struct kobj_attribute *attr, char *buf)
+{
+	return sprintf(buf, "%d\n", device_suspend_time_threshold);
+}
+
+static ssize_t
+device_suspend_time_threshold_store(struct kobject *kobj,
+				    struct kobj_attribute *attr,
+				    const char *buf, size_t n)
+{
+	int val;
+	if (sscanf(buf, "%d", &val) > 0) {
+		device_suspend_time_threshold = val;
+		return n;
+	}
+	return -EINVAL;
+}
+power_attr(device_suspend_time_threshold);
+#endif
+
 static struct attribute * g[] = {
 	&state_attr.attr,
 #ifdef CONFIG_PM_TRACE
 	&pm_trace_attr.attr,
 	&pm_trace_dev_match_attr.attr,
 #endif
+#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
+	&device_suspend_time_threshold_attr.attr,
+#endif
 #ifdef CONFIG_PM_SLEEP
 	&pm_async_attr.attr,
 	&wakeup_count_attr.attr,
-- 
1.7.1

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Jiejing.Zhang]

[-- Attachment #1.1: Type: text/plain, Size: 7014 bytes --]

Hi,

Does anyone have comments on this driver?

Best regards,
Zhang Jiejing


2011/4/7 Jiejing Zhang <kzjeef@gmail.com>

> From: Zhang Jiejing <jiejing.zhang@freescale.com>
>
> This patch add function to check each device's suspend time
> consumption. If any driver takes more time that the threshold (default
> 0.5 ms), it will print a warnning message including the device and bus
> name on the console.  You can change the threshold on-the-fly by
> modify file '/sys/power/device_suspend_time_threshold' to adjust this
> value,the unit is in microsecond.
>
> The output is like:
> PM: device (bus)   :(device name) suspend/resume too slow, takes (time)
> msencs.
> PM: device platform:soc-audio.2 suspend too slow, takes          606.696
> msecs
> PM: device platform:mxc_sdc_fb.1 suspend too slow, takes         7.708
> msecs
>
> Signed-off-by: Zhang Jiejing <jiejing.zhang@freescale.com>
> ---
>  drivers/base/power/main.c  |   40 +++++++++++++++++++++++++++++++++++++++-
>  drivers/base/power/power.h |    3 +++
>  kernel/power/Kconfig       |   15 +++++++++++++++
>  kernel/power/main.c        |   32 ++++++++++++++++++++++++++++++++
>  4 files changed, 89 insertions(+), 1 deletions(-)
>
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 052dc53..000243c 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -178,6 +178,40 @@ static void initcall_debug_report(struct device *dev,
> ktime_t calltime,
>        }
>  }
>
> +#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
> +static void suspend_time_debug_start(ktime_t *start)
> +{
> +       *start = ktime_get();
> +}
> +
> +static void suspend_time_debug_report(const char *name, struct device
> *dev,
> +                                     ktime_t starttime)
> +{
> +       ktime_t rettime;
> +       s64 usecs64;
> +       int usecs;
> +
> +       if (!dev->driver)
> +               return;
> +
> +       rettime = ktime_get();
> +       usecs64 = ktime_to_us(ktime_sub(rettime, starttime));
> +       usecs = usecs64;
> +       if (usecs == 0)
> +               usecs = 1;
> +
> +       if (device_suspend_time_threshold
> +           && usecs > device_suspend_time_threshold)
> +               pr_info("PM: device %s:%s %s too slow, it takes \t
> %ld.%03ld mses\n",
> +                       dev->bus->name, dev_name(dev), name,
> +                       usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
> +}
> +#else
> +static void suspend_time_debug_start(ktime_t *start) {}
> +static void suspend_time_debug_report(const char *name, struct device
> *dev,
> +                                     ktime_t starttime) {}
> +#endif /* CONFIG_SUSPEND_DEVICE_TIME_DEBUG */
> +
>  /**
>  * dpm_wait - Wait for a PM operation to complete.
>  * @dev: Device to wait for.
> @@ -214,7 +248,7 @@ static int pm_op(struct device *dev,
>                 pm_message_t state)
>  {
>        int error = 0;
> -       ktime_t calltime;
> +       ktime_t calltime, starttime;
>
>        calltime = initcall_debug_start(dev);
>
> @@ -222,13 +256,17 @@ static int pm_op(struct device *dev,
>  #ifdef CONFIG_SUSPEND
>        case PM_EVENT_SUSPEND:
>                if (ops->suspend) {
> +                       suspend_time_debug_start(&starttime);
>                        error = ops->suspend(dev);
> +                       suspend_time_debug_report("suspend", dev,
> starttime);
>                        suspend_report_result(ops->suspend, error);
>                }
>                break;
>        case PM_EVENT_RESUME:
>                if (ops->resume) {
> +                       suspend_time_debug_start(&starttime);
>                        error = ops->resume(dev);
> +                       suspend_time_debug_report("resume", dev,
> starttime);
>                        suspend_report_result(ops->resume, error);
>                }
>                break;
> diff --git a/drivers/base/power/power.h b/drivers/base/power/power.h
> index f2a25f1..72d5963 100644
> --- a/drivers/base/power/power.h
> +++ b/drivers/base/power/power.h
> @@ -18,6 +18,9 @@ extern int pm_async_enabled;
>  /* drivers/base/power/main.c */
>  extern struct list_head dpm_list;      /* The active device list */
>
> +/* driver/base/power/main.c */
> +extern int device_suspend_time_threshold;
> +
>  static inline struct device *to_device(struct list_head *entry)
>  {
>        return container_of(entry, struct device, power.entry);
> diff --git a/kernel/power/Kconfig b/kernel/power/Kconfig
> index 4603f08..9b82c4b 100644
> --- a/kernel/power/Kconfig
> +++ b/kernel/power/Kconfig
> @@ -87,6 +87,21 @@ config PM_SLEEP
>        def_bool y
>        depends on SUSPEND || HIBERNATION || XEN_SAVE_RESTORE
>
> +config SUSPEND_DEVICE_TIME_DEBUG
> +        bool "Warnning device suspend/resume takes too much time"
> +       depends on SUSPEND && PM_DEBUG
> +       default n
> +       ---help---
> +
> +       This option will enable a timing function to check each device
> +        suspend time consumption, If the device takes more time that
> +        the threshold (default 0.5 ms), it will print the device and
> +        bus name on the console.  You can change the threshold
> +        on-the-fly by modify "/sys/power/device_suspend_time_threshold"
> +        the unit is in microsecond.
> +
> +       This options only for debug proprose, If in doubt, say N.
> +
>  config PM_SLEEP_SMP
>        def_bool y
>        depends on SMP
> diff --git a/kernel/power/main.c b/kernel/power/main.c
> index 8eaba5f..d2e734f 100644
> --- a/kernel/power/main.c
> +++ b/kernel/power/main.c
> @@ -297,12 +297,44 @@ power_attr(pm_trace_dev_match);
>
>  #endif /* CONFIG_PM_TRACE */
>
> +#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
> +/*
> + * threshold of device suspend time consumption in microsecond(0.5ms), the
> + * driver suspend/resume time longer than this threshold will be
> + * print to console, 0 to disable */
> +int device_suspend_time_threshold = 500;
> +
> +static ssize_t
> +device_suspend_time_threshold_show(struct kobject *kobj,
> +                                  struct kobj_attribute *attr, char *buf)
> +{
> +       return sprintf(buf, "%d\n", device_suspend_time_threshold);
> +}
> +
> +static ssize_t
> +device_suspend_time_threshold_store(struct kobject *kobj,
> +                                   struct kobj_attribute *attr,
> +                                   const char *buf, size_t n)
> +{
> +       int val;
> +       if (sscanf(buf, "%d", &val) > 0) {
> +               device_suspend_time_threshold = val;
> +               return n;
> +       }
> +       return -EINVAL;
> +}
> +power_attr(device_suspend_time_threshold);
> +#endif
> +
>  static struct attribute * g[] = {
>        &state_attr.attr,
>  #ifdef CONFIG_PM_TRACE
>        &pm_trace_attr.attr,
>        &pm_trace_dev_match_attr.attr,
>  #endif
> +#ifdef CONFIG_SUSPEND_DEVICE_TIME_DEBUG
> +       &device_suspend_time_threshold_attr.attr,
> +#endif
>  #ifdef CONFIG_PM_SLEEP
>        &pm_async_attr.attr,
>        &wakeup_count_attr.attr,
> --
> 1.7.1
>
>

[-- Attachment #1.2: Type: text/html, Size: 8191 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Alan Stern]

On Tue, 12 Apr 2011, Jiejing.Zhang  wrote:

> Hi,
> 
> Does anyone have comments on this driver?
> 
> Best regards,
> Zhang Jiejing
> 
> 
> 2011/4/7 Jiejing Zhang <kzjeef@gmail.com>
> 
> > From: Zhang Jiejing <jiejing.zhang@freescale.com>
> >
> > This patch add function to check each device's suspend time
> > consumption. If any driver takes more time that the threshold (default
> > 0.5 ms), it will print a warnning message including the device and bus
> > name on the console.  You can change the threshold on-the-fly by
> > modify file '/sys/power/device_suspend_time_threshold' to adjust this
> > value,the unit is in microsecond.

Bear in mind that rotating disk drives typically take several hundred 
milliseconds to spin down.  The warning would always trigger.  That 
doesn't seem particularly useful.

Alan Stern

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Jiejing.Zhang]

[-- Attachment #1.1: Type: text/plain, Size: 1620 bytes --]

Hi Alan,

2011/4/12 Alan Stern <stern@rowland.harvard.edu>

> On Tue, 12 Apr 2011, Jiejing.Zhang  wrote:
>
> > Hi,
> >
> > Does anyone have comments on this driver?
> >
> > Best regards,
> > Zhang Jiejing
> >
> >
> > 2011/4/7 Jiejing Zhang <kzjeef@gmail.com>
> >
> > > From: Zhang Jiejing <jiejing.zhang@freescale.com>
> > >
> > > This patch add function to check each device's suspend time
> > > consumption. If any driver takes more time that the threshold (default
> > > 0.5 ms), it will print a warnning message including the device and bus
> > > name on the console.  You can change the threshold on-the-fly by
> > > modify file '/sys/power/device_suspend_time_threshold' to adjust this
> > > value,the unit is in microsecond.
>
> Bear in mind that rotating disk drives typically take several hundred
> milliseconds to spin down.  The warning would always trigger.  That
> doesn't seem particularly useful.
>

I think it's better change the default value 0 to disable it, enable it only
some one write a threshold.

First of all, it's a debug function (depends on PM_DEBUG), It's useful
in embedded area, like mobile phone or e-book, they are suspend/resume very
frequently and required resume as quick as possible. This debug function
can used to figure out which driver(s) is/are slow on suspend/resume.

I fact that embedded engineer meets a lot is, after some development the
total time of suspend/resume is become slow, since there was a lot driver
may affect the total time, it's function can help them to figure out which
driver is slow, and it's make life easier.

Thanks.

Jiejing Zhang


> Alan Stern
>
>

[-- Attachment #1.2: Type: text/html, Size: 2543 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Alan Stern]

On Tue, 12 Apr 2011, Jiejing.Zhang  wrote:

> > Bear in mind that rotating disk drives typically take several hundred
> > milliseconds to spin down.  The warning would always trigger.  That
> > doesn't seem particularly useful.
> >
> 
> I think it's better change the default value 0 to disable it, enable it only
> some one write a threshold.
> 
> First of all, it's a debug function (depends on PM_DEBUG), It's useful
> in embedded area, like mobile phone or e-book, they are suspend/resume very
> frequently and required resume as quick as possible. This debug function
> can used to figure out which driver(s) is/are slow on suspend/resume.
> 
> I fact that embedded engineer meets a lot is, after some development the
> total time of suspend/resume is become slow, since there was a lot driver
> may affect the total time, it's function can help them to figure out which
> driver is slow, and it's make life easier.

Maybe you should mention this in the patch description.

You know, the "initcall_debug" boot parameter will cause the kernel to 
log the amount of time each device spends doing suspend and resume.

Alan Stern

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Jiejing.Zhang]

Hi Alan,

2011/4/12 Alan Stern <stern@rowland.harvard.edu>
>
> On Tue, 12 Apr 2011, Jiejing.Zhang  wrote:
>
> > > Bear in mind that rotating disk drives typically take several hundred
> > > milliseconds to spin down.  The warning would always trigger.  That
> > > doesn't seem particularly useful.
> > >
> >
> > I think it's better change the default value 0 to disable it, enable it only
> > some one write a threshold.
> >
> > First of all, it's a debug function (depends on PM_DEBUG), It's useful
> > in embedded area, like mobile phone or e-book, they are suspend/resume very
> > frequently and required resume as quick as possible. This debug function
> > can used to figure out which driver(s) is/are slow on suspend/resume.
> >
> > I fact that embedded engineer meets a lot is, after some development the
> > total time of suspend/resume is become slow, since there was a lot driver
> > may affect the total time, it's function can help them to figure out which
> > driver is slow, and it's make life easier.
>
> Maybe you should mention this in the patch description.
>
> You know, the "initcall_debug" boot parameter will cause the kernel to
> log the amount of time each device spends doing suspend and resume.

Thanks for you reply.
Yes, you are right, this parameter can print out log of information,
also can echo 1 > /sys/module/kernel/parameters/initcall_debug to enable this.
but the output is really not good to read, and hard to filter out
what's is time consume device:

This  a snapshot of output of initcall_debug when suspend:

PM: Syncing filesystems ... done.
Freezing user space processes ...
PHY: 0:00 - Link is Up - 100/Full
(elapsed 2.71 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
calling  mmc2:0001+ @ 12
call mmc2:0001+ returned 0 after 1 usecs
calling  input9+ @ 12
call input9+ returned 0 after 2 usecs
calling  input8+ @ 12
call input8+ returned 0 after 2 usecs
calling  2-1.4.1:1.1+ @ 4006
call 2-1.4.1:1.1+ returned 0 after 0 usecs   <-- this can be ignore by threshold
calling  input7+ @ 12
call input7+ returned 0 after 1 usecs         <-- this too
calling  2-1.4.1:1.0+ @ 4007
call 2-1.4.1:1.0+ returned 0 after 0 usecs   <-- this too
calling  2-1.4:1.0+ @ 4008
calling  mmc0:0001+ @ 12
call 2-1.4:1.0+ returned 0 after 0 usecs
call mmc0:0001+ returned 0 after 4 usecs
calling  2-1.1:1.0+ @ 4010
calling  2-1.4.1+ @ 4006
call 2-1.1:1.0+ returned 0 after 0 usecs
calling  soc-audio.2+ @ 12
calling  2-1.1+ @ 4007
call 2-1.4.1+ returned 0 after 23052 usecs    <-- name better be
"busname : device name "
calling  2-1.4.1+ @ 4006
call 2-1.4.1+ returned 0 after 0 usecs
calling  2-1.4+ @ 4009
call 2-1.1+ returned 0 after 25869 usecs         <-- this is really
time consuming.
calling  2-1.1+ @ 4007
call 2-1.1+ returned 0 after 0 usecs
call 2-1.4+ returned 0 after 17828 usecs
calling  2-1.4+ @ 4009
call 2-1.4+ returned 0 after 0 usecs
call soc-audio.2+ returned 0 after 1188954 usecs   <--- this too .
calling  input6+ @ 12
call input6+ returned 0 after 1 usecs
calling  2-1:1.0+ @ 4012
call 2-1:1.0+ returned 0 after 0 usecs
calling  2-1+ @ 4012
calling  alarm+ @ 12
call alarm+ returned 0 after 98 usecs
calling  rtc0+ @ 12
call rtc0+ returned 0 after 3 usecs
calling  input5+ @ 12
call 2-1+ returned 0 after 12385 usecs
calling  2-1+ @ 4012
....
....
....
....
....
[ignore 100+ lines.]
PM: suspend of devices complete after 1895.908 msecs

---------log end--------------

you can see this there was lots of driver finish suspend within 10
usecs(most of them are).
call ahci.0+ returned 0 after 0 usecs
                                            ^^
and the name  like:
call 2-1.4.1+ returned 0 after 23052 usecs
       ^^^^^^^^^
I think add a bus name here is better.

Do you think I add a time threshold and a better readable name in
initcall_debug is a good idea ?
I've tried add some threshold into this code, but I don't know where
to put the threshold parameter.
The initcall_debug is a module parameter of kernel/main.c, I don't
think add some threshold here is a good idea.

Also, I think the mission of my patch, and initcall_debug is
different, my patch is aim to filter out some really time consuming
device, but initcall_debug seems to figure out where kernel died when
doing init/suspend/resume operation. It's hard to merge two together.

my patch put this option under PM_DEBUG, and the threshold file under
/sys/power/device_suspend_time_threshold

the output is like this:

bash-3.2# echo 500 > /sys/power/device_suspend_time_threshold
bash-3.2# request_suspend_state: mem (0->3) at 73269332502 (1970-01-02
03:12:18.107533376 UTC)
PM: Syncing filesystems ... done.
Freezing user space processes ... (elapsed 0.02 seconds) done.
Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
PM: device usb:2-1.1 suspend too slow, it takes          15.758 msecs
PM: device usb:2-1.4.1 suspend too slow, it takes        21.619 msecs
PM: device usb:2-1.4 suspend too slow, it takes          18.569 msecs
PM: device platform:soc-audio.2 suspend too slow, it takes       1216.710 msecs
da9052_tsi_suspend: called
PM: device platform:da9052-tsi suspend too slow, it takes        2.538 msecs
PM: device usb:2-1 suspend too slow, it takes    22.371 msecs
PM: suspend of devices complete after 1252.998 msecs
suspend wp cpu=400000000
PM: late suspend of devices complete after 0.775 msecs

--- [ log end ] ----

If you want to figure out which device suspend too slow, this patch
will do better.

Thanks.

Jiejing


>
> Alan Stern
>

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Alan Stern]

On Tue, 12 Apr 2011, Jiejing.Zhang  wrote:

> Thanks for you reply.
> Yes, you are right, this parameter can print out log of information,
> also can echo 1 > /sys/module/kernel/parameters/initcall_debug to enable this.
> but the output is really not good to read, and hard to filter out
> what's is time consume device:

...

> Do you think I add a time threshold and a better readable name in
> initcall_debug is a good idea ?
> I've tried add some threshold into this code, but I don't know where
> to put the threshold parameter.
> The initcall_debug is a module parameter of kernel/main.c, I don't
> think add some threshold here is a good idea.
> 
> Also, I think the mission of my patch, and initcall_debug is
> different, my patch is aim to filter out some really time consuming
> device, but initcall_debug seems to figure out where kernel died when
> doing init/suspend/resume operation. It's hard to merge two together.
> 
> my patch put this option under PM_DEBUG, and the threshold file under
> /sys/power/device_suspend_time_threshold
> 
> the output is like this:
> 
> bash-3.2# echo 500 > /sys/power/device_suspend_time_threshold
> bash-3.2# request_suspend_state: mem (0->3) at 73269332502 (1970-01-02
> 03:12:18.107533376 UTC)
> PM: Syncing filesystems ... done.
> Freezing user space processes ... (elapsed 0.02 seconds) done.
> Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
> PM: device usb:2-1.1 suspend too slow, it takes          15.758 msecs
> PM: device usb:2-1.4.1 suspend too slow, it takes        21.619 msecs
> PM: device usb:2-1.4 suspend too slow, it takes          18.569 msecs
> PM: device platform:soc-audio.2 suspend too slow, it takes       1216.710 msecs
> da9052_tsi_suspend: called
> PM: device platform:da9052-tsi suspend too slow, it takes        2.538 msecs
> PM: device usb:2-1 suspend too slow, it takes    22.371 msecs
> PM: suspend of devices complete after 1252.998 msecs
> suspend wp cpu=400000000
> PM: late suspend of devices complete after 0.775 msecs
> 
> --- [ log end ] ----
> 
> If you want to figure out which device suspend too slow, this patch
> will do better.

It's okay with me.  Presenting the information in an easy-to-read form 
is fine.  I just wanted to point out that the information is already 
available.

BTW, there are several spelling errors in the Kconfig help text in your 
patch.  You should fix them before submitting the patch again.

Alan Stern

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Pavel Machek]

Hi!

> > If you want to figure out which device suspend too slow, this patch
> > will do better.
> 
> It's okay with me.  Presenting the information in an easy-to-read form 
> is fine.  I just wanted to point out that the information is already 
> available.
> 
> BTW, there are several spelling errors in the Kconfig help text in your 
> patch.  You should fix them before submitting the patch again.

Well well. I'd avoid placing this in kernel. It seems that parsing
dmesg to get the "better" debugging information out is pretty much
trivial.

Just publish that shell script somewhere...
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Jiejing.Zhang]

Hi Pavel,

2011/4/13 Pavel Machek <pavel@ucw.cz>:
> Hi!
>
>> > If you want to figure out which device suspend too slow, this patch
>> > will do better.
>>
>> It's okay with me.  Presenting the information in an easy-to-read form
>> is fine.  I just wanted to point out that the information is already
>> available.
>>
>> BTW, there are several spelling errors in the Kconfig help text in your
>> patch.  You should fix them before submitting the patch again.
>
> Well well. I'd avoid placing this in kernel. It seems that parsing
> dmesg to get the "better" debugging information out is pretty much
> trivial.

I'm admit it's not a big feather, but it's belong to PM_DEBUG, it's a
debug feather.
It's very useful in embedded Linux development. Also, when someone
debugging suspend/resume in these system, they always have to
implement a version like this. So I think add this debug feather to
kernel can do some help.

I'm ok with drop this patch, I just want to clarify the aim of patch.

Thanks.

Jiejing

>
> Just publish that shell script somewhere...
>                                                                        Pavel
> --
> (english) http://www.livejournal.com/~pavelmachek
> (cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html
>

Re: [RESEND PATCH] PM: add a config that give warnning if driver take too long on suspend/resume.

[Pavel Machek]

> Hi Pavel,
> 
> 2011/4/13 Pavel Machek <pavel@ucw.cz>:
> > Hi!
> >
> >> > If you want to figure out which device suspend too slow, this patch
> >> > will do better.
> >>
> >> It's okay with me.  Presenting the information in an easy-to-read form
> >> is fine.  I just wanted to point out that the information is already
> >> available.
> >>
> >> BTW, there are several spelling errors in the Kconfig help text in your
> >> patch.  You should fix them before submitting the patch again.
> >
> > Well well. I'd avoid placing this in kernel. It seems that parsing
> > dmesg to get the "better" debugging information out is pretty much
> > trivial.
> 
> I'm admit it's not a big feather, but it's belong to PM_DEBUG, it's a
> debug feather.
> It's very useful in embedded Linux development. Also, when someone
> debugging suspend/resume in these system, they always have to
> implement a version like this. So I think add this debug feather to
> kernel can do some help.
> 
> I'm ok with drop this patch, I just want to clarify the aim of patch.

Good.

Adding helpful dmesg-parsing script to linux/scripts/ would not be a
bad idea, through.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html