[PATCH v8 0/1] PM: sleep: Expose last succeeded resumed timestamp in sysfs

[PATCH v8 0/1] PM: sleep: Expose last succeeded resumed timestamp in sysfs

[Masami Hiramatsu (Google)]

Hi,

Here is the 8th version of the patch to expose last succeeded resumed
timestamp in sysfs as /sys/power/suspend_stats/last_success_resume_time.
The previous version is here.

https://lore.kernel.org/lkml/170359668692.1864392.6909734045167510522.stgit@mhiramat.roam.corp.google.com/

This version is just update against for the upstream kernel.


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.

This patch introduces a last succeeded resumed timestamp (just before
thawing processes) on sysfs which allows us to find when the kernel
resume process successfully done in MONOTONIC clock. Thus user processes
can measure the elapsed time taken by its resume process at any point
in time.

This will help us to detect abnormal value (longer time) process in
the resuming and quickly decide the root cause is in the kernel or
user-space. The kernel side we can use many tools (e.g. printk or
ftrace) but for user-space we need to define the starting point of
the resuming process. Actually, the kernel side needs to use local
clock because the clock subsystem is also suspended. But in that
case, user space can not use that timestamp because the local clock
is not exposed.

So this will be used something like

where_the_user_space_resume_finish() {
	clock_gettime(CLOCK_MONOTONIC, &etime_ts);
	fileread("/sys/.../last_success_resume_time", stime);
	convert_timespec(stime, &stime_ts);
	user_resume_time = timespec_delta(&etime_ts, &stime_ts);
	...
}

Thank you,

---

Masami Hiramatsu (1):
      PM: sleep: Expose last succeeded resumed timestamp in sysfs


 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(+)

--
Masami Hiramatsu (Google) <mhiramat@kernel.org>

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

[Masami Hiramatsu (Google)]

From: Masami Hiramatsu <mhiramat@kernel.org>

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) <mhiramat@kernel.org>
---
 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(+)

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 <mhiramat@kernel.org>
+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 <jonas@freesources.org>
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);

Re: [PATCH v8 0/1] PM: sleep: Expose last succeeded resumed timestamp in sysfs

[Masami Hiramatsu]

Hi Rafael,

Gentry ping. I would like to hear your comment on it.

Thank you,

On Tue,  2 Jul 2024 23:24:43 +0900
"Masami Hiramatsu (Google)" <mhiramat@kernel.org> wrote:

> Hi,
> 
> Here is the 8th version of the patch to expose last succeeded resumed
> timestamp in sysfs as /sys/power/suspend_stats/last_success_resume_time.
> The previous version is here.
> 
> https://lore.kernel.org/lkml/170359668692.1864392.6909734045167510522.stgit@mhiramat.roam.corp.google.com/
> 
> This version is just update against for the upstream kernel.
> 
> 
> 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.
> 
> This patch introduces a last succeeded resumed timestamp (just before
> thawing processes) on sysfs which allows us to find when the kernel
> resume process successfully done in MONOTONIC clock. Thus user processes
> can measure the elapsed time taken by its resume process at any point
> in time.
> 
> This will help us to detect abnormal value (longer time) process in
> the resuming and quickly decide the root cause is in the kernel or
> user-space. The kernel side we can use many tools (e.g. printk or
> ftrace) but for user-space we need to define the starting point of
> the resuming process. Actually, the kernel side needs to use local
> clock because the clock subsystem is also suspended. But in that
> case, user space can not use that timestamp because the local clock
> is not exposed.
> 
> So this will be used something like
> 
> where_the_user_space_resume_finish() {
> 	clock_gettime(CLOCK_MONOTONIC, &etime_ts);
> 	fileread("/sys/.../last_success_resume_time", stime);
> 	convert_timespec(stime, &stime_ts);
> 	user_resume_time = timespec_delta(&etime_ts, &stime_ts);
> 	...
> }
> 
> Thank you,
> 
> ---
> 
> Masami Hiramatsu (1):
>       PM: sleep: Expose last succeeded resumed timestamp in sysfs
> 
> 
>  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(+)
> 
> --
> Masami Hiramatsu (Google) <mhiramat@kernel.org>


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>