Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1690857 > unrolled thread

[PATCH 0/3] PM / sleep: Avoid filling up kernel log buffer with debug messages

Back to article view | Back to linux.kernel

Contents

  [PATCH 0/3] PM / sleep: Avoid filling up kernel log buffer with debug messages "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-07-19 03:00 +0200
    [PATCH 3/3] PM / timekeeping: Print debug messages when requested "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-07-19 03:00 +0200
      Re: [PATCH 3/3] PM / timekeeping: Print debug messages when requested "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-07-21 00:10 +0200
    [PATCH 2/3] PM / sleep: Mark suspend/hibernation start and finish "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-07-19 03:00 +0200
      [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and finish "Rafael J. Wysocki" <rjw@rjwysocki.net> - 2017-07-20 03:50 +0200
        Re: [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and  finish Mark Salyzyn <salyzyn@android.com> - 2017-07-20 20:00 +0200
          Re: [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and finish "Rafael J. Wysocki" <rafael@kernel.org> - 2017-07-20 23:10 +0200

#1690857 — [PATCH 0/3] PM / sleep: Avoid filling up kernel log buffer with debug messages

Hi,

The problem at hand is that on some systems suspend-to-idle can easily fill up
the kernel log buffer with debug messages in one cycle (if spurious wakeups
happen ofter enough).

I tried to make that somewhat better before, but it still turns out to be
problematic, so here's a patch series to possibly address this.

[1/3] adds a sysfs knob to turn debug messages from the core suspend/hibernate
code on and off (default) and a printk() wrapper taking that into account.

[2/3] adds some "info" messages to indicate when system power transitions start
and finish which IMO is useful to see in the log regardless.

[3/3] modifies the wrapper introduced by [1/3] to make it suitable for
tk_debug_account_sleep_time() and uses it in there instead of the
plain printk_deferred() as that also is a debug thing really and can
fill up the log buffer by itself in some cases.

Thanks,
Rafael

[toc] | [next] | [standalone]

#1690859 — [PATCH 3/3] PM / timekeeping: Print debug messages when requested

From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

The messages printed by tk_debug_account_sleep_time() are basically
useful for system sleep debugging, so print them only when the other
debug messages from the core suspend/hibernate code are enabled.

While at it, make it clear that the messages from
tk_debug_account_sleep_time() are about timekeeping suspend
duration, because in general timekeeping may be suspeded and
resumed for multiple times during one system suspend-resume cycle.

Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
---
 include/linux/suspend.h         |   10 ++++++++--
 kernel/power/main.c             |   10 +++++++---
 kernel/time/timekeeping_debug.c |    5 +++--
 3 files changed, 18 insertions(+), 7 deletions(-)

Index: linux-pm/include/linux/suspend.h
===================================================================
--- linux-pm.orig/include/linux/suspend.h
+++ linux-pm/include/linux/suspend.h
@@ -491,16 +491,22 @@ static inline void unlock_system_sleep(v
 
 #ifdef CONFIG_PM_SLEEP_DEBUG
 extern bool pm_print_times_enabled;
-extern __printf(1, 2) void pm_pr_dbg(const char *fmt, ...);
+extern __printf(2, 3) void __pm_pr_dbg(bool defer, const char *fmt, ...);
 #else
 #define pm_print_times_enabled	(false)
 
 #include <linux/printk.h>
 
-#define pm_pr_dbg(fmt, ...) \
+#define pm_pr_dbg(defer, fmt, ...) \
 	no_printk(KERN_DEBUG fmt, ##__VA_ARGS__)
 #endif
 
+#define pm_pr_dbg(fmt, ...) \
+	__pm_pr_dbg(false, fmt, ##__VA_ARGS__)
+
+#define pm_deferred_pr_dbg(fmt, ...) \
+	__pm_pr_dbg(true, fmt, ##__VA_ARGS__)
+
 #ifdef CONFIG_PM_AUTOSLEEP
 
 /* kernel/power/autosleep.c */
Index: linux-pm/kernel/power/main.c
===================================================================
--- linux-pm.orig/kernel/power/main.c
+++ linux-pm/kernel/power/main.c
@@ -388,13 +388,14 @@ static ssize_t pm_debug_messages_store(s
 power_attr(pm_debug_messages);
 
 /**
- * pm_pr_dbg - Print a suspend debug message to the kernel log.
+ * __pm_pr_dbg - Print a suspend debug message to the kernel log.
+ * @defer: Whether or not to use printk_deferred() to print the message.
  * @fmt: Message format.
  *
  * The message will be emitted if enabled through the pm_debug_messages
  * sysfs attribute.
  */
-void pm_pr_dbg(const char *fmt, ...)
+void __pm_pr_dbg(bool defer, const char *fmt, ...)
 {
 	struct va_format vaf;
 	va_list args;
@@ -407,7 +408,10 @@ void pm_pr_dbg(const char *fmt, ...
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk(KERN_DEBUG "PM: %pV", &vaf);
+	if (defer)
+		printk_deferred(KERN_DEBUG "PM: %pV", &vaf);
+	else
+		printk(KERN_DEBUG "PM: %pV", &vaf);
 
 	va_end(args);
 }
Index: linux-pm/kernel/time/timekeeping_debug.c
===================================================================
--- linux-pm.orig/kernel/time/timekeeping_debug.c
+++ linux-pm/kernel/time/timekeeping_debug.c
@@ -19,6 +19,7 @@
 #include <linux/init.h>
 #include <linux/kernel.h>
 #include <linux/seq_file.h>
+#include <linux/suspend.h>
 #include <linux/time.h>
 
 #include "timekeeping_internal.h"
@@ -75,7 +76,7 @@ void tk_debug_account_sleep_time(struct
 	int bin = min(fls(t->tv_sec), NUM_BINS-1);
 
 	sleep_time_bin[bin]++;
-	printk_deferred(KERN_INFO "Suspended for %lld.%03lu seconds\n",
-			(s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC);
+	pm_deferred_pr_dbg("Timekeeping suspended for %lld.%03lu seconds\n",
+			   (s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC);
 }
 

[toc] | [prev] | [next] | [standalone]

#1693252 — Re: [PATCH 3/3] PM / timekeeping: Print debug messages when requested

On Wednesday, July 19, 2017 02:42:43 AM Rafael J. Wysocki wrote:
> From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> 
> The messages printed by tk_debug_account_sleep_time() are basically
> useful for system sleep debugging, so print them only when the other
> debug messages from the core suspend/hibernate code are enabled.
> 
> While at it, make it clear that the messages from
> tk_debug_account_sleep_time() are about timekeeping suspend
> duration, because in general timekeeping may be suspeded and
> resumed for multiple times during one system suspend-resume cycle.
> 
> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

Any complaints or issues here?

If not, I'm going to queue it up for 4.14.

> ---
>  include/linux/suspend.h         |   10 ++++++++--
>  kernel/power/main.c             |   10 +++++++---
>  kernel/time/timekeeping_debug.c |    5 +++--
>  3 files changed, 18 insertions(+), 7 deletions(-)
> 
> Index: linux-pm/include/linux/suspend.h
> ===================================================================
> --- linux-pm.orig/include/linux/suspend.h
> +++ linux-pm/include/linux/suspend.h
> @@ -491,16 +491,22 @@ static inline void unlock_system_sleep(v
>  
>  #ifdef CONFIG_PM_SLEEP_DEBUG
>  extern bool pm_print_times_enabled;
> -extern __printf(1, 2) void pm_pr_dbg(const char *fmt, ...);
> +extern __printf(2, 3) void __pm_pr_dbg(bool defer, const char *fmt, ...);
>  #else
>  #define pm_print_times_enabled	(false)
>  
>  #include <linux/printk.h>
>  
> -#define pm_pr_dbg(fmt, ...) \
> +#define pm_pr_dbg(defer, fmt, ...) \
>  	no_printk(KERN_DEBUG fmt, ##__VA_ARGS__)
>  #endif
>  
> +#define pm_pr_dbg(fmt, ...) \
> +	__pm_pr_dbg(false, fmt, ##__VA_ARGS__)
> +
> +#define pm_deferred_pr_dbg(fmt, ...) \
> +	__pm_pr_dbg(true, fmt, ##__VA_ARGS__)
> +
>  #ifdef CONFIG_PM_AUTOSLEEP
>  
>  /* kernel/power/autosleep.c */
> Index: linux-pm/kernel/power/main.c
> ===================================================================
> --- linux-pm.orig/kernel/power/main.c
> +++ linux-pm/kernel/power/main.c
> @@ -388,13 +388,14 @@ static ssize_t pm_debug_messages_store(s
>  power_attr(pm_debug_messages);
>  
>  /**
> - * pm_pr_dbg - Print a suspend debug message to the kernel log.
> + * __pm_pr_dbg - Print a suspend debug message to the kernel log.
> + * @defer: Whether or not to use printk_deferred() to print the message.
>   * @fmt: Message format.
>   *
>   * The message will be emitted if enabled through the pm_debug_messages
>   * sysfs attribute.
>   */
> -void pm_pr_dbg(const char *fmt, ...)
> +void __pm_pr_dbg(bool defer, const char *fmt, ...)
>  {
>  	struct va_format vaf;
>  	va_list args;
> @@ -407,7 +408,10 @@ void pm_pr_dbg(const char *fmt, ...
>  	vaf.fmt = fmt;
>  	vaf.va = &args;
>  
> -	printk(KERN_DEBUG "PM: %pV", &vaf);
> +	if (defer)
> +		printk_deferred(KERN_DEBUG "PM: %pV", &vaf);
> +	else
> +		printk(KERN_DEBUG "PM: %pV", &vaf);
>  
>  	va_end(args);
>  }
> Index: linux-pm/kernel/time/timekeeping_debug.c
> ===================================================================
> --- linux-pm.orig/kernel/time/timekeeping_debug.c
> +++ linux-pm/kernel/time/timekeeping_debug.c
> @@ -19,6 +19,7 @@
>  #include <linux/init.h>
>  #include <linux/kernel.h>
>  #include <linux/seq_file.h>
> +#include <linux/suspend.h>
>  #include <linux/time.h>
>  
>  #include "timekeeping_internal.h"
> @@ -75,7 +76,7 @@ void tk_debug_account_sleep_time(struct
>  	int bin = min(fls(t->tv_sec), NUM_BINS-1);
>  
>  	sleep_time_bin[bin]++;
> -	printk_deferred(KERN_INFO "Suspended for %lld.%03lu seconds\n",
> -			(s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC);
> +	pm_deferred_pr_dbg("Timekeeping suspended for %lld.%03lu seconds\n",
> +			   (s64)t->tv_sec, t->tv_nsec / NSEC_PER_MSEC);
>  }
>  
> 

[toc] | [prev] | [next] | [standalone]

#1690860 — [PATCH 2/3] PM / sleep: Mark suspend/hibernation start and finish

From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

Regardless of whether or not debug messages from the core system
suspend/hibernation code are enabled, it is useful to know when
system-wide transitions start and finish (or fail), so print "info"
messages at these points.

Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
---
 kernel/power/hibernate.c |    8 ++++++++
 kernel/power/suspend.c   |    4 ++++
 2 files changed, 12 insertions(+)

Index: linux-pm/kernel/power/hibernate.c
===================================================================
--- linux-pm.orig/kernel/power/hibernate.c
+++ linux-pm/kernel/power/hibernate.c
@@ -692,6 +692,7 @@ int hibernate(void)
 		goto Unlock;
 	}
 
+	pr_info("Starting hibernation\n");
 	pm_prepare_console();
 	error = __pm_notifier_call_chain(PM_HIBERNATION_PREPARE, -1, &nr_calls);
 	if (error) {
@@ -762,6 +763,11 @@ int hibernate(void)
 	atomic_inc(&snapshot_device_available);
  Unlock:
 	unlock_system_sleep();
+	if (error)
+		pr_info("Hibernation failed (%d)\n", error);
+	else
+		pr_info("System resume complete\n");
+
 	return error;
 }
 
@@ -868,6 +874,7 @@ static int software_resume(void)
 		goto Unlock;
 	}
 
+	pr_info("Starting resume from hibernation\n");
 	pm_prepare_console();
 	error = __pm_notifier_call_chain(PM_RESTORE_PREPARE, -1, &nr_calls);
 	if (error) {
@@ -884,6 +891,7 @@ static int software_resume(void)
  Finish:
 	__pm_notifier_call_chain(PM_POST_RESTORE, nr_calls, NULL);
 	pm_restore_console();
+	pr_info("Resume from hibernation failed (%d)\n", error);
 	atomic_inc(&snapshot_device_available);
 	/* For success case, the suspend path will release the lock */
  Unlock:
Index: linux-pm/kernel/power/suspend.c
===================================================================
--- linux-pm.orig/kernel/power/suspend.c
+++ linux-pm/kernel/power/suspend.c
@@ -579,12 +579,16 @@ int pm_suspend(suspend_state_t state)
 	if (state <= PM_SUSPEND_ON || state >= PM_SUSPEND_MAX)
 		return -EINVAL;
 
+	pr_info("PM: Starting system suspend (%s)\n", pm_states[state]);
 	error = enter_state(state);
 	if (error) {
 		suspend_stats.fail++;
 		dpm_save_failed_errno(error);
+		pr_info("PM: System suspend (%s) failed (%d)\n",
+			pm_states[state], error);
 	} else {
 		suspend_stats.success++;
+		pr_info("PM: System resume complete\n");
 	}
 	return error;
 }

[toc] | [prev] | [next] | [standalone]

#1692337 — [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and finish

From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>

Regardless of whether or not debug messages from the core system
suspend/hibernation code are enabled, it is useful to know when
system-wide transitions start and finish (or fail), so print "info"
messages at these points.

Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
---

-> v2: Smiplified the messages as suggested by Mark.

---
 kernel/power/hibernate.c |    5 +++++
 kernel/power/suspend.c   |    2 ++
 2 files changed, 7 insertions(+)

Index: linux-pm/kernel/power/hibernate.c
===================================================================
--- linux-pm.orig/kernel/power/hibernate.c
+++ linux-pm/kernel/power/hibernate.c
@@ -692,6 +692,7 @@ int hibernate(void)
 		goto Unlock;
 	}
 
+	pr_info("hibernation entry\n");
 	pm_prepare_console();
 	error = __pm_notifier_call_chain(PM_HIBERNATION_PREPARE, -1, &nr_calls);
 	if (error) {
@@ -762,6 +763,8 @@ int hibernate(void)
 	atomic_inc(&snapshot_device_available);
  Unlock:
 	unlock_system_sleep();
+	pr_info("hibernation exit\n");
+
 	return error;
 }
 
@@ -868,6 +871,7 @@ static int software_resume(void)
 		goto Unlock;
 	}
 
+	pr_info("resume from hibernation\n");
 	pm_prepare_console();
 	error = __pm_notifier_call_chain(PM_RESTORE_PREPARE, -1, &nr_calls);
 	if (error) {
@@ -884,6 +888,7 @@ static int software_resume(void)
  Finish:
 	__pm_notifier_call_chain(PM_POST_RESTORE, nr_calls, NULL);
 	pm_restore_console();
+	pr_info("resume from hibernation failed (%d)\n", error);
 	atomic_inc(&snapshot_device_available);
 	/* For success case, the suspend path will release the lock */
  Unlock:
Index: linux-pm/kernel/power/suspend.c
===================================================================
--- linux-pm.orig/kernel/power/suspend.c
+++ linux-pm/kernel/power/suspend.c
@@ -579,6 +579,7 @@ int pm_suspend(suspend_state_t state)
 	if (state <= PM_SUSPEND_ON || state >= PM_SUSPEND_MAX)
 		return -EINVAL;
 
+	pr_info("PM: suspend entry (%s)\n", pm_states[state]);
 	error = enter_state(state);
 	if (error) {
 		suspend_stats.fail++;
@@ -586,6 +587,7 @@ int pm_suspend(suspend_state_t state)
 	} else {
 		suspend_stats.success++;
 	}
+	pr_info("PM: suspend exit\n");
 	return error;
 }
 EXPORT_SYMBOL(pm_suspend);

[toc] | [prev] | [next] | [standalone]

#1693148 — Re: [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and finish

On 07/19/2017 06:38 PM, Rafael J. Wysocki wrote:
> From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
>
> Regardless of whether or not debug messages from the core system
> suspend/hibernation code are enabled, it is useful to know when
> system-wide transitions start and finish (or fail), so print "info"
> messages at these points.
>
> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> ---
>
> -> v2: Smiplified the messages as suggested by Mark.
>
> ---
>   kernel/power/hibernate.c |    5 +++++
>   kernel/power/suspend.c   |    2 ++
>   2 files changed, 7 insertions(+)
>
> Index: linux-pm/kernel/power/hibernate.c
> ===================================================================
> --- linux-pm.orig/kernel/power/hibernate.c
> +++ linux-pm/kernel/power/hibernate.c
> @@ -692,6 +692,7 @@ int hibernate(void)
>   		goto Unlock;
>   	}
>   
> +	pr_info("hibernation entry\n");
nit (minor): Many of the logs report a PM: prefix. Flipping coin that 
the 3 characters provides any real gain is in your hands. My WAG is it 
would be nice to be able to do dmesg | grep PM:

Ack

[toc] | [prev] | [next] | [standalone]

#1693231 — Re: [PATCH v2 2/3] PM / sleep: Mark suspend/hibernation start and finish

On Thu, Jul 20, 2017 at 7:49 PM, Mark Salyzyn <salyzyn@android.com> wrote:
> On 07/19/2017 06:38 PM, Rafael J. Wysocki wrote:
>>
>> From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
>>
>> Regardless of whether or not debug messages from the core system
>> suspend/hibernation code are enabled, it is useful to know when
>> system-wide transitions start and finish (or fail), so print "info"
>> messages at these points.
>>
>> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
>> ---
>>
>> -> v2: Smiplified the messages as suggested by Mark.
>>
>> ---
>>   kernel/power/hibernate.c |    5 +++++
>>   kernel/power/suspend.c   |    2 ++
>>   2 files changed, 7 insertions(+)
>>
>> Index: linux-pm/kernel/power/hibernate.c
>> ===================================================================
>> --- linux-pm.orig/kernel/power/hibernate.c
>> +++ linux-pm/kernel/power/hibernate.c
>> @@ -692,6 +692,7 @@ int hibernate(void)
>>                 goto Unlock;
>>         }
>>   +     pr_info("hibernation entry\n");
>
> nit (minor): Many of the logs report a PM: prefix. Flipping coin that the 3
> characters provides any real gain is in your hands. My WAG is it would be
> nice to be able to do dmesg | grep PM:

Yeah, that's why pr_fmt() is defined in hibernate.c.  It is missing in
suspend.c ATM, though, hence the difference (but will be added there
too).

Thanks,
Rafael

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web