diff mbox series

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

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

Commit Message

Masami Hiramatsu (Google) Oct. 28, 2023, 12:53 p.m. UTC
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).

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

Comments

Randy Dunlap Oct. 28, 2023, 4:48 p.m. UTC | #1
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.
Masami Hiramatsu (Google) Oct. 29, 2023, 2:54 a.m. UTC | #2
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
Randy Dunlap Oct. 29, 2023, 12:16 p.m. UTC | #3
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
> 
>
Masami Hiramatsu (Google) Oct. 29, 2023, 1:28 p.m. UTC | #4
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 mbox series

Patch

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;