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

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

[Masami Hiramatsu (Google)]

Hi,

Here is the 5th version of the patch to expose last succeeded resumed
timestamp in sysfs as /sys/power/suspend_stats/last_success_resume_time.
This version is just updated for v6.7-rc3.

This allows us to find when the kernel resume process successfully done
in the sysfs in MONOTONIC clock. Thus we can measure the time taken by
the user space 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 |   10 ++++++++++
 include/linux/suspend.h               |    2 ++
 kernel/power/main.c                   |   15 +++++++++++++++
 kernel/power/suspend.c                |    1 +
 4 files changed, 28 insertions(+)

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

[PATCH v5] 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.

There are some printk()s for printing the similar resume timing to
dmesg, but those are recorded with local_clock(), and user can not
compare it with current time. We also have tracing events but it
requires CAP_SYS_ADMIN to use it.

This suspend_stats attribute is easy to access and only expose the
timestamp in CLOCK_MONOTONIC. So user can find the actual resumed
time and measure the elapsed time from the time when the kernel
finished the resume to the user-space action (e.g. display the UI).

Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
---
 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 |   10 ++++++++++
 include/linux/suspend.h               |    2 ++
 kernel/power/main.c                   |   15 +++++++++++++++
 kernel/power/suspend.c                |    1 +
 4 files changed, 28 insertions(+)

diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
index a3942b1036e2..e14975859766 100644
--- a/Documentation/ABI/testing/sysfs-power
+++ b/Documentation/ABI/testing/sysfs-power
@@ -442,6 +442,16 @@ 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:		Oct 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 from suspend/hibernate.
+		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/include/linux/suspend.h b/include/linux/suspend.h
index ef503088942d..ddd789044960 100644
--- a/include/linux/suspend.h
+++ b/include/linux/suspend.h
@@ -8,6 +8,7 @@
 #include <linux/pm.h>
 #include <linux/mm.h>
 #include <linux/freezer.h>
+#include <linux/timekeeping.h>
 #include <asm/errno.h>
 
 #ifdef CONFIG_VT
@@ -71,6 +72,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];
 };
 
diff --git a/kernel/power/main.c b/kernel/power/main.c
index f6425ae3e8b0..2ab23fd3daac 100644
--- a/kernel/power/main.c
+++ b/kernel/power/main.c
@@ -421,6 +421,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,
@@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = {
 	&last_hw_sleep.attr,
 	&total_hw_sleep.attr,
 	&max_hw_sleep.attr,
+	&last_success_resume_time.attr,
 	NULL,
 };
 
@@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused)
 			suspend_step_name(
 				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/suspend.c b/kernel/power/suspend.c
index fa3bf161d13f..33334565d5a6 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state)
 		dpm_save_failed_errno(error);
 	} else {
 		suspend_stats.success++;
+		ktime_get_ts64(&suspend_stats.last_success_resume_time);
 	}
 	pr_info("suspend exit\n");
 	return error;

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

[Randy Dunlap]

Hi--


On 11/27/23 02:38, Masami Hiramatsu (Google) wrote:
> From: Masami Hiramatsu <mhiramat@kernel.org>
> 

> diff --git a/kernel/power/main.c b/kernel/power/main.c
> index f6425ae3e8b0..2ab23fd3daac 100644
> --- a/kernel/power/main.c
> +++ b/kernel/power/main.c

> @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused)
>  			suspend_step_name(
>  				suspend_stats.failed_steps[index]));
>  	}
> +	seq_printf(s,	"last_success_resume_time:\t%-llu.%llu\n",

The <TAB> after "s," is a bit odd IMO, but I don't see a need to resend it
just for that.

> +		   (unsigned long long)suspend_stats.last_success_resume_time.tv_sec,
> +		   (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec);
>  
>  	return 0;
>  }

-- 
~Randy

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

[Masami Hiramatsu]

Hi Randy,

On Mon, 27 Nov 2023 15:47:01 -0800
Randy Dunlap <rdunlap@infradead.org> wrote:

> Hi--
> 
> 
> On 11/27/23 02:38, Masami Hiramatsu (Google) wrote:
> > From: Masami Hiramatsu <mhiramat@kernel.org>
> > 
> 
> > diff --git a/kernel/power/main.c b/kernel/power/main.c
> > index f6425ae3e8b0..2ab23fd3daac 100644
> > --- a/kernel/power/main.c
> > +++ b/kernel/power/main.c
> 
> > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused)
> >  			suspend_step_name(
> >  				suspend_stats.failed_steps[index]));
> >  	}
> > +	seq_printf(s,	"last_success_resume_time:\t%-llu.%llu\n",
> 
> The <TAB> after "s," is a bit odd IMO, but I don't see a need to resend it
> just for that.

Yeah, this might be a cosmetic tab. You can see the other seq_prints()
in the same function also have the same <TAB>. I don't want to break it.

Thank you,

> 
> > +		   (unsigned long long)suspend_stats.last_success_resume_time.tv_sec,
> > +		   (unsigned long long)suspend_stats.last_success_resume_time.tv_nsec);
> >  
> >  	return 0;
> >  }
> 
> -- 
> ~Randy


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

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

[Rafael J. Wysocki]

On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google)
<mhiramat@kernel.org> wrote:
>
> From: Masami Hiramatsu <mhiramat@kernel.org>
>
> Expose last succeeded resumed timestamp as last_success_resume_time
> attribute of suspend_stats in sysfs.
>
> There are some printk()s for printing the similar resume timing to
> dmesg, but those are recorded with local_clock(), and user can not
> compare it with current time. We also have tracing events but it
> requires CAP_SYS_ADMIN to use it.
>
> This suspend_stats attribute is easy to access and only expose the
> timestamp in CLOCK_MONOTONIC.

Why CLOCK_MONOTONIC?

> So user can find the actual resumed
> time and measure the elapsed time from the time when the kernel
> finished the resume to the user-space action (e.g. display the UI).

Can you please say a bit more about why this is useful?

The time stamp is taken at the point when user space has been already
running for some time, so what's the exact benefit of it?

> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> ---
>  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 |   10 ++++++++++
>  include/linux/suspend.h               |    2 ++
>  kernel/power/main.c                   |   15 +++++++++++++++
>  kernel/power/suspend.c                |    1 +
>  4 files changed, 28 insertions(+)
>
> diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
> index a3942b1036e2..e14975859766 100644
> --- a/Documentation/ABI/testing/sysfs-power
> +++ b/Documentation/ABI/testing/sysfs-power
> @@ -442,6 +442,16 @@ 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:          Oct 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 from suspend/hibernate.
> +               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/include/linux/suspend.h b/include/linux/suspend.h
> index ef503088942d..ddd789044960 100644
> --- a/include/linux/suspend.h
> +++ b/include/linux/suspend.h
> @@ -8,6 +8,7 @@
>  #include <linux/pm.h>
>  #include <linux/mm.h>
>  #include <linux/freezer.h>
> +#include <linux/timekeeping.h>
>  #include <asm/errno.h>
>
>  #ifdef CONFIG_VT
> @@ -71,6 +72,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];
>  };
>
> diff --git a/kernel/power/main.c b/kernel/power/main.c
> index f6425ae3e8b0..2ab23fd3daac 100644
> --- a/kernel/power/main.c
> +++ b/kernel/power/main.c
> @@ -421,6 +421,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,
> @@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = {
>         &last_hw_sleep.attr,
>         &total_hw_sleep.attr,
>         &max_hw_sleep.attr,
> +       &last_success_resume_time.attr,
>         NULL,
>  };
>
> @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused)
>                         suspend_step_name(
>                                 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/suspend.c b/kernel/power/suspend.c
> index fa3bf161d13f..33334565d5a6 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state)
>                 dpm_save_failed_errno(error);
>         } else {
>                 suspend_stats.success++;
> +               ktime_get_ts64(&suspend_stats.last_success_resume_time);

And so hibernation is not really covered.

>         }
>         pr_info("suspend exit\n");
>         return error;
>

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

[Masami Hiramatsu]

Hi Rafael,

On Tue, 12 Dec 2023 14:39:17 +0100
"Rafael J. Wysocki" <rafael@kernel.org> wrote:

> On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google)
> <mhiramat@kernel.org> wrote:
> >
> > From: Masami Hiramatsu <mhiramat@kernel.org>
> >
> > Expose last succeeded resumed timestamp as last_success_resume_time
> > attribute of suspend_stats in sysfs.
> >
> > There are some printk()s for printing the similar resume timing to
> > dmesg, but those are recorded with local_clock(), and user can not
> > compare it with current time. We also have tracing events but it
> > requires CAP_SYS_ADMIN to use it.
> >
> > This suspend_stats attribute is easy to access and only expose the
> > timestamp in CLOCK_MONOTONIC.
> 
> Why CLOCK_MONOTONIC?

CLOCK_MONOTONIC is the simplest clock which can be used in both user
space and kernel space. If we use the CLOCK_LOCAL here, user can not
know the actual time delta from the succeeded resume.

> 
> > So user can find the actual resumed
> > time and measure the elapsed time from the time when the kernel
> > finished the resume to the user-space action (e.g. display the UI).
> 
> Can you please say a bit more about why this is useful?

This is a reference timestamp from the user space to measure their
processing time for resuming. The kernel side is OK to just trace
or printk the each component or subsystem internally. But the user
space needs to know when the kernel resume has been done for measuring
its component or processes done. Actually this is obscure because the
end of resuming in userspace is defined by the user-space application
or desktop systems. But anyway if there is a reference point, user
process can calculate the delta at any point from that.

> 
> The time stamp is taken at the point when user space has been already
> running for some time, so what's the exact benefit of it?

Yes, but that timestamp can be scheduled afterwards so it may not
be so accurate. This can provide the accurate time of the kernel
resume.

Thank you,

> 
> > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
> > ---
> >  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 |   10 ++++++++++
> >  include/linux/suspend.h               |    2 ++
> >  kernel/power/main.c                   |   15 +++++++++++++++
> >  kernel/power/suspend.c                |    1 +
> >  4 files changed, 28 insertions(+)
> >
> > diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power
> > index a3942b1036e2..e14975859766 100644
> > --- a/Documentation/ABI/testing/sysfs-power
> > +++ b/Documentation/ABI/testing/sysfs-power
> > @@ -442,6 +442,16 @@ 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:          Oct 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 from suspend/hibernate.
> > +               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/include/linux/suspend.h b/include/linux/suspend.h
> > index ef503088942d..ddd789044960 100644
> > --- a/include/linux/suspend.h
> > +++ b/include/linux/suspend.h
> > @@ -8,6 +8,7 @@
> >  #include <linux/pm.h>
> >  #include <linux/mm.h>
> >  #include <linux/freezer.h>
> > +#include <linux/timekeeping.h>
> >  #include <asm/errno.h>
> >
> >  #ifdef CONFIG_VT
> > @@ -71,6 +72,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];
> >  };
> >
> > diff --git a/kernel/power/main.c b/kernel/power/main.c
> > index f6425ae3e8b0..2ab23fd3daac 100644
> > --- a/kernel/power/main.c
> > +++ b/kernel/power/main.c
> > @@ -421,6 +421,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,
> > @@ -438,6 +449,7 @@ static struct attribute *suspend_attrs[] = {
> >         &last_hw_sleep.attr,
> >         &total_hw_sleep.attr,
> >         &max_hw_sleep.attr,
> > +       &last_success_resume_time.attr,
> >         NULL,
> >  };
> >
> > @@ -514,6 +526,9 @@ static int suspend_stats_show(struct seq_file *s, void *unused)
> >                         suspend_step_name(
> >                                 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/suspend.c b/kernel/power/suspend.c
> > index fa3bf161d13f..33334565d5a6 100644
> > --- a/kernel/power/suspend.c
> > +++ b/kernel/power/suspend.c
> > @@ -622,6 +622,7 @@ int pm_suspend(suspend_state_t state)
> >                 dpm_save_failed_errno(error);
> >         } else {
> >                 suspend_stats.success++;
> > +               ktime_get_ts64(&suspend_stats.last_success_resume_time);
> 
> And so hibernation is not really covered.
> 
> >         }
> >         pr_info("suspend exit\n");
> >         return error;
> >


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

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

[Rafael J. Wysocki]

On Tue, Dec 12, 2023 at 3:32 PM Masami Hiramatsu <mhiramat@kernel.org> wrote:
>
> Hi Rafael,
>
> On Tue, 12 Dec 2023 14:39:17 +0100
> "Rafael J. Wysocki" <rafael@kernel.org> wrote:
>
> > On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google)
> > <mhiramat@kernel.org> wrote:
> > >
> > > From: Masami Hiramatsu <mhiramat@kernel.org>
> > >
> > > Expose last succeeded resumed timestamp as last_success_resume_time
> > > attribute of suspend_stats in sysfs.
> > >
> > > There are some printk()s for printing the similar resume timing to
> > > dmesg, but those are recorded with local_clock(), and user can not
> > > compare it with current time. We also have tracing events but it
> > > requires CAP_SYS_ADMIN to use it.
> > >
> > > This suspend_stats attribute is easy to access and only expose the
> > > timestamp in CLOCK_MONOTONIC.
> >
> > Why CLOCK_MONOTONIC?
>
> CLOCK_MONOTONIC is the simplest clock which can be used in both user
> space and kernel space. If we use the CLOCK_LOCAL here, user can not
> know the actual time delta from the succeeded resume.

So what does user space need to do to use this value?

> >
> > > So user can find the actual resumed
> > > time and measure the elapsed time from the time when the kernel
> > > finished the resume to the user-space action (e.g. display the UI).
> >
> > Can you please say a bit more about why this is useful?
>
> This is a reference timestamp from the user space to measure their
> processing time for resuming. The kernel side is OK to just trace
> or printk the each component or subsystem internally. But the user
> space needs to know when the kernel resume has been done for measuring
> its component or processes done.

Why does it need to know that?

> Actually this is obscure because the
> end of resuming in userspace is defined by the user-space application
> or desktop systems. But anyway if there is a reference point, user
> process can calculate the delta at any point from that.
>
> >
> > The time stamp is taken at the point when user space has been already
> > running for some time, so what's the exact benefit of it?
>
> Yes, but that timestamp can be scheduled afterwards so it may not
> be so accurate. This can provide the accurate time of the kernel
> resume.

I'm talking about the timestamp added by this patch, that is
/sys/power/suspend_stats/last_success_resume_time.

By the time ktime_get_ts64() in pm_suspend() is called, user space has
already been thawed and is running, so why is this useful?

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

[Masami Hiramatsu]

On Tue, 12 Dec 2023 15:57:52 +0100
"Rafael J. Wysocki" <rafael@kernel.org> wrote:

> On Tue, Dec 12, 2023 at 3:32 PM Masami Hiramatsu <mhiramat@kernel.org> wrote:
> >
> > Hi Rafael,
> >
> > On Tue, 12 Dec 2023 14:39:17 +0100
> > "Rafael J. Wysocki" <rafael@kernel.org> wrote:
> >
> > > On Mon, Nov 27, 2023 at 11:38 AM Masami Hiramatsu (Google)
> > > <mhiramat@kernel.org> wrote:
> > > >
> > > > From: Masami Hiramatsu <mhiramat@kernel.org>
> > > >
> > > > Expose last succeeded resumed timestamp as last_success_resume_time
> > > > attribute of suspend_stats in sysfs.
> > > >
> > > > There are some printk()s for printing the similar resume timing to
> > > > dmesg, but those are recorded with local_clock(), and user can not
> > > > compare it with current time. We also have tracing events but it
> > > > requires CAP_SYS_ADMIN to use it.
> > > >
> > > > This suspend_stats attribute is easy to access and only expose the
> > > > timestamp in CLOCK_MONOTONIC.
> > >
> > > Why CLOCK_MONOTONIC?
> >
> > CLOCK_MONOTONIC is the simplest clock which can be used in both user
> > space and kernel space. If we use the CLOCK_LOCAL here, user can not
> > know the actual time delta from the succeeded resume.
> 
> So what does user space need to do to use this value?

This will be used to measure the delay of the user-space resuming as a
metric of system health.

> > >
> > > > So user can find the actual resumed
> > > > time and measure the elapsed time from the time when the kernel
> > > > finished the resume to the user-space action (e.g. display the UI).
> > >
> > > Can you please say a bit more about why this is useful?
> >
> > This is a reference timestamp from the user space to measure their
> > processing time for resuming. The kernel side is OK to just trace
> > or printk the each component or subsystem internally. But the user
> > space needs to know when the kernel resume has been done for measuring
> > its component or processes done.
> 
> Why does it need to know that?

For the metrics, the kernel side resume time and user-side resume time are
important to know if any update caused regressions and separate the issue.

> 
> > Actually this is obscure because the
> > end of resuming in userspace is defined by the user-space application
> > or desktop systems. But anyway if there is a reference point, user
> > process can calculate the delta at any point from that.
> >
> > >
> > > The time stamp is taken at the point when user space has been already
> > > running for some time, so what's the exact benefit of it?
> >
> > Yes, but that timestamp can be scheduled afterwards so it may not
> > be so accurate. This can provide the accurate time of the kernel
> > resume.
> 
> I'm talking about the timestamp added by this patch, that is
> /sys/power/suspend_stats/last_success_resume_time.
> 
> By the time ktime_get_ts64() in pm_suspend() is called, user space has
> already been thawed and is running, so why is this useful?

Aaah, good catch! It should be right before thawing process, right?

Thank you,

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