[v8] PM: sleep: Expose last succeeded resumed timestamp in sysfs

Commit Message

Masami Hiramatsu (Google) July 2, 2024, 2:24 p.m. UTC

From: Masami Hiramatsu <[e-mail]>

Expose last succeeded resumed timestamp as last_success_resume_time
attribute of suspend_stats in sysfs so that user can use this time
stamp as a reference point of resuming user space.

On some system like the ChromeOS, the system suspend and resume are
controlled by a power management process. The user-space tasks will be
noticed the suspend and the resume signal from it.
To improve the suspend/resume performance and/or to find regressions,
we would like to know how long the resume processes are taken in kernel
and in user-space.
For this purpose, expose the accarate time when the kernel is finished
to resume so that we can distinguish the duration of kernel resume and
user space resume.

This suspend_stats attribute is easy to access and only expose the
timestamp in CLOCK_MONOTONIC. User can find the accarate time when the
kernel finished to resume its drivers/subsystems and start thawing, and
measure the elapsed time from the time when the kernel finished the
resume to a user-space action (e.g. displaying the UI).

Signed-off-by: Masami Hiramatsu (Google) <[e-mail]>
---
 Changes in v8:
  - Update against the latest kernel.
  - Introduce dpm_save_success_time() to update last_succeess_resume_time.
 Changes in v7:
  - Update patch description.
  - Update sysfs documentation to say the exact timing.
  - Update the comment.
 Changes in v6:
  - Fix to record resume time before thawing user processes.
 Changes in v5:
  - Just updated for v6.7-rc3.
 Changes in v4.1:
  - Fix document typo (again).
 Changes in v4:
  - Update description to add why.
  - Fix document typo.
 Changes in v3:
  - Add (unsigned long long) casting for %llu.
  - Add a line after last_success_resume_time_show().
 Changes in v2:
  - Use %llu instead of %lu for printing u64 value.
  - Remove unneeded indent spaces from the last_success_resume_time
    line in the debugfs suspend_stat file.
---
 Documentation/ABI/testing/sysfs-power |   11 +++++++++++
 kernel/power/main.c                   |   28 ++++++++++++++++++++++++++++
 kernel/power/power.h                  |    1 +
 kernel/power/suspend.c                |    1 +
 4 files changed, 41 insertions(+)

Patch

diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
index a3942b1036e2..ee567e7e9d4a 100644
--- a/Documentation/ABI/testing/sysfs-power
+++ b/Documentation/ABI/testing/sysfs-power
@@ -442,6 +442,17 @@  Description:
 		'total_hw_sleep' and 'last_hw_sleep' may not be accurate.
 		This number is measured in microseconds.
 
+What:		/sys/power/suspend_stats/last_success_resume_time
+Date:		Dec 2023
+Contact:	Masami Hiramatsu <[e-mail]>
+Description:
+		The /sys/power/suspend_stats/last_success_resume_time file
+		contains the timestamp of when the kernel successfully
+		resumed drivers/subsystems from suspend/hibernate. This is
+		just before thawing the user processes.
+		This floating point number is measured in seconds by monotonic
+		clock.
+
 What:		/sys/power/sync_on_suspend
 Date:		October 2019
 Contact:	Jonas Meurer <[e-mail]>
diff --git a/kernel/power/main.c b/kernel/power/main.c
index a9e0693aaf69..d9236bdab42a 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -16,6 +16,7 @@ 
 #include <linux/seq_file.h>
 #include <linux/suspend.h>
 #include <linux/syscalls.h>
+#include <linux/timekeeping.h>
 #include <linux/pm_runtime.h>
 
 #include "power.h"
@@ -321,6 +322,7 @@  struct suspend_stats {
 	u64 last_hw_sleep;
 	u64 total_hw_sleep;
 	u64 max_hw_sleep;
+	struct timespec64 last_success_resume_time;
 	enum suspend_stat_step failed_steps[REC_FAILED_NUM];
 };
 
@@ -361,6 +363,17 @@  void dpm_save_errno(int err)
 	suspend_stats.last_failed_errno %= REC_FAILED_NUM;
 }
 
+void dpm_save_success_time(int err)
+{
+	/*
+	 * Record last succeeded resume timestamp just before thawing processes.
+	 * This is for helping users to measure user-space resume performance
+	 * for improving their programs or finding regressions.
+	 */
+	if (!err)
+		ktime_get_ts64(&suspend_stats.last_success_resume_time);
+}
+
 void pm_report_hw_sleep_time(u64 t)
 {
 	suspend_stats.last_hw_sleep = t;
@@ -460,6 +473,17 @@  static ssize_t last_failed_step_show(struct kobject *kobj,
 }
 static struct kobj_attribute last_failed_step = __ATTR_RO(last_failed_step);
 
+static ssize_t last_success_resume_time_show(struct kobject *kobj,
+		struct kobj_attribute *attr, char *buf)
+{
+	return sprintf(buf, "%llu.%llu\n",
+		(unsigned long long)suspend_stats.last_success_resume_time.tv_sec,
+		(unsigned long long)suspend_stats.last_success_resume_time.tv_nsec);
+}
+
+static struct kobj_attribute last_success_resume_time =
+			__ATTR_RO(last_success_resume_time);
+
 static struct attribute *suspend_attrs[] = {
 	&success.attr,
 	&fail.attr,
@@ -477,6 +501,7 @@  static struct attribute *suspend_attrs[] = {
 	&last_hw_sleep.attr,
 	&total_hw_sleep.attr,
 	&max_hw_sleep.attr,
+	&last_success_resume_time.attr,
 	NULL,
 };
 
@@ -542,6 +567,9 @@  static int suspend_stats_show(struct seq_file *s, void *unused)
 		seq_printf(s, "\t\t\t%-s\n",
 			   suspend_step_names[suspend_stats.failed_steps[index]]);
 	}
+	seq_printf(s,	"last_success_resume_time:\t%-llu.%llu\n",
+		   (unsigned long long)suspend_stats.last_success_resume_time.tv_sec,
+		   (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec);
 
 	return 0;
 }
diff --git a/kernel/power/power.h b/kernel/power/power.h
index de0e6b1077f2..70726a55a9d1 100644
--- a/kernel/power/power.h
+++ b/kernel/power/power.h
@@ -348,3 +348,4 @@  static inline void pm_sleep_enable_secondary_cpus(void)
 }
 
 void dpm_save_errno(int err);
+void dpm_save_success_time(int err);
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 09f8397bae15..1e561eb6681a 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -601,6 +601,7 @@  static int enter_state(suspend_state_t state)
  Finish:
 	events_check_enabled = false;
 	pm_pr_dbg("Finishing wakeup.\n");
+	dpm_save_success_time(error);
 	suspend_finish();
  Unlock:
 	mutex_unlock(&system_transition_mutex);