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

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

[Rafael J. Wysocki]

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

[PATCH 1/3] PM / sleep: Do not print debug messages by default

[Rafael J. Wysocki]

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

Debug messages from the system suspend/hibernation infrastructure can
fill up the entire kernel log buffer in some cases and anyway they
are only useful for debugging.  They depend on CONFIG_PM_DEBUG, but
that is set as a rule as some generally useful diagnostic facilities
depend on it too.

For this reason, avoid printing those messages by default, but make
it possible to turn them on as needed with the help of a new sysfs
attribute under /sys/power/.

Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
---
 Documentation/ABI/testing/sysfs-power |   12 +++++++
 drivers/base/power/main.c             |   12 ++-----
 include/linux/suspend.h               |    6 +++
 kernel/power/hibernate.c              |   24 +++++++--------
 kernel/power/main.c                   |   52 ++++++++++++++++++++++++++++++++++
 kernel/power/suspend.c                |   10 +++---
 6 files changed, 91 insertions(+), 25 deletions(-)

Index: linux-pm/include/linux/suspend.h
===================================================================
--- linux-pm.orig/include/linux/suspend.h
+++ linux-pm/include/linux/suspend.h
@@ -491,8 +491,14 @@ 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, ...);
 #else
 #define pm_print_times_enabled	(false)
+
+#include <linux/printk.h>
+
+#define pm_pr_dbg(fmt, ...) \
+	no_printk(KERN_DEBUG fmt, ##__VA_ARGS__)
 #endif
 
 #ifdef CONFIG_PM_AUTOSLEEP
Index: linux-pm/kernel/power/main.c
===================================================================
--- linux-pm.orig/kernel/power/main.c
+++ linux-pm/kernel/power/main.c
@@ -361,6 +361,57 @@ static ssize_t pm_wakeup_irq_show(struct
 
 power_attr_ro(pm_wakeup_irq);
 
+static bool pm_debug_messages_on __read_mostly;
+
+static ssize_t pm_debug_messages_show(struct kobject *kobj,
+				      struct kobj_attribute *attr, char *buf)
+{
+	return sprintf(buf, "%d\n", pm_debug_messages_on);
+}
+
+static ssize_t pm_debug_messages_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_debug_messages_on = !!val;
+	return n;
+}
+
+power_attr(pm_debug_messages);
+
+/**
+ * pm_pr_dbg - Print a suspend debug message to the kernel log.
+ * @fmt: Message format.
+ *
+ * The message will be emitted if enabled through the pm_debug_messages
+ * sysfs attribute.
+ */
+void pm_pr_dbg(const char *fmt, ...)
+{
+	struct va_format vaf;
+	va_list args;
+
+	if (!pm_debug_messages_on)
+		return;
+
+	va_start(args, fmt);
+
+	vaf.fmt = fmt;
+	vaf.va = &args;
+
+	printk(KERN_DEBUG "PM: %pV", &vaf);
+
+	va_end(args);
+}
+
 #else /* !CONFIG_PM_SLEEP_DEBUG */
 static inline void pm_print_times_init(void) {}
 #endif /* CONFIG_PM_SLEEP_DEBUG */
@@ -697,6 +748,7 @@ static struct attribute * g[] = {
 #ifdef CONFIG_PM_SLEEP_DEBUG
 	&pm_print_times_attr.attr,
 	&pm_wakeup_irq_attr.attr,
+	&pm_debug_messages_attr.attr,
 #endif
 #endif
 #ifdef CONFIG_FREEZER
Index: linux-pm/kernel/power/hibernate.c
===================================================================
--- linux-pm.orig/kernel/power/hibernate.c
+++ linux-pm/kernel/power/hibernate.c
@@ -651,7 +651,7 @@ static int load_image_and_restore(void)
 	int error;
 	unsigned int flags;
 
-	pr_debug("Loading hibernation image.\n");
+	pm_pr_dbg("Loading hibernation image.\n");
 
 	lock_device_hotplug();
 	error = create_basic_memory_bitmaps();
@@ -681,7 +681,7 @@ int hibernate(void)
 	bool snapshot_test = false;
 
 	if (!hibernation_available()) {
-		pr_debug("Hibernation not available.\n");
+		pm_pr_dbg("Hibernation not available.\n");
 		return -EPERM;
 	}
 
@@ -727,7 +727,7 @@ int hibernate(void)
 		else
 		        flags |= SF_CRC32_MODE;
 
-		pr_debug("Writing image.\n");
+		pm_pr_dbg("Writing image.\n");
 		error = swsusp_write(flags);
 		swsusp_free();
 		if (!error) {
@@ -739,7 +739,7 @@ int hibernate(void)
 		in_suspend = 0;
 		pm_restore_gfp_mask();
 	} else {
-		pr_debug("Image restored successfully.\n");
+		pm_pr_dbg("Image restored successfully.\n");
 	}
 
  Free_bitmaps:
@@ -747,7 +747,7 @@ int hibernate(void)
  Thaw:
 	unlock_device_hotplug();
 	if (snapshot_test) {
-		pr_debug("Checking hibernation image\n");
+		pm_pr_dbg("Checking hibernation image\n");
 		error = swsusp_check();
 		if (!error)
 			error = load_image_and_restore();
@@ -811,7 +811,7 @@ static int software_resume(void)
 		goto Unlock;
 	}
 
-	pr_debug("Checking hibernation image partition %s\n", resume_file);
+	pm_pr_dbg("Checking hibernation image partition %s\n", resume_file);
 
 	if (resume_delay) {
 		pr_info("Waiting %dsec before reading resume device ...\n",
@@ -853,10 +853,10 @@ static int software_resume(void)
 	}
 
  Check_image:
-	pr_debug("Hibernation image partition %d:%d present\n",
+	pm_pr_dbg("Hibernation image partition %d:%d present\n",
 		MAJOR(swsusp_resume_device), MINOR(swsusp_resume_device));
 
-	pr_debug("Looking for hibernation image.\n");
+	pm_pr_dbg("Looking for hibernation image.\n");
 	error = swsusp_check();
 	if (error)
 		goto Unlock;
@@ -875,7 +875,7 @@ static int software_resume(void)
 		goto Close_Finish;
 	}
 
-	pr_debug("Preparing processes for restore.\n");
+	pm_pr_dbg("Preparing processes for restore.\n");
 	error = freeze_processes();
 	if (error)
 		goto Close_Finish;
@@ -888,7 +888,7 @@ static int software_resume(void)
 	/* For success case, the suspend path will release the lock */
  Unlock:
 	mutex_unlock(&pm_mutex);
-	pr_debug("Hibernation image not present or could not be loaded.\n");
+	pm_pr_dbg("Hibernation image not present or could not be loaded.\n");
 	return error;
  Close_Finish:
 	swsusp_close(FMODE_READ);
@@ -1012,8 +1012,8 @@ static ssize_t disk_store(struct kobject
 		error = -EINVAL;
 
 	if (!error)
-		pr_debug("Hibernation mode set to '%s'\n",
-			 hibernation_modes[mode]);
+		pm_pr_dbg("Hibernation mode set to '%s'\n",
+			       hibernation_modes[mode]);
 	unlock_system_sleep();
 	return error ? error : n;
 }
Index: linux-pm/kernel/power/suspend.c
===================================================================
--- linux-pm.orig/kernel/power/suspend.c
+++ linux-pm/kernel/power/suspend.c
@@ -104,7 +104,7 @@ static void freeze_enter(void)
 
 static void s2idle_loop(void)
 {
-	pr_debug("PM: suspend-to-idle\n");
+	pm_pr_dbg("suspend-to-idle\n");
 
 	do {
 		freeze_enter();
@@ -122,7 +122,7 @@ static void s2idle_loop(void)
 		pm_wakeup_clear(false);
 	} while (!dpm_suspend_noirq(PMSG_SUSPEND));
 
-	pr_debug("PM: resume from suspend-to-idle\n");
+	pm_pr_dbg("resume from suspend-to-idle\n");
 }
 
 void freeze_wake(void)
@@ -542,7 +542,7 @@ static int enter_state(suspend_state_t s
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 #endif
 
-	pr_debug("PM: Preparing system for sleep (%s)\n", pm_states[state]);
+	pm_pr_dbg("Preparing system for sleep (%s)\n", pm_states[state]);
 	pm_suspend_clear_flags();
 	error = suspend_prepare(state);
 	if (error)
@@ -552,13 +552,13 @@ static int enter_state(suspend_state_t s
 		goto Finish;
 
 	trace_suspend_resume(TPS("suspend_enter"), state, false);
-	pr_debug("PM: Suspending system (%s)\n", pm_states[state]);
+	pm_pr_dbg("Suspending system (%s)\n", pm_states[state]);
 	pm_restrict_gfp_mask();
 	error = suspend_devices_and_enter(state);
 	pm_restore_gfp_mask();
 
  Finish:
-	pr_debug("PM: Finishing wakeup.\n");
+	pm_pr_dbg("Finishing wakeup.\n");
 	suspend_finish();
  Unlock:
 	mutex_unlock(&pm_mutex);
Index: linux-pm/Documentation/ABI/testing/sysfs-power
===================================================================
--- linux-pm.orig/Documentation/ABI/testing/sysfs-power
+++ linux-pm/Documentation/ABI/testing/sysfs-power
@@ -273,3 +273,15 @@ Description:
 
 		This output is useful for system wakeup diagnostics of spurious
 		wakeup interrupts.
+
+What:		/sys/power/pm_debug_messages
+Date:		July 2017
+Contact:	Rafael J. Wysocki <rjw@rjwysocki.net>
+Description:
+		The /sys/power/pm_debug_messages file controls the printing
+		of debug messages from the system suspend/hiberbation
+		infrastructure to the kernel log.
+
+		Writing a "1" to this file enables the debug messages and
+		writing a "0" (default) to it disables them.  Reads from
+		this file return the current value.
Index: linux-pm/drivers/base/power/main.c
===================================================================
--- linux-pm.orig/drivers/base/power/main.c
+++ linux-pm/drivers/base/power/main.c
@@ -418,7 +418,6 @@ static void pm_dev_err(struct device *de
 		dev_name(dev), pm_verb(state.event), info, error);
 }
 
-#ifdef CONFIG_PM_DEBUG
 static void dpm_show_time(ktime_t starttime, pm_message_t state,
 			  const char *info)
 {
@@ -432,14 +431,11 @@ static void dpm_show_time(ktime_t startt
 	usecs = usecs64;
 	if (usecs == 0)
 		usecs = 1;
-	pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs\n",
-		info ?: "", info ? " " : "", pm_verb(state.event),
-		usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
+
+	pm_pr_dbg("%s%s%s of devices complete after %ld.%03ld msecs\n",
+		  info ?: "", info ? " " : "", pm_verb(state.event),
+		  usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
 }
-#else
-static inline void dpm_show_time(ktime_t starttime, pm_message_t state,
-				 const char *info) {}
-#endif /* CONFIG_PM_DEBUG */
 
 static int dpm_run_callback(pm_callback_t cb, struct device *dev,
 			    pm_message_t state, const char *info)

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

[Rafael J. Wysocki]

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;
 }

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

[Rafael J. Wysocki]

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);
 }
 

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

[Rafael J. Wysocki]

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);

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

[Mark Salyzyn]

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

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

[Rafael J. Wysocki]

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

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

[Rafael J. Wysocki]

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);
>  }
>  
>