| Message ID | 20170605193157.59875-1-salyzyn@android.com (mailing list archive) |
|---|---|
| State | Deferred |
| Headers | show |
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);
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
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
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
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
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
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
Hi! > >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. Well, there are real phones with mainline Linux: Nokia N900, N9, N950, Motorola Droid 4. Current kernel is 4.13, not v4.9. Yes, Qualcomm is a problem. There are other vendors, you can get those phones in retail. So no, I don't think android community is doing a good job. I don't think it makes sense to merge patches that "help debugging" when basic support is missing. Best regards, Pavel
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);