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@xxxxxxxxxx> wrote:
>
> From: Masami Hiramatsu <mhiramat@xxxxxxxxxx>
>
> 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@xxxxxxxxxx>
> ---
>  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@xxxxxxxxxx>
> +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@xxxxxxxxxxxxxxx>
> 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;
>