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

[Google]

Hi,

On Tue, 19 Dec 2023 21:32:06 +0100
"Rafael J. Wysocki" <rafael@xxxxxxxxxx> wrote:

> On Wed, Dec 13, 2023 at 8:39 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 so that user can use this time
> > stamp as a reference point of resuming user space.
> >
> > 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.
> 
> You'd need to explain why.

OK, I'll add it.

> 
> > 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. User can find the actual resumed
> > time and measure the elapsed time from the time when the kernel
> > finished the resume
> 
> So now it is the time when the kernel has started thawing tasks.

Yes, so update the description.

> 
> > to the user-space action (e.g. display the UI)
> > and use it as a performance metric of user process resuming time.
> 
> The whole "user process resuming time" idea is highly questionable,
> because it assumes that the user space task has been notified of the
> system suspend somehow and so it knows that it will be resuming
> subsequently.
> 
> I'm wondering what exactly is going on?

I'm improving ChromeOS system resume performance. As you assumed, the
user space tasks have been notified the suspend and the resume from
the power manager daemon. We already have a metrics about kernel resume
time, but no user space resume time. If we have a metrics about user-
space resuming, we can identify which part caused a resume delay if
any delay happens.

For that purpose, the key parts is this timestamp when the kernel
actually finished the resuming, because user application (power
manager and chrome etc.) can get the timestamp when any event happens
in the user space, but it can not know the kernel event timestamp
counted by the same clock easily.

> 
> > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>
> > ---
> >  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 |   10 ++++++++++
> >  include/linux/suspend.h               |    2 ++
> >  kernel/power/main.c                   |   15 +++++++++++++++
> >  kernel/power/suspend.c                |    3 +++
> >  4 files changed, 30 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.
> 
> It needs to say what exactly the time is.

OK.

> 
> > +               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..b85889358f53 100644
> > --- a/kernel/power/suspend.c
> > +++ b/kernel/power/suspend.c
> > @@ -595,6 +595,9 @@ static int enter_state(suspend_state_t state)
> >   Finish:
> >         events_check_enabled = false;
> >         pm_pr_dbg("Finishing wakeup.\n");
> > +       /* Record last succeeded resume time before thawing processes. */
> 
> IMV the comment should explain why this particular time is recorded or
> it is not very useful otherwise.

Agreed.

> 
> > +       if (!error)
> > +               ktime_get_ts64(&suspend_stats.last_success_resume_time);
> 
> A blank line here, please.

OK.

Thank you,

> 
> >         suspend_finish();
> >   Unlock:
> >         mutex_unlock(&system_transition_mutex);
> >
> >


-- 
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>