Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1658111 > unrolled thread

PM / Suspend: Print wall time at suspend entry and exit

Back to article view | Back to linux.kernel

Contents

  PM / Suspend: Print wall time at suspend entry and exit Mark Salyzyn <salyzyn@android.com> - 2017-06-05 21:40 +0200
    PM / Hibernation: Print wall time at hibernation entry and exit Mark Salyzyn <salyzyn@android.com> - 2017-06-05 21:40 +0200
    Re: PM / Suspend: Print wall time at suspend entry and exit Pavel Machek <pavel@ucw.cz> - 2017-06-05 22:10 +0200
    Re: PM / Suspend: Print wall time at suspend entry and exit "Rafael J. Wysocki" <rafael@kernel.org> - 2017-06-05 23:00 +0200
      Re: PM / Suspend: Print wall time at suspend entry and exit Pavel Machek <pavel@ucw.cz> - 2017-06-05 23:20 +0200
        Re: PM / Suspend: Print wall time at suspend entry and exit Mark Salyzyn <salyzyn@android.com> - 2017-06-05 23:50 +0200
          Re: PM / Suspend: Print wall time at suspend entry and exit Mark Salyzyn <salyzyn@android.com> - 2017-06-06 00:20 +0200
            Re: PM / Suspend: Print wall time at suspend entry and exit Pavel Machek <pavel@ucw.cz> - 2017-06-06 00:50 +0200
              Re: PM / Suspend: Print wall time at suspend entry and exit Mark Salyzyn <salyzyn@android.com> - 2017-06-06 20:10 +0200

#1658111 — PM / Suspend: Print wall time at suspend entry and exit

Permits power state and battery life diagnosis.

Signed-off-by: Todd Poynor <toddpoynor@google.com>
Signed-off-by: Mark Salyzyn <salyzyn@android.com>
---
 kernel/power/suspend.c | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index c0248c74d6d4..464175f04bc5 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -26,6 +26,7 @@
 #include <linux/suspend.h>
 #include <linux/syscore_ops.h>
 #include <linux/ftrace.h>
+#include <linux/rtc.h>
 #include <trace/events/power.h>
 #include <linux/compiler.h>
 #include <linux/moduleparam.h>
@@ -563,6 +564,18 @@ static int enter_state(suspend_state_t state)
 	return error;
 }
 
+static void pm_suspend_marker(char *annotation)
+{
+	struct timespec ts;
+	struct rtc_time tm;
+
+	getnstimeofday(&ts);
+	rtc_time_to_tm(ts.tv_sec, &tm);
+	pr_info("PM: suspend %s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n",
+		annotation, tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
+		tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec);
+}
+
 /**
  * pm_suspend - Externally visible function for suspending the system.
  * @state: System sleep state to enter.
@@ -577,6 +590,7 @@ int pm_suspend(suspend_state_t state)
 	if (state <= PM_SUSPEND_ON || state >= PM_SUSPEND_MAX)
 		return -EINVAL;
 
+	pm_suspend_marker("entry");
 	error = enter_state(state);
 	if (error) {
 		suspend_stats.fail++;
@@ -584,6 +598,7 @@ int pm_suspend(suspend_state_t state)
 	} else {
 		suspend_stats.success++;
 	}
+	pm_suspend_marker("exit");
 	return error;
 }
 EXPORT_SYMBOL(pm_suspend);
-- 
2.13.0.506.g27d5fe0cd-goog

[toc] | [next] | [standalone]

#1658112 — PM / Hibernation: Print wall time at hibernation entry and exit

Permits power state and battery life diagnosis.

Signed-off-by: Mark Salyzyn <salyzyn@android.com>
---
 kernel/power/hibernate.c | 2 ++
 kernel/power/power.h     | 1 +
 kernel/power/suspend.c   | 2 +-
 3 files changed, 4 insertions(+), 1 deletion(-)

diff --git a/kernel/power/hibernate.c b/kernel/power/hibernate.c
index a8b978c35a6a..0a8b7315d298 100644
--- a/kernel/power/hibernate.c
+++ b/kernel/power/hibernate.c
@@ -342,6 +342,7 @@ int hibernation_snapshot(int platform_mode)
 	pm_message_t msg;
 	int error;
 
+	pm_suspend_marker("entry hibernation");
 	pm_suspend_clear_flags();
 	error = platform_begin(platform_mode);
 	if (error)
@@ -409,6 +410,7 @@ int hibernation_snapshot(int platform_mode)
 	thaw_kernel_threads();
  Cleanup:
 	swsusp_free();
+	pm_suspend_marker("exit hibernation");
 	goto Close;
 }
 
diff --git a/kernel/power/power.h b/kernel/power/power.h
index 7fdc40d31b7d..08f63ae27a31 100644
--- a/kernel/power/power.h
+++ b/kernel/power/power.h
@@ -194,6 +194,7 @@ extern const char *pm_states[];
 extern const char *mem_sleep_states[];
 extern suspend_state_t mem_sleep_current;
 
+extern void pm_suspend_marker(const char *annotation);
 extern int suspend_devices_and_enter(suspend_state_t state);
 #else /* !CONFIG_SUSPEND */
 #define mem_sleep_current	PM_SUSPEND_ON
diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
index 464175f04bc5..69da2b880bde 100644
--- a/kernel/power/suspend.c
+++ b/kernel/power/suspend.c
@@ -564,7 +564,7 @@ static int enter_state(suspend_state_t state)
 	return error;
 }
 
-static void pm_suspend_marker(char *annotation)
+void pm_suspend_marker(const char *annotation)
 {
 	struct timespec ts;
 	struct rtc_time tm;
-- 
2.13.0.506.g27d5fe0cd-goog

[toc] | [prev] | [next] | [standalone]

#1658126

[Multipart message — attachments visible in raw view] — view raw

On Mon 2017-06-05 12:31:14, Mark Salyzyn wrote:
> Permits power state and battery life diagnosis.
> 
> Signed-off-by: Todd Poynor <toddpoynor@google.com>
> Signed-off-by: Mark Salyzyn <salyzyn@android.com>

I don't particulary like it (RTC is slow on PC class machines), but I
guess the information is useful.

Acked-by: Pavel Machek <pavel@ucw.cz>

> ---
>  kernel/power/suspend.c | 15 +++++++++++++++
>  1 file changed, 15 insertions(+)
> 
> diff --git a/kernel/power/suspend.c b/kernel/power/suspend.c
> index c0248c74d6d4..464175f04bc5 100644
> --- a/kernel/power/suspend.c
> +++ b/kernel/power/suspend.c
> @@ -26,6 +26,7 @@
>  #include <linux/suspend.h>
>  #include <linux/syscore_ops.h>
>  #include <linux/ftrace.h>
> +#include <linux/rtc.h>
>  #include <trace/events/power.h>
>  #include <linux/compiler.h>
>  #include <linux/moduleparam.h>
> @@ -563,6 +564,18 @@ static int enter_state(suspend_state_t state)
>  	return error;
>  }
>  
> +static void pm_suspend_marker(char *annotation)
> +{
> +	struct timespec ts;
> +	struct rtc_time tm;
> +
> +	getnstimeofday(&ts);
> +	rtc_time_to_tm(ts.tv_sec, &tm);
> +	pr_info("PM: suspend %s %d-%02d-%02d %02d:%02d:%02d.%09lu UTC\n",
> +		annotation, tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday,
> +		tm.tm_hour, tm.tm_min, tm.tm_sec, ts.tv_nsec);
> +}
> +
>  /**
>   * pm_suspend - Externally visible function for suspending the system.
>   * @state: System sleep state to enter.
> @@ -577,6 +590,7 @@ int pm_suspend(suspend_state_t state)
>  	if (state <= PM_SUSPEND_ON || state >= PM_SUSPEND_MAX)
>  		return -EINVAL;
>  
> +	pm_suspend_marker("entry");
>  	error = enter_state(state);
>  	if (error) {
>  		suspend_stats.fail++;
> @@ -584,6 +598,7 @@ int pm_suspend(suspend_state_t state)
>  	} else {
>  		suspend_stats.success++;
>  	}
> +	pm_suspend_marker("exit");
>  	return error;
>  }
>  EXPORT_SYMBOL(pm_suspend);

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1658147

On Mon, Jun 5, 2017 at 9:31 PM, Mark Salyzyn <salyzyn@android.com> wrote:
> Permits power state and battery life diagnosis.

Which is possible even without this patch and we have tools for that
(analyze_suspend.py, anyone?).

Honestly, I don't see why this change is necessary or even useful.

Thanks,
Rafael

[toc] | [prev] | [next] | [standalone]

#1658152

[Multipart message — attachments visible in raw view] — view raw

Hi!

> On Mon, Jun 5, 2017 at 9:31 PM, Mark Salyzyn <salyzyn@android.com> wrote:
> > Permits power state and battery life diagnosis.
> 
> Which is possible even without this patch and we have tools for that
> (analyze_suspend.py, anyone?).
> 
> Honestly, I don't see why this change is necessary or even useful.

I ran dmesg after resume and now I...

[1019729.486249] ACPI : EC: EC stopped
[1019729.486255] PM: Saving platform NVS memory
[1019729.486276] Disabling non-boot CPUs ...
[1019729.490423] smpboot: CPU 1 is now offline
[1019729.531015] smpboot: CPU 2 is now offline
[1019729.577742] Broke affinity for irq 16
[1019729.577747] Broke affinity for irq 17
[1019729.577751] Broke affinity for irq 19
[1019729.577756] Broke affinity for irq 23
[1019729.578771] smpboot: CPU 3 is now offline
[1019729.604987] ACPI: Low-level resume complete
[1019729.605052] ACPI : EC: EC started
[1019729.605054] PM: Restoring platform NVS memory
[1019729.605352] Suspended for 3196.166 seconds
[1019729.605376] Enabling non-boot CPUs ...
[1019729.631246] x86: Booting SMP configuration:
[1019729.631249] smpboot: Booting Node 0 Processor 1 APIC 0x1
[1019729.631496] Initializing CPU#1
[1019729.631514] Disabled fast string operations
[1019729.636643]  cache: parent cpu1 should not be sleeping
[1019729.637286] CPU1 is up

Aha. I missed the "suspended for 3196" message before. So I believe
you are right; there's already enough information in the kernel logs.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1658168

On 06/05/2017 02:18 PM, Pavel Machek wrote:
> Hi!
>
>> On Mon, Jun 5, 2017 at 9:31 PM, Mark Salyzyn <salyzyn@android.com> wrote:
>>> Permits power state and battery life diagnosis.
>> Which is possible even without this patch and we have tools for that
>> (analyze_suspend.py, anyone?).
>>
>> Honestly, I don't see why this change is necessary or even useful.
> I ran dmesg after resume and now I...
>
> [1019729.486249] ACPI : EC: EC stopped
> [1019729.486255] PM: Saving platform NVS memory
> [1019729.486276] Disabling non-boot CPUs ...
> [1019729.490423] smpboot: CPU 1 is now offline
> [1019729.531015] smpboot: CPU 2 is now offline
> [1019729.577742] Broke affinity for irq 16
> [1019729.577747] Broke affinity for irq 17
> [1019729.577751] Broke affinity for irq 19
> [1019729.577756] Broke affinity for irq 23
> [1019729.578771] smpboot: CPU 3 is now offline
> [1019729.604987] ACPI: Low-level resume complete
> [1019729.605052] ACPI : EC: EC started
> [1019729.605054] PM: Restoring platform NVS memory
> [1019729.605352] Suspended for 3196.166 seconds
> [1019729.605376] Enabling non-boot CPUs ...
> [1019729.631246] x86: Booting SMP configuration:
> [1019729.631249] smpboot: Booting Node 0 Processor 1 APIC 0x1
> [1019729.631496] Initializing CPU#1
> [1019729.631514] Disabled fast string operations
> [1019729.636643]  cache: parent cpu1 should not be sleeping
> [1019729.637286] CPU1 is up
>
> Aha. I missed the "suspended for 3196" message before. So I believe
> you are right; there's already enough information in the kernel logs.
>
> 									Pavel

We do not get the Suspended for messages on failure to suspend 
(interrupt wakeup), but that is a weak argument ;-/ since it is 
discoverable from context and we can count the aborted suspends 
switching the tools. The Suspended for messages are in ms which is not 
accurate enough for Android user space logs (in ns) long term continuous 
tracking of monotonic vs realtime and makes no accounting for ntp 
adjustments. Currently, post mortem data only on Android, we have no 
other way to align monotonic kernel logs with user space logs without this.

Sincerely -- Mark Salyzyn

[toc] | [prev] | [next] | [standalone]

#1658186

On 06/05/2017 02:47 PM, Mark Salyzyn wrote:
> On 06/05/2017 02:18 PM, Pavel Machek wrote:
>> Hi!
>>
>>> On Mon, Jun 5, 2017 at 9:31 PM, Mark Salyzyn <salyzyn@android.com> 
>>> wrote:
>>>> Permits power state and battery life diagnosis.
>>> Which is possible even without this patch and we have tools for that
>>> (analyze_suspend.py, anyone?).
>>>
>>> Honestly, I don't see why this change is necessary or even useful.
>> I ran dmesg after resume and now I...
>>
>> [1019729.486249] ACPI : EC: EC stopped
>> [1019729.486255] PM: Saving platform NVS memory
>> [1019729.486276] Disabling non-boot CPUs ...
>> [1019729.490423] smpboot: CPU 1 is now offline
>> [1019729.531015] smpboot: CPU 2 is now offline
>> [1019729.577742] Broke affinity for irq 16
>> [1019729.577747] Broke affinity for irq 17
>> [1019729.577751] Broke affinity for irq 19
>> [1019729.577756] Broke affinity for irq 23
>> [1019729.578771] smpboot: CPU 3 is now offline
>> [1019729.604987] ACPI: Low-level resume complete
>> [1019729.605052] ACPI : EC: EC started
>> [1019729.605054] PM: Restoring platform NVS memory
>> [1019729.605352] Suspended for 3196.166 seconds
>> [1019729.605376] Enabling non-boot CPUs ...
>> [1019729.631246] x86: Booting SMP configuration:
>> [1019729.631249] smpboot: Booting Node 0 Processor 1 APIC 0x1
>> [1019729.631496] Initializing CPU#1
>> [1019729.631514] Disabled fast string operations
>> [1019729.636643]  cache: parent cpu1 should not be sleeping
>> [1019729.637286] CPU1 is up
>>
>> Aha. I missed the "suspended for 3196" message before. So I believe
>> you are right; there's already enough information in the kernel logs.
>>
>>                                     Pavel
>
> We do not get the Suspended for messages on failure to suspend 
> (interrupt wakeup), but that is a weak argument ;-/ since it is 
> discoverable from context and we can count the aborted suspends 
> switching the tools. The Suspended for messages are in ms which is not 
> accurate enough for Android user space logs (in ns) long term 
> continuous tracking of monotonic vs realtime and makes no accounting 
> for ntp adjustments. Currently, post mortem data only on Android, we 
> have no other way to align monotonic kernel logs with user space logs 
> without this.
>
> Sincerely -- Mark Salyzyn
>
Also, not all devices have a persistent time that can be collected at 
Suspend at that level, so they have to turn off CONFIG_SUSPEND_TIME 
because 'Suspended for' is meaningless on those platforms, but alas 
these prints turn into a backup mechanism for those platforms as they 
are printed befopre and after the hardware is up and running.

-- Mark

[toc] | [prev] | [next] | [standalone]

#1658200

[Multipart message — attachments visible in raw view] — view raw

Hi!

> >>>On Mon, Jun 5, 2017 at 9:31 PM, Mark Salyzyn <salyzyn@android.com>
> >>>wrote:
> >>>>Permits power state and battery life diagnosis.
> >>>Which is possible even without this patch and we have tools for that
> >>>(analyze_suspend.py, anyone?).
> >>>
> >>>Honestly, I don't see why this change is necessary or even useful.
> >>I ran dmesg after resume and now I...
> >>
> >>[1019729.486249] ACPI : EC: EC stopped
> >>[1019729.486255] PM: Saving platform NVS memory
> >>[1019729.486276] Disabling non-boot CPUs ...
> >>[1019729.490423] smpboot: CPU 1 is now offline
> >>[1019729.531015] smpboot: CPU 2 is now offline
> >>[1019729.577742] Broke affinity for irq 16
> >>[1019729.577747] Broke affinity for irq 17
> >>[1019729.577751] Broke affinity for irq 19
> >>[1019729.577756] Broke affinity for irq 23
> >>[1019729.578771] smpboot: CPU 3 is now offline
> >>[1019729.604987] ACPI: Low-level resume complete
> >>[1019729.605052] ACPI : EC: EC started
> >>[1019729.605054] PM: Restoring platform NVS memory
> >>[1019729.605352] Suspended for 3196.166 seconds
> >>[1019729.605376] Enabling non-boot CPUs ...
> >>[1019729.631246] x86: Booting SMP configuration:
> >>[1019729.631249] smpboot: Booting Node 0 Processor 1 APIC 0x1
> >>[1019729.631496] Initializing CPU#1
> >>[1019729.631514] Disabled fast string operations
> >>[1019729.636643]  cache: parent cpu1 should not be sleeping
> >>[1019729.637286] CPU1 is up
> >>
> >>Aha. I missed the "suspended for 3196" message before. So I believe
> >>you are right; there's already enough information in the kernel logs.
> >>
> >>                                    Pavel
> >
> >We do not get the Suspended for messages on failure to suspend (interrupt
> >wakeup), but that is a weak argument ;-/ since it is discoverable from
> >context and we can count the aborted suspends switching the tools. The
> >Suspended for messages are in ms which is not accurate enough for Android
> >user space logs (in ns) long term continuous tracking of monotonic

Nanoseconds do not really matter here, right?

And userspace should not really be parsing kernel logs for time
keeping, right?

> >realtime and makes no accounting for ntp adjustments. Currently, post
> >mortem data only on Android, we have no other way to align monotonic
> >kernel logs with user space logs without this.

> Also, not all devices have a persistent time that can be collected at
> Suspend at that level, so they have to turn off CONFIG_SUSPEND_TIME because
> 'Suspended for' is meaningless on those platforms, but alas these prints
> turn into a backup mechanism for those platforms as they are printed befopre
> and after the hardware is up and running.

The devices you are talking about... is any of them running something
close to mainline kernel, or is planned for merge? I'd like to get a
phone that is supported by mainline...
									
									Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1659028

On 06/05/2017 03:40 PM, Pavel Machek wrote:
>
> Nanoseconds do not really matter here, right?

useconds do matter (syscall takes about 1us). But no matter, since 
Suspended message is only available on platforms that support persistent 
clock, so in those case (more devices than I can count) the messages we 
add here are all we get since they do not have a requirement to be 
supported by the persistent clock.

> And userspace should not really be parsing kernel logs for time
> keeping, right?
Post-mortem, armed with user space logs in CLOCK_REALTIME (a choice that 
most want on Android Logging) and kernel logs, these messages are 
_invaluable_ in order to merge the kernel activities with user space. At 
runtime they help too, as there is some post-mortem activities on user 
space logging daemon startup.
> The devices you are talking about... is any of them running something
> close to mainline kernel, or is planned for merge? I'd like to get a
> phone that is supported by mainline...

Android on hikey development board is running 4.9 kernel + Android 
patches (this is one of 'em), I _expect_ ToT will work. As for _real_ 
phones, you have to take that up with the vendors making the chips.
> 									
> 									Pavel

-- Mark

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web