| Message ID | 169849758243.1357961.4105003693126485611.stgit@mhiramat.roam.corp.google.com |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [v3] PM: sleep: Expose last succeeded resumed timestamp in sysfs | expand |
Hi, On 10/28/23 05:53, Masami Hiramatsu (Google) wrote: > From: Masami Hiramatsu <mhiramat@kernel.org> > > Expose last succeeded resumed timestamp as last_success_resume_time > attribute of suspend_stats in sysfs. This timestamp is recorded 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). Can you go into the use-case a bit more, please? You have said "what", but not "why". What do you (or google) plan to do with this? > > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> > --- > 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..63659765dee1 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 number is measured in seconds by monotonic What does "floating" mean here? Not floating point... > + clock. > + > What: /sys/power/sync_on_suspend > Date: October 2019 > Contact: Jonas Meurer <jonas@freesources.org> [snip] Thanks.
On Sat, 28 Oct 2023 09:48:36 -0700 Randy Dunlap <rdunlap@infradead.org> wrote: > Hi, > > On 10/28/23 05:53, Masami Hiramatsu (Google) wrote: > > From: Masami Hiramatsu <mhiramat@kernel.org> > > > > Expose last succeeded resumed timestamp as last_success_resume_time > > attribute of suspend_stats in sysfs. This timestamp is recorded 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). > > Can you go into the use-case a bit more, please? > You have said "what", but not "why". > What do you (or google) plan to do with this? > > > > > Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> > > --- > > 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..63659765dee1 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 number is measured in seconds by monotonic > > What does "floating" mean here? Not floating point... Oops, it should be "floating point number". Thank you! > > > > + clock. > > + > > What: /sys/power/sync_on_suspend > > Date: October 2019 > > Contact: Jonas Meurer <jonas@freesources.org> > > [snip] > > Thanks. > -- > ~Randy
Hi. On 10/28/23 19:54, Masami Hiramatsu (Google) wrote: > On Sat, 28 Oct 2023 09:48:36 -0700 > Randy Dunlap <rdunlap@infradead.org> wrote: > >> Hi, >> >> On 10/28/23 05:53, Masami Hiramatsu (Google) wrote: >>> From: Masami Hiramatsu <mhiramat@kernel.org> >>> >>> Expose last succeeded resumed timestamp as last_success_resume_time >>> attribute of suspend_stats in sysfs. This timestamp is recorded 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). >> >> Can you go into the use-case a bit more, please? >> You have said "what", but not "why". >> What do you (or google) plan to do with this? and what about this part of my questions? ^^^^^^^^^ >> >>> >>> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> >>> --- >>> 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..63659765dee1 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 number is measured in seconds by monotonic >> >> What does "floating" mean here? Not floating point... > > Oops, it should be "floating point number". > > Thank you! > >> >> >>> + clock. >>> + >>> What: /sys/power/sync_on_suspend >>> Date: October 2019 >>> Contact: Jonas Meurer <jonas@freesources.org> >> >> [snip] >> >> Thanks. >> -- >> ~Randy > >
Hi, On Sun, 29 Oct 2023 05:16:49 -0700 Randy Dunlap <rdunlap@infradead.org> wrote: > Hi. > > On 10/28/23 19:54, Masami Hiramatsu (Google) wrote: > > On Sat, 28 Oct 2023 09:48:36 -0700 > > Randy Dunlap <rdunlap@infradead.org> wrote: > > > >> Hi, > >> > >> On 10/28/23 05:53, Masami Hiramatsu (Google) wrote: > >>> From: Masami Hiramatsu <mhiramat@kernel.org> > >>> > >>> Expose last succeeded resumed timestamp as last_success_resume_time > >>> attribute of suspend_stats in sysfs. This timestamp is recorded 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). > >> > >> Can you go into the use-case a bit more, please? > >> You have said "what", but not "why". > >> What do you (or google) plan to do with this? > > and what about this part of my questions? ^^^^^^^^^ Oh, sorry I missed it. I would like to know the actual (accurate) elapsed time from the succeeded kernel resume time to displaying UI so that we can identify the user visible (noticable) resume delay happens in the kernel or the user resume process. The kernel side will be recorded on the dmesg if we use PRINTK_TIME, but the PRINTK_TIME is recorded by local_clock(), we can not know the actual time in the user space. I also considered to expose current local_clock() by introducing CLOCK_LOCAL, but that may be more user-space intrusive change, so I chose this way. Thank you, > > > >> > >>> > >>> Signed-off-by: Masami Hiramatsu (Google) <mhiramat@kernel.org> > >>> --- > >>> 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..63659765dee1 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 number is measured in seconds by monotonic > >> > >> What does "floating" mean here? Not floating point... > > > > Oops, it should be "floating point number". > > > > Thank you! > > > >> > >> > >>> + clock. > >>> + > >>> What: /sys/power/sync_on_suspend > >>> Date: October 2019 > >>> Contact: Jonas Meurer <jonas@freesources.org> > >> > >> [snip] > >> > >> Thanks. > >> -- > >> ~Randy > > > > > > -- > ~Randy
diff --git a/Documentation/ABI/testing/sysfs-power b/Documentation/ABI/testing/sysfs-power index a3942b1036e2..63659765dee1 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 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;