linux-kernel - Re: PM / Suspend: Print wall time at suspend entry and exit

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <ca5fb419-386f-9e27-43c4-677be6f0ae4b@android.com>
Date:   Mon, 5 Jun 2017 15:10:52 -0700
From:   Mark Salyzyn <salyzyn@...roid.com>
To:     Pavel Machek <pavel@....cz>,
        "Rafael J. Wysocki" <rafael@...nel.org>
Cc:     Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Linux PM <linux-pm@...r.kernel.org>,
        Todd Poynor <toddpoynor@...gle.com>,
        "Rafael J. Wysocki" <rjw@...ysocki.net>,
        Len Brown <len.brown@...el.com>
Subject: Re: PM / Suspend: Print wall time at suspend entry and exit

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@...roid.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