kernel: power: Neaten PM: logging

PATCH In review Joe Perches 3 participants 13 messages Jun 4, 2015 – Jun 9, 2015

Subsystems (2)

Suspend to RAM Hibernation

lore

Share & tools

lore

Joe Perches

author

2015-06-04 18:36 UTC #0 lore raw

cover kernel: power: Neaten PM: logging

Joe Perches (6):
power: hibernate: Use separate messages for "Syncing filesystems"
power: process: Standardize "freezing process" messages
power: suspend: Standardize "Syncing filesystems" messages
power: swap: Standardize "Image <loading/saving>" messages
power: user: Standardize "Syncing filesystems ..." message
power: Use pr_fmt and pr_<level>

 kernel/power/hibernate.c    |  61 ++++++++++-----------
 kernel/power/main.c         |   6 +-
 kernel/power/process.c      |  54 +++++++++---------
 kernel/power/qos.c          |   6 +-
 kernel/power/snapshot.c     |  38 ++++++-------
 kernel/power/suspend.c      |  29 +++++-----
 kernel/power/suspend_test.c |  44 ++++++---------
 kernel/power/swap.c         | 131 ++++++++++++++++++++------------------------
 kernel/power/user.c         |   6 +-
 9 files changed, 178 insertions(+), 197 deletions(-)

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #1 lore raw

PATCH 1/6 power: hibernate: Use separate messages for "Syncing filesystems"

Add the ability to see how long it takes to sync the filesystems via the printk time mechanism.

Start to standardize the printk "PM: doing something...done" messages on two separate lines.

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/hibernate.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/power/hibernate.c +2 -2

index 2329daa..2466d78 100644
@@ -663,9 +663,9 @@ int hibernate(void)
 	if (error)
 		goto Exit;
 
-	printk(KERN_INFO "PM: Syncing filesystems ... ");
+	printk(KERN_INFO "PM: Syncing filesystems ...\n");
 	sys_sync();
-	printk("done.\n");
+	printk(KERN_INFO "PM: Syncing filesystems: done\n");
 
 	error = freeze_processes();
 	if (error)

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #5 lore raw

PATCH 2/6 power: process: Standardize "freezing process" messages

In reply to Joe Perches

Always emit the "freezing ... processes" on 2 separate lines so that these messages can't be interleaved.

Start to standardize the printk "PM: doing something...done" messages on two separate lines.

Miscellanea:

o Add an argument for the elapsed time to try_to_freeze_tasks.
o Remove some trailing whitespace

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/process.c | 53 +++++++++++++++++++++++++-------------------------
 1 file changed, 26 insertions(+), 27 deletions(-)

kernel/power/process.c +26 ~~-27~~

index 564f786..f072ae6 100644
@@ -1,5 +1,5 @@
 /*
- * drivers/power/process.c - Functions for starting/stopping processes on 
+ * drivers/power/process.c - Functions for starting/stopping processes on
  *                           suspend transitions.
  *
  * Originally from swsusp.

@@ -19,12 +19,12 @@
 #include <linux/kmod.h>
 #include <trace/events/power.h>
 
-/* 
+/*
  * Timeout for stopping processes
  */
 unsigned int __read_mostly freeze_timeout_msecs = 20 * MSEC_PER_SEC;
 
-static int try_to_freeze_tasks(bool user_only)
+static int try_to_freeze_tasks(bool user_only, unsigned int *elapsed_msecs)
 {
 	struct task_struct *g, *p;
 	unsigned long end_time;

@@ -32,7 +32,6 @@ static int try_to_freeze_tasks(bool user_only)
 	bool wq_busy = false;
 	struct timeval start, end;
 	u64 elapsed_msecs64;
-	unsigned int elapsed_msecs;
 	bool wakeup = false;
 	int sleep_usecs = USEC_PER_MSEC;

@@ -81,14 +80,12 @@ static int try_to_freeze_tasks(bool user_only)
 	do_gettimeofday(&end);
 	elapsed_msecs64 = timeval_to_ns(&end) - timeval_to_ns(&start);
 	do_div(elapsed_msecs64, NSEC_PER_MSEC);
-	elapsed_msecs = elapsed_msecs64;
+	*elapsed_msecs = elapsed_msecs64;
 
 	if (todo) {
-		pr_cont("\n");
-		pr_err("Freezing of tasks %s after %d.%03d seconds "
-		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
+		pr_err("Freezing of tasks %s after %d.%03d seconds (%d tasks refusing to freeze, wq_busy=%d)\n",
 		       wakeup ? "aborted" : "failed",
-		       elapsed_msecs / 1000, elapsed_msecs % 1000,
+		       *elapsed_msecs / 1000, *elapsed_msecs % 1000,
 		       todo - wq_busy, wq_busy);
 
 		if (!wakeup) {

@@ -100,9 +97,6 @@ static int try_to_freeze_tasks(bool user_only)
 			}
 			read_unlock(&tasklist_lock);
 		}
-	} else {
-		pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
-			elapsed_msecs % 1000);
 	}
 
 	return todo ? -EBUSY : 0;

@@ -118,6 +112,7 @@ static int try_to_freeze_tasks(bool user_only)
 int freeze_processes(void)
 {
 	int error;
+	unsigned int msecs;
 
 	error = __usermodehelper_disable(UMH_FREEZING);
 	if (error)

@@ -130,18 +125,22 @@ int freeze_processes(void)
 		atomic_inc(&system_freezing_cnt);
 
 	pm_wakeup_clear();
-	pr_info("Freezing user space processes ... ");
+	pr_info("Freezing user space processes...\n");
 	pm_freezing = true;
-	error = try_to_freeze_tasks(true);
-	if (!error) {
+	error = try_to_freeze_tasks(true, &msecs);
+	if (error < 0) {
+		pr_info("Freezing user space processes: done (error: %d)\n",
+			error);
+	} else {
 		__usermodehelper_set_disable_depth(UMH_DISABLED);
-		pr_cont("done.");
+		pr_info("Freezing user space processes: done (elapsed %u.%03u seconds)\n",
+			msecs / 1000, msecs % 1000);
 	}
-	pr_cont("\n");
+
 	BUG_ON(in_atomic());
 
 	/*
-	 * Now that the whole userspace is frozen we need to disbale
+	 * Now that the whole userspace is frozen we need to disable
 	 * the OOM killer to disallow any further interference with
 	 * killable tasks.
 	 */

@@ -164,15 +163,15 @@ int freeze_processes(void)
 int freeze_kernel_threads(void)
 {
 	int error;
+	unsigned int msecs;
 
-	pr_info("Freezing remaining freezable tasks ... ");
+	pr_info("Freezing remaining freezable tasks...\n");
 
 	pm_nosig_freezing = true;
-	error = try_to_freeze_tasks(false);
-	if (!error)
-		pr_cont("done.");
+	error = try_to_freeze_tasks(false, &msecs);
+	if (error >= 0)
+		pr_info("Freezing remaining freezable tasks: done\n");
 
-	pr_cont("\n");
 	BUG_ON(in_atomic());
 
 	if (error)

@@ -193,7 +192,7 @@ void thaw_processes(void)
 
 	oom_killer_enable();
 
-	pr_info("Restarting tasks ... ");
+	pr_info("Restarting tasks...\n");
 
 	__usermodehelper_set_disable_depth(UMH_FREEZING);
 	thaw_workqueues();

@@ -212,7 +211,7 @@ void thaw_processes(void)
 	usermodehelper_enable();
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info("Restarting tasks: done\n");
 	trace_suspend_resume(TPS("thaw_processes"), 0, false);
 }

@@ -221,7 +220,7 @@ void thaw_kernel_threads(void)
 	struct task_struct *g, *p;
 
 	pm_nosig_freezing = false;
-	pr_info("Restarting kernel threads ... ");
+	pr_info("Restarting kernel threads...\n");
 
 	thaw_workqueues();

@@ -233,5 +232,5 @@ void thaw_kernel_threads(void)
 	read_unlock(&tasklist_lock);
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info("Restarting kernel threads: done\n");
 }

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #6 lore raw

PATCH 3/6 power: suspend: Standardize "Syncing filesystems" messages

In reply to Joe Perches

Always emit the "Syncing filesystems" on 2 separate lines so that these messages can't be interleaved.

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/suspend.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/power/suspend.c +2 -2

index 53266b7..c3fec97 100644
@@ -485,9 +485,9 @@ static int enter_state(suspend_state_t state)
 		freeze_begin();
 
 	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	printk(KERN_INFO "PM: Syncing filesystems ... ");
+	printk(KERN_INFO "PM: Syncing filesystems...\n");
 	sys_sync();
-	printk("done.\n");
+	printk(KERN_INFO "PM: Syncing filesystems: done\n");
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 
 	pr_debug("PM: Preparing system for sleep (%s)\n", pm_states[state]);

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #7 lore raw

PATCH 4/6 power: swap: Standardize "Image <loading/saving>" messages

In reply to Joe Perches

Standardize "Image <...>" messages

Always emit the "Image <loading/saving>" messages on 2 separate lines so that these messages can't be interleaved.

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/swap.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

kernel/power/swap.c +3 -3

index 2f30ca9..7aa2635 100644
@@ -552,7 +552,7 @@ static int save_image(struct swap_map_handle *handle,
 	if (!ret)
 		ret = err2;
 	if (!ret)
-		printk(KERN_INFO "PM: Image saving done.\n");
+		printk(KERN_INFO "PM: Image saving: done\n");
 	swsusp_show_speed(start, stop, nr_to_write, "Wrote");
 	return ret;
 }

@@ -843,7 +843,7 @@ out_finish:
 	if (!ret)
 		ret = err2;
 	if (!ret)
-		printk(KERN_INFO "PM: Image saving done.\n");
+		printk(KERN_INFO "PM: Image saving: done\n");
 	swsusp_show_speed(start, stop, nr_to_write, "Wrote");
 out_clean:
 	if (crc) {

@@ -1081,7 +1081,7 @@ static int load_image(struct swap_map_handle *handle,
 	if (!ret)
 		ret = err2;
 	if (!ret) {
-		printk(KERN_INFO "PM: Image loading done.\n");
+		printk(KERN_INFO "PM: Image loading: done\n");
 		snapshot_write_finalize(snapshot);
 		if (!snapshot_image_loaded(snapshot))
 			ret = -ENODATA;

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #8 lore raw

PATCH 5/6 power: user: Standardize "Syncing filesystems ..." message

In reply to Joe Perches

Instead of a two individual printks that would generally be emitted on a single line, emit 2 lines to make the start and end of the synchronization more easily timeable.

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/user.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/power/user.c +2 -2

index 526e891..e22f6ad 100644
@@ -221,9 +221,9 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
+		printk("Syncing filesystems ...\n");
 		sys_sync();
-		printk("done.\n");
+		printk("Syncing filesystems: done\n");
 
 		error = freeze_processes();
 		if (error)

Signature · 1 line

2.1.2

Joe Perches

author

2015-06-04 18:36 UTC #12 lore raw

PATCH 6/6 power: Use pr_fmt and pr_<level>

In reply to Joe Perches

Use a more current logging style.

Some of these messages did not use prefixes so use pr_fmt to prefix every message with "PM: "

In snapshot.c, one of the messages was a single line emited with KERN_CONT. Use 2 lines so the time to allocate memory can be more easily known by printk/dmesg timestamps.

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/hibernate.c    |  61 ++++++++++-----------
 kernel/power/main.c         |   6 +-
 kernel/power/process.c      |   1 +
 kernel/power/qos.c          |   6 +-
 kernel/power/snapshot.c     |  38 ++++++-------
 kernel/power/suspend.c      |  29 +++++-----
 kernel/power/suspend_test.c |  44 ++++++---------
 kernel/power/swap.c         | 131 ++++++++++++++++++++------------------------
 kernel/power/user.c         |   6 +-
 9 files changed, 152 insertions(+), 170 deletions(-)

kernel/power/hibernate.c +29 ~~-32~~

index 2466d78..71f9904 100644
@@ -10,6 +10,8 @@
  * This file is released under the GPLv2.
  */
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/export.h>
 #include <linux/suspend.h>
 #include <linux/syscalls.h>

@@ -103,7 +105,7 @@ EXPORT_SYMBOL(system_entering_hibernation);
 #ifdef CONFIG_PM_DEBUG
 static void hibernation_debug_sleep(void)
 {
-	printk(KERN_INFO "hibernation debug: Waiting for 5 seconds.\n");
+	pr_info("%s: Waiting for 5 seconds\n", __func__);
 	mdelay(5000);
 }

@@ -249,10 +251,10 @@ void swsusp_show_speed(ktime_t start, ktime_t stop,
 		centisecs = 1;	/* avoid div-by-zero */
 	k = nr_pages * (PAGE_SIZE / 1024);
 	kps = (k * 100) / centisecs;
-	printk(KERN_INFO "PM: %s %u kbytes in %u.%02u seconds (%u.%02u MB/s)\n",
-			msg, k,
-			centisecs / 100, centisecs % 100,
-			kps / 1000, (kps % 1000) / 10);
+	pr_info("%s %u kbytes in %u.%02u seconds (%u.%02u MB/s)\n",
+		msg, k,
+		centisecs / 100, centisecs % 100,
+		kps / 1000, (kps % 1000) / 10);
 }
 
 /**

@@ -270,8 +272,7 @@ static int create_image(int platform_mode)
 
 	error = dpm_suspend_end(PMSG_FREEZE);
 	if (error) {
-		printk(KERN_ERR "PM: Some devices failed to power down, "
-			"aborting hibernation\n");
+		pr_err("Some devices failed to power down, aborting hibernation\n");
 		return error;
 	}

@@ -287,8 +288,7 @@ static int create_image(int platform_mode)
 
 	error = syscore_suspend();
 	if (error) {
-		printk(KERN_ERR "PM: Some system devices failed to power down, "
-			"aborting hibernation\n");
+		pr_err("Some system devices failed to power down, aborting hibernation\n");
 		goto Enable_irqs;
 	}

@@ -301,8 +301,7 @@ static int create_image(int platform_mode)
 	error = swsusp_arch_suspend();
 	trace_suspend_resume(TPS("machine_suspend"), PM_EVENT_HIBERNATE, false);
 	if (error)
-		printk(KERN_ERR "PM: Error %d creating hibernation image\n",
-			error);
+		pr_err("Error %d creating hibernation image\n", error);
 	/* Restore control flow magically appears here */
 	restore_processor_state();
 	if (!in_suspend)

@@ -423,8 +422,7 @@ static int resume_target_kernel(bool platform_mode)
 
 	error = dpm_suspend_end(PMSG_QUIESCE);
 	if (error) {
-		printk(KERN_ERR "PM: Some devices failed to power down, "
-			"aborting resume\n");
+		pr_err("Some devices failed to power down, aborting resume\n");
 		return error;
 	}

@@ -624,8 +622,7 @@ static void power_down(void)
 		 */
 		error = swsusp_unmark();
 		if (error)
-			printk(KERN_ERR "PM: Swap will be unusable! "
-			                "Try swapon -a.\n");
+			pr_err("Swap will be unusable! Try 'swapon -a'\n");
 		return;
 #endif
 	}

@@ -634,7 +631,7 @@ static void power_down(void)
 	 * Valid image is on the disk, if we continue we risk serious data
 	 * corruption after resume.
 	 */
-	printk(KERN_CRIT "PM: Please power down manually\n");
+	pr_crit("Please power down manually\n");
 	while (1)
 		cpu_relax();
 }

@@ -647,7 +644,7 @@ int hibernate(void)
 	int error;
 
 	if (!hibernation_available()) {
-		pr_debug("PM: Hibernation not available.\n");
+		pr_debug("Hibernation not available\n");
 		return -EPERM;
 	}

@@ -663,9 +660,9 @@ int hibernate(void)
 	if (error)
 		goto Exit;
 
-	printk(KERN_INFO "PM: Syncing filesystems ...\n");
+	pr_info("Syncing filesystems...\n");
 	sys_sync();
-	printk(KERN_INFO "PM: Syncing filesystems: done\n");
+	pr_info("Syncing filesystems: done\n");
 
 	error = freeze_processes();
 	if (error)

@@ -691,7 +688,7 @@ int hibernate(void)
 		else
 		        flags |= SF_CRC32_MODE;
 
-		pr_debug("PM: writing image.\n");
+		pr_debug("writing image\n");
 		error = swsusp_write(flags);
 		swsusp_free();
 		if (!error)

@@ -699,7 +696,7 @@ int hibernate(void)
 		in_suspend = 0;
 		pm_restore_gfp_mask();
 	} else {
-		pr_debug("PM: Image restored successfully.\n");
+		pr_debug("Image restored successfully\n");
 	}
 
  Free_bitmaps:

@@ -766,10 +763,10 @@ static int software_resume(void)
 		goto Unlock;
 	}
 
-	pr_debug("PM: Checking hibernation image partition %s\n", resume_file);
+	pr_debug("Checking hibernation image partition %s\n", resume_file);
 
 	if (resume_delay) {
-		printk(KERN_INFO "Waiting %dsec before reading resume device...\n",
+		pr_info("Waiting %dsec before reading resume device...\n",
 			resume_delay);
 		ssleep(resume_delay);
 	}

@@ -808,10 +805,10 @@ static int software_resume(void)
 	}
 
  Check_image:
-	pr_debug("PM: Hibernation image partition %d:%d present\n",
-		MAJOR(swsusp_resume_device), MINOR(swsusp_resume_device));
+	pr_debug("Hibernation image partition %d:%d present\n",
+		 MAJOR(swsusp_resume_device), MINOR(swsusp_resume_device));
 
-	pr_debug("PM: Looking for hibernation image.\n");
+	pr_debug("Looking for hibernation image\n");
 	error = swsusp_check();
 	if (error)
 		goto Unlock;

@@ -828,12 +825,12 @@ static int software_resume(void)
 	if (error)
 		goto Close_Finish;
 
-	pr_debug("PM: Preparing processes for restore.\n");
+	pr_debug("Preparing processes for restore\n");
 	error = freeze_processes();
 	if (error)
 		goto Close_Finish;
 
-	pr_debug("PM: Loading hibernation image.\n");
+	pr_debug("Loading hibernation image\n");
 
 	lock_device_hotplug();
 	error = create_basic_memory_bitmaps();

@@ -845,7 +842,7 @@ static int software_resume(void)
 	if (!error)
 		hibernation_restore(flags & SF_PLATFORM_MODE);
 
-	printk(KERN_ERR "PM: Failed to load hibernation image, recovering.\n");
+	pr_err("Failed to load hibernation image, recovering\n");
 	swsusp_free();
 	free_basic_memory_bitmaps();
  Thaw:

@@ -858,7 +855,7 @@ static int software_resume(void)
 	/* For success case, the suspend path will release the lock */
  Unlock:
 	mutex_unlock(&pm_mutex);
-	pr_debug("PM: Hibernation image not present or could not be loaded.\n");
+	pr_debug("Hibernation image not present or could not be loaded\n");
 	return error;
  Close_Finish:
 	swsusp_close(FMODE_READ);

@@ -979,7 +976,7 @@ static ssize_t disk_store(struct kobject *kobj, struct kobj_attribute *attr,
 		error = -EINVAL;
 
 	if (!error)
-		pr_debug("PM: Hibernation mode set to '%s'\n",
+		pr_debug("Hibernation mode set to '%s'\n",
 			 hibernation_modes[mode]);
 	unlock_system_sleep();
 	return error ? error : n;

@@ -1015,7 +1012,7 @@ static ssize_t resume_store(struct kobject *kobj, struct kobj_attribute *attr,
 	lock_system_sleep();
 	swsusp_resume_device = res;
 	unlock_system_sleep();
-	printk(KERN_INFO "PM: Starting manual resume from disk\n");
+	pr_info("Starting manual resume from disk\n");
 	noresume = 0;
 	software_resume();
 	return n;

kernel/power/main.c +4 -2

index 63d395b..27d76b4 100644
@@ -8,6 +8,8 @@
  *
  */
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/export.h>
 #include <linux/kobject.h>
 #include <linux/string.h>

@@ -531,8 +533,8 @@ pm_trace_store(struct kobject *kobj, struct kobj_attribute *attr,
 	if (sscanf(buf, "%d", &val) == 1) {
 		pm_trace_enabled = !!val;
 		if (pm_trace_enabled) {
-			pr_warn("PM: Enabling pm_trace changes system date and time during resume.\n"
-				"PM: Correct system time has to be restored manually after resume.\n");
+			pr_warn("Enabling pm_trace changes system date and time during resume\n");
+			pr_warn("Correct system time has to be restored manually after resume\n");
 		}
 		return n;
 	}

kernel/power/process.c +1 -0

index f072ae6..749d88c 100644
@@ -5,6 +5,7 @@
  * Originally from swsusp.
  */
 
+#define pr_fmt(fmt) "PM: " fmt
 
 #undef DEBUG

kernel/power/qos.c +4 -2

index 97b0df71..531f5ef 100644
@@ -29,6 +29,8 @@
 
 /*#define DEBUG*/
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/pm_qos.h>
 #include <linux/sched.h>
 #include <linux/spinlock.h>

@@ -701,8 +703,8 @@ static int __init pm_qos_power_init(void)
 	for (i = PM_QOS_CPU_DMA_LATENCY; i < PM_QOS_NUM_CLASSES; i++) {
 		ret = register_pm_qos_misc(pm_qos_array[i], d);
 		if (ret < 0) {
-			printk(KERN_ERR "pm_qos_param: %s setup failed\n",
-			       pm_qos_array[i]->name);
+			pr_err("%s: %s setup failed\n",
+			       __func__, pm_qos_array[i]->name);
 			return ret;
 		}
 	}

kernel/power/snapshot.c +19 ~~-19~~

index 5235dd4..0fd7ad8 100644
@@ -10,6 +10,8 @@
  *
  */
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/version.h>
 #include <linux/module.h>
 #include <linux/mm.h>

@@ -867,7 +869,7 @@ __register_nosave_region(unsigned long start_pfn, unsigned long end_pfn,
 	region->end_pfn = end_pfn;
 	list_add_tail(&region->list, &nosave_regions);
  Report:
-	printk(KERN_INFO "PM: Registered nosave memory: [mem %#010llx-%#010llx]\n",
+	pr_info("Registered nosave memory: [mem %#010llx-%#010llx]\n",
 		(unsigned long long) start_pfn << PAGE_SHIFT,
 		((unsigned long long) end_pfn << PAGE_SHIFT) - 1);
 }

@@ -937,10 +939,9 @@ static void mark_nosave_pages(struct memory_bitmap *bm)
 	list_for_each_entry(region, &nosave_regions, list) {
 		unsigned long pfn;
 
-		pr_debug("PM: Marking nosave pages: [mem %#010llx-%#010llx]\n",
-			 (unsigned long long) region->start_pfn << PAGE_SHIFT,
-			 ((unsigned long long) region->end_pfn << PAGE_SHIFT)
-				- 1);
+		pr_debug("Marking nosave pages: [mem %#010llx-%#010llx]\n",
+			 (unsigned long long)region->start_pfn << PAGE_SHIFT,
+			 ((unsigned long long)region->end_pfn << PAGE_SHIFT) - 1);
 
 		for (pfn = region->start_pfn; pfn < region->end_pfn; pfn++)
 			if (pfn_valid(pfn)) {

@@ -993,7 +994,7 @@ int create_basic_memory_bitmaps(void)
 	free_pages_map = bm2;
 	mark_nosave_pages(forbidden_pages_map);
 
-	pr_debug("PM: Basic memory bitmaps created\n");
+	pr_debug("Basic memory bitmaps created\n");
 
 	return 0;

@@ -1029,7 +1030,7 @@ void free_basic_memory_bitmaps(void)
 	memory_bm_free(bm2, PG_UNSAFE_CLEAR);
 	kfree(bm2);
 
-	pr_debug("PM: Basic memory bitmaps freed\n");
+	pr_debug("Basic memory bitmaps freed\n");
 }
 
 /**

@@ -1564,7 +1565,7 @@ int hibernate_preallocate_memory(void)
 	ktime_t start, stop;
 	int error;
 
-	printk(KERN_INFO "PM: Preallocating image memory... ");
+	pr_info("Preallocating image memory...\n");
 	start = ktime_get();
 
 	error = memory_bm_create(&orig_bm, GFP_IMAGE, PG_ANY);

@@ -1695,13 +1696,13 @@ int hibernate_preallocate_memory(void)
 
  out:
 	stop = ktime_get();
-	printk(KERN_CONT "done (allocated %lu pages)\n", pages);
+	pr_info("Preallocating image memory: done (allocated %lu pages)\n",
+		pages);
 	swsusp_show_speed(start, stop, pages, "Allocated");
 
 	return 0;
 
  err_out:
-	printk(KERN_CONT "\n");
 	swsusp_free();
 	return -ENOMEM;
 }

@@ -1743,8 +1744,8 @@ static int enough_free_mem(unsigned int nr_pages, unsigned int nr_highmem)
 			free += zone_page_state(zone, NR_FREE_PAGES);
 
 	nr_pages += count_pages_for_highmem(nr_highmem);
-	pr_debug("PM: Normal pages needed: %u + %u, available pages: %u\n",
-		nr_pages, PAGES_FOR_IO, free);
+	pr_debug("Normal pages needed: %u + %u, available pages: %u\n",
+		 nr_pages, PAGES_FOR_IO, free);
 
 	return free > nr_pages + PAGES_FOR_IO;
 }

@@ -1838,20 +1839,20 @@ asmlinkage __visible int swsusp_save(void)
 {
 	unsigned int nr_pages, nr_highmem;
 
-	printk(KERN_INFO "PM: Creating hibernation image:\n");
+	pr_info("Creating hibernation image\n");
 
 	drain_local_pages(NULL);
 	nr_pages = count_data_pages();
 	nr_highmem = count_highmem_pages();
-	printk(KERN_INFO "PM: Need to copy %u pages\n", nr_pages + nr_highmem);
+	pr_info("Need to copy %u pages\n", nr_pages + nr_highmem);
 
 	if (!enough_free_mem(nr_pages, nr_highmem)) {
-		printk(KERN_ERR "PM: Not enough free memory\n");
+		pr_err("Not enough free memory\n");
 		return -ENOMEM;
 	}
 
 	if (swsusp_alloc(&orig_bm, &copy_bm, nr_pages, nr_highmem)) {
-		printk(KERN_ERR "PM: Memory allocation failed\n");
+		pr_err("Memory allocation failed\n");
 		return -ENOMEM;
 	}

@@ -1871,8 +1872,7 @@ asmlinkage __visible int swsusp_save(void)
 	nr_copy_pages = nr_pages;
 	nr_meta_pages = DIV_ROUND_UP(nr_pages * sizeof(long), PAGE_SIZE);
 
-	printk(KERN_INFO "PM: Hibernation image created (%d pages copied)\n",
-		nr_pages);
+	pr_info("Hibernation image created (%d pages copied)\n", nr_pages);
 
 	return 0;
 }

@@ -2056,7 +2056,7 @@ static int check_header(struct swsusp_info *info)
 	if (!reason && info->num_physpages != get_num_physpages())
 		reason = "memory size";
 	if (reason) {
-		printk(KERN_ERR "PM: Image mismatch: %s\n", reason);
+		pr_err("Image mismatch: %s\n", reason);
 		return -EPERM;
 	}
 	return 0;

kernel/power/suspend.c +15 ~~-14~~

index c3fec97..730506f 100644
@@ -8,6 +8,8 @@
  * This file is released under the GPLv2.
  */
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/string.h>
 #include <linux/delay.h>
 #include <linux/errno.h>

@@ -68,11 +70,11 @@ static void freeze_enter(void)
 
 	/* Push all the CPUs into the idle loop. */
 	wake_up_all_idle_cpus();
-	pr_debug("PM: suspend-to-idle\n");
+	pr_debug("suspend-to-idle\n");
 	/* Make the current CPU wait so it can enter the idle loop too. */
 	wait_event(suspend_freeze_wait_head,
 		   suspend_freeze_state == FREEZE_STATE_WAKE);
-	pr_debug("PM: resume from suspend-to-idle\n");
+	pr_debug("resume from suspend-to-idle\n");
 
 	cpuidle_pause();
 	put_online_cpus();

@@ -245,8 +247,8 @@ static int suspend_test(int level)
 {
 #ifdef CONFIG_PM_DEBUG
 	if (pm_test_level == level) {
-		printk(KERN_INFO "suspend debug: Waiting for %d second(s).\n",
-				pm_test_delay);
+		pr_info("suspend debug: Waiting for %d second(s)\n",
+			pm_test_delay);
 		mdelay(pm_test_delay * 1000);
 		return 1;
 	}

@@ -317,7 +319,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
 
 	error = dpm_suspend_late(PMSG_SUSPEND);
 	if (error) {
-		printk(KERN_ERR "PM: late suspend of devices failed\n");
+		pr_err("late suspend of devices failed\n");
 		goto Platform_finish;
 	}
 	error = platform_suspend_prepare_late(state);

@@ -326,7 +328,7 @@ static int suspend_enter(suspend_state_t state, bool *wakeup)
 
 	error = dpm_suspend_noirq(PMSG_SUSPEND);
 	if (error) {
-		printk(KERN_ERR "PM: noirq suspend of devices failed\n");
+		pr_err("noirq suspend of devices failed\n");
 		goto Platform_early_resume;
 	}
 	error = platform_suspend_prepare_noirq(state);

@@ -413,7 +415,7 @@ int suspend_devices_and_enter(suspend_state_t state)
 	suspend_test_start();
 	error = dpm_suspend_start(PMSG_SUSPEND);
 	if (error) {
-		pr_err("PM: Some devices failed to suspend, or early wake event detected\n");
+		pr_err("Some devices failed to suspend, or early wake event detected\n");
 		goto Recover_platform;
 	}
 	suspend_test_finish("suspend devices");

@@ -470,8 +472,7 @@ static int enter_state(suspend_state_t state)
 	if (state == PM_SUSPEND_FREEZE) {
 #ifdef CONFIG_PM_DEBUG
 		if (pm_test_level != TEST_NONE && pm_test_level <= TEST_CPUS) {
-			pr_warning("PM: Unsupported test mode for suspend to idle,"
-				   "please choose none/freezer/devices/platform.\n");
+			pr_warn("Unsupported test mode for suspend to idle, please choose none/freezer/devices/platform\n");
 			return -EAGAIN;
 		}
 #endif

@@ -485,12 +486,12 @@ static int enter_state(suspend_state_t state)
 		freeze_begin();
 
 	trace_suspend_resume(TPS("sync_filesystems"), 0, true);
-	printk(KERN_INFO "PM: Syncing filesystems...\n");
+	pr_info("Syncing filesystems...\n");
 	sys_sync();
-	printk(KERN_INFO "PM: Syncing filesystems: done\n");
+	pr_info("Syncing filesystems: done\n");
 	trace_suspend_resume(TPS("sync_filesystems"), 0, false);
 
-	pr_debug("PM: Preparing system for sleep (%s)\n", pm_states[state]);
+	pr_debug("Preparing system for sleep (%s)\n", pm_states[state]);
 	error = suspend_prepare(state);
 	if (error)
 		goto Unlock;

@@ -499,13 +500,13 @@ static int enter_state(suspend_state_t state)
 		goto Finish;
 
 	trace_suspend_resume(TPS("suspend_enter"), state, false);
-	pr_debug("PM: Suspending system (%s)\n", pm_states[state]);
+	pr_debug("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");
+	pr_debug("Finishing wakeup\n");
 	suspend_finish();
  Unlock:
 	mutex_unlock(&pm_mutex);

kernel/power/suspend_test.c +18 ~~-26~~

122 lines not on this page · raw message

kernel/power/swap.c +58 ~~-73~~

388 lines not on this page · raw message

kernel/power/user.c +4 -2

index e22f6ad..07dba67 100644
@@ -9,6 +9,8 @@
  *
  */
 
+#define pr_fmt(fmt) "PM: " fmt
+
 #include <linux/suspend.h>
 #include <linux/syscalls.h>
 #include <linux/reboot.h>

@@ -221,9 +223,9 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ...\n");
+		pr_info("Syncing filesystems...\n");
 		sys_sync();
-		printk("Syncing filesystems: done\n");
+		pr_info("Syncing filesystems: done\n");
 
 		error = freeze_processes();
 		if (error)

Signature · 1 line

2.1.2

Pavel Machek

2015-06-05 10:37 UTC #9 lore raw

Re: [PATCH 5/6] power: user: Standardize "Syncing filesystems ..." message

In reply to Joe Perches

Quoted 14 lines · Joe Perches

Instead of a two individual printks that would generally be emitted on a single line, emit 2 lines to make the start and end of the synchronization more easily timeable.
Signed-off-by Joe Perches <[email protected]>
---
 kernel/power/user.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
kernel/power/user.c +0 -0
index 526e891..e22f6ad 100644

kernel/power/user.c static long snapshot_ioctl(struct file *filp, unsigned int cmd, · line 226

Quoted 8 lines

kernel/power/user.c +2 -2

@@ -221,9 +221,9 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
+		printk("Syncing filesystems ...\n");
 		sys_sync();
-		printk("done.\n");
+		printk("Syncing filesystems: done\n");

You converted " ..." -> "..." elsewhere, so why not here?

Is splitting message to two lines a good idea?

Is it time to introduce helper function that does the sync with the printing?

I must say that I'm to a great fan on adding more lines to hibernation output. Eats too much vertical space on screen, etc. Do you see real problems there or are you just trying to "improve" this?

I'm pretty sure sync timing can be easily obtained from other messages around this one...

Pavel

Signature · 2 lines

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

Joe Perches

author

2015-06-05 15:07 UTC #10 lore raw

Re: [PATCH 5/6] power: user: Standardize "Syncing filesystems ..." message

Quoted 4 lines · Pavel Machek

Quoted 3 lines · Joe Perches
Instead of a two individual printks that would generally be emitted on a single line, emit 2 lines to make the start and end of the synchronization more easily timeable.

[]

Quoted 1 line

kernel/power/user.c
Quoted 1 line
kernel/power/user.c +0 -0

[]

Quoted 11 lines

kernel/power/user.c static long snapshot_ioctl(struct file *filp, unsigned int cmd, · line 226
Quoted 9 lines
kernel/power/user.c +2 -2
@@ -221,9 +221,9 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
+		printk("Syncing filesystems ...\n");
 		sys_sync();
-		printk("done.\n");
+		printk("Syncing filesystems: done\n");
You converted " ..." -> "..." elsewhere, so why not here?

Missed that one.

Quoted 1 line

Is splitting message to two lines a good idea?

I think the "done" is unnecessary actually.

As there's no newline on the first, printk is
async and can be interleaved by other threads.

Pavel Machek

2015-06-06 13:36 UTC #11 lore raw

Re: [PATCH 5/6] power: user: Standardize "Syncing filesystems ..." message

Quoted 20 lines · Joe Perches

Quoted 4 lines · Pavel Machek
Quoted 3 lines · Joe Perches
Instead of a two individual printks that would generally be emitted on a single line, emit 2 lines to make the start and end of the synchronization more easily timeable.
[]
Quoted 1 line
kernel/power/user.c
Quoted 1 line
kernel/power/user.c +0 -0
[]
Quoted 11 lines
kernel/power/user.c static long snapshot_ioctl(struct file *filp, unsigned int cmd, · line 226
Quoted 9 lines
kernel/power/user.c +2 -2
@@ -221,9 +221,9 @@ static long snapshot_ioctl(struct file *filp, unsigned int cmd,
 		if (data->frozen)
 			break;
 
-		printk("Syncing filesystems ... ");
+		printk("Syncing filesystems ...\n");
 		sys_sync();
-		printk("done.\n");
+		printk("Syncing filesystems: done\n");
You converted " ..." -> "..." elsewhere, so why not here?

Quoted 5 lines

Missed that one.
Quoted 1 line
Is splitting message to two lines a good idea?
I think the "done" is unnecessary actually.

Well... if it is not neccessary for timing, this change can be safely dropped, as timing will be provided for existing code, too.

Quoted 2 lines

As there's no newline on the first, printk is
async and can be interleaved by other threads.

...which will probably never happen here, due to feezer.

Pavel

Signature · 2 lines

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

Rafael J. Wysocki

2015-06-08 23:09 UTC #2 lore raw

Re: [PATCH 1/6] power: hibernate: Use separate messages for "Syncing filesystems"

In reply to Joe Perches

Quoted 5 lines · Joe Perches

Add the ability to see how long it takes to sync the filesystems via the printk time mechanism.
Start to standardize the printk "PM: doing something...done" messages on two separate lines.

Well, it would be good to say what problem this is attempting to fix.

And while I understand the underlying concern, there is a merit in keeping each of these messages in one line (if everything goes well), so I'm wondering what about printing each of them in one go after the operation with a tail depending on the result? Like

printk(KERN_INFO "PM: Syncing filesystems ... done\n");

on success or

printk(KERN_INFO "PM: Syncing filesystems ... failed\n");

on failure?

Quoted 22 lines

Signed-off-by Joe Perches <[email protected]>

---
 kernel/power/hibernate.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

kernel/power/hibernate.c +2 -2

index 2329daa..2466d78 100644
@@ -663,9 +663,9 @@ int hibernate(void)
 	if (error)
 		goto Exit;
 
-	printk(KERN_INFO "PM: Syncing filesystems ... ");
+	printk(KERN_INFO "PM: Syncing filesystems ...\n");
 	sys_sync();
-	printk("done.\n");
+	printk(KERN_INFO "PM: Syncing filesystems: done\n");
 
 	error = freeze_processes();
 	if (error)

Signature · 2 lines

I speak only for myself.
Rafael J. Wysocki, Intel Open Source Technology Center.

Joe Perches

author

2015-06-08 23:23 UTC #3 lore raw

Re: [PATCH 1/6] power: hibernate: Use separate messages for "Syncing filesystems"

Quoted 14 lines · Rafael J. Wysocki

Quoted 5 lines · Joe Perches
Add the ability to see how long it takes to sync the filesystems via the printk time mechanism.
Start to standardize the printk "PM: doing something...done" messages on two separate lines.
Well, it would be good to say what problem this is attempting to fix.
And while I understand the underlying concern, there is a merit in keeping each of these messages in one line (if everything goes well), so I'm wondering what about printing each of them in one go after the operation with a tail depending on the result? Like

Quoted 7 lines

printk(KERN_INFO "PM: Syncing filesystems ... done\n");
on success or
printk(KERN_INFO "PM: Syncing filesystems ... failed\n");
on failure?

Maybe.

I believe there are multi-second delays possible when syncing the filesystems on things like usb memory sticks.

I think the dmesg line count here isn't particularly important and there's some small value in consistently presenting timing information via dmesg timestamps when using 2 lines.

There's also some small value in patch 6/6 and the consistent prefixing of "PM: " on all these messages.

Pavel Machek

2015-06-09 09:20 UTC #4 lore raw

Re: [PATCH 1/6] power: hibernate: Use separate messages for "Syncing filesystems"

Quoted 23 lines · Joe Perches

Quoted 14 lines · Rafael J. Wysocki
Quoted 5 lines · Joe Perches
Add the ability to see how long it takes to sync the filesystems via the printk time mechanism.
Start to standardize the printk "PM: doing something...done" messages on two separate lines.
Well, it would be good to say what problem this is attempting to fix.
And while I understand the underlying concern, there is a merit in keeping each of these messages in one line (if everything goes well), so I'm wondering what about printing each of them in one go after the operation with a tail depending on the result? Like
Quoted 7 lines
printk(KERN_INFO "PM: Syncing filesystems ... done\n");
on success or
printk(KERN_INFO "PM: Syncing filesystems ... failed\n");
on failure?

Quoted 8 lines

Maybe.
I believe there are multi-second delays possible when syncing the filesystems on things like usb memory sticks.
I think the dmesg line count here isn't particularly important and there's some small value in consistently presenting timing information via dmesg timestamps when using 2 lines.

Hibernation is little special here, because that's what user actually sees, and because message interleaving is extremely unlikely there.

Unless you have a real problem with this, just let it be.
Pavel

Signature · 2 lines

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