[PATCH v5] printk: Add pr_info_show_time

[PATCH v5] printk: Add pr_info_show_time

[Mark Salyzyn]

Primary purpose of pr_info_show_time() is to provide a marker used for
post-mortem Battery and Power analysis.  These markers are to be
placed at major discontinuities of time and power level.  An optional
timestamp is added to aid the post-mortem or delayed analysis.  This
function is to be called at a level where the associated timekeeping
is active and available.  pr_info_show_time() is functionally the same
as pr_info(), except for the ability to add an alternate time prefix
to the message.

For example, the persistent clock that is used to report
"Suspended for" message, although very useful, is not present on all
platforms.  It is currently standardized for millisecond precision.
Thus pr_info_show_time would be used at a higher level to aid power
analysis.

An added value to the time report is the ability in post-mortem
triage analysis to synchronize kernel logging activities in MONOTONIC
time with user space logging activities in REALTIME or BOOTTIME.

Feature activated by CONFIG_PR_INFO_SHOW_TIME_<TYPE>, where <TYPE> is:

MONOTONIC - default, disabled time prefix because dmesg logs already
            are reported in monotonic.
REALTIME - Add a [<epoch>.<nanoseconds>U] prefix to the message to
           report getnstimeofday64() collected timestamp.
BOOTTIME - Add a [<seconds>.<nanoseconds>B] prefix to the message to
           report getboottime64() collected timestamp.

Since this is for post mortem field analysis, there is no debugfs or
trace facility that can generally be leveraged.  For example
analyze_suspend.py requires a debug configured kernel, on the other
hand these pr_info_show_time prints can remain in a field product.
The purpose for pr_info_show_time is not necessarily for development
debugging.

Data collected may be recorded by klogd with a longer logspan than the
built-in dmesg buffer, or land in pstore console driver to be collected
after a reboot.

Signed-off-by: Mark Salyzyn <salyzyn@android.com>

v2:
- move implementation to kernel timekeeping from rtc_lib files
- use rtc_time64_to_tm() instead of rtc_time_to_tm()
- use inline in include/linux/rtc.h for !CONFIG_RTC_SHOW_TIME
v3:
- _correctly_ use rtc_time64_to_tm
v4:
- introduce CONFIG_RTC_SHOW_TIME_<TYPE> and split off rtc time
  format printing to a separate patch.
v5:
- change function to pr_info_show_time
- remove dependent patches from the series to ease discussion.

---
 include/linux/printk.h | 30 +++++++++++++++++++++++++++++
 lib/Kconfig.debug      | 52 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 82 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..c1283a893cc1 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -306,6 +306,36 @@ extern asmlinkage void dump_stack(void) __cold;
 	printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_info(fmt, ...) \
 	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+
+/*
+ * pr_info_show_time() prefixes an alternate time prefix as selected by
+ * CONFIG_PR_INFO_SHOW_TIME_<TYPE>.  The time is prefixed on the message
+ * as "[<seconds>.<nseconds><typchar>] ". <TYPE> in the config selection
+ * can be one of the following:
+ *
+ * MONOTONIC - (default) print no alternate time, monotonic is part of dmesg.
+ * BOOTTIME - Adds a message prefix with getboottime64() values.
+ * REALTIME - Adds a message prefix with getnstimeofday64() values.
+ */
+#if defined(CONFIG_PR_INFO_SHOW_TIME_BOOTTIME)
+#define pr_info_show_time(fmt, ...) ({	\
+	struct timespec64 ts;		\
+					\
+	getboottime64(&ts);		\
+	pr_info("[%5lu.%09luB] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
+#include <linux/time64.h>
+#elif defined(CONFIG_PR_INFO_SHOW_TIME_REALTIME)
+#define pr_info_show_time(fmt, ...) ({	\
+	struct timespec64 ts;		\
+					\
+	getnstimeofday64(&ts);		\
+	pr_info("[%lu.%09luU] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
+#include <linux/time64.h>
+#else
+#define pr_info_show_time(fmt, ...) \
+	pr_info(fmt, ##__VA_ARGS__)
+#endif
+
 /*
  * Like KERN_CONT, pr_cont() should only be used when continuing
  * a line with no newline ('\n') enclosed. Otherwise it defaults
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 98fe715522e8..0d63c3fb4e24 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -30,6 +30,58 @@ config CONSOLE_LOGLEVEL_DEFAULT
 	  usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
 	  option.
 
+# set if time is being printed in pr_info_show_time()
+config PR_INFO_SHOW_TIME
+	bool
+
+choice
+	prompt "pr_info_show_time() alternate time message prefix"
+	help
+	  Activate alternate time prefix in pr_info_show_time
+
+	  The primary use of the instrumentation is to aid field
+	  analysis of Battery and Power usage.  The instrumentation
+	  may also help triage and synchronize kernel logs and user
+	  space activity logs at key displacements.
+	config PR_INFO_SHOW_TIME_MONOTONIC
+		bool "monotonic"
+		help
+		  Deactivate alternate time prefix in pr_info_show_time.
+		  Doing so because monotonic time is part of the normal
+		  printk time logging.
+
+		  Print only the supplied message in pr_info_show_time,
+		  indistinguishable from pr_info.
+	config PR_INFO_SHOW_TIME_REALTIME
+		bool "realtime"
+		select PR_INFO_SHOW_TIME
+		help
+		  Activate alternate time prefix in pr_info_show_time
+
+		  The primary use of the instrumentation is to aid field
+		  analysis of Battery and Power usage.  The instrumentation
+		  may also help triage and synchronize kernel logs and user
+		  space activity logs at key displacements.  For instance
+		  CLOCK_MONOTONIC stops while suspended, while CLOCK_REALTIME
+		  continues, and the timestamps help re-orient post-analysis.
+
+		  Prefix realtime [<epoch>.<ns>U] timestamp in pr_info_show_time
+	config PR_INFO_SHOW_TIME_BOOTTIME
+		bool "boottime"
+		select PR_INFO_SHOW_TIME
+		help
+		  Activate alternate time prefix in pr_info_show_time
+
+		  The primary use of the instrumentation is to aid field
+		  analysis of Battery and Power usage.  The instrumentation
+		  may also help triage and synchronize kernel logs and user
+		  space activity logs at key displacements.  For instance
+		  CLOCK_MONOTONIC stops while suspended, while CLOCK_BOOTTIME
+		  continues, and the timestamps help re-orient post-analysis.
+
+		  Prefix boottime [<epoch>.<ns>B] timestamp in pr_info_show_time
+endchoice
+
 config MESSAGE_LOGLEVEL_DEFAULT
 	int "Default message log level (1-7)"
 	range 1 7
-- 
2.14.0.rc0.284.gd933b75aa4-goog

Re: [PATCH v5] printk: Add pr_info_show_time

[Sergey Senozhatsky]

On (07/20/17 11:24), Mark Salyzyn wrote:
> Primary purpose of pr_info_show_time() is to provide a marker used for
> post-mortem Battery and Power analysis.  These markers are to be
> placed at major discontinuities of time and power level.

so shouldn't that just be under CONFIG_PM_DEBUG or even
CONFIG_PM_ADVANCED_DEBUG and, hence, be implemented somewhere
in PM? I just don't see why this needs to be in printk.

without the users or (at least) examples that would demonstrate
why this is more useful than local_clock(), which we already append
to every message, it's rather hard for me to judge.

[..]
> +/*
> + * pr_info_show_time() prefixes an alternate time prefix as selected by
> + * CONFIG_PR_INFO_SHOW_TIME_<TYPE>.  The time is prefixed on the message
> + * as "[<seconds>.<nseconds><typchar>] ". <TYPE> in the config selection
> + * can be one of the following:
> + *
> + * MONOTONIC - (default) print no alternate time, monotonic is part of dmesg.
> + * BOOTTIME - Adds a message prefix with getboottime64() values.
> + * REALTIME - Adds a message prefix with getnstimeofday64() values.
> + */
> +#if defined(CONFIG_PR_INFO_SHOW_TIME_BOOTTIME)
> +#define pr_info_show_time(fmt, ...) ({	\
> +	struct timespec64 ts;		\
> +					\
> +	getboottime64(&ts);		\
> +	pr_info("[%5lu.%09luB] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
> +#include <linux/time64.h>
> +#elif defined(CONFIG_PR_INFO_SHOW_TIME_REALTIME)
> +#define pr_info_show_time(fmt, ...) ({	\
> +	struct timespec64 ts;		\
> +					\
> +	getnstimeofday64(&ts);		\
> +	pr_info("[%lu.%09luU] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
> +#include <linux/time64.h>
> +#else
> +#define pr_info_show_time(fmt, ...) \
> +	pr_info(fmt, ##__VA_ARGS__)
> +#endif

so why just pr_info()? what about pr_err(), pr_crit() and so on?

>  /*
>   * Like KERN_CONT, pr_cont() should only be used when continuing
>   * a line with no newline ('\n') enclosed. Otherwise it defaults
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 98fe715522e8..0d63c3fb4e24 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -30,6 +30,58 @@ config CONSOLE_LOGLEVEL_DEFAULT
>  	  usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
>  	  option.
>  
> +# set if time is being printed in pr_info_show_time()
> +config PR_INFO_SHOW_TIME
> +	bool

we all love Kconfig, don't we? ;)


> +choice
> +	prompt "pr_info_show_time() alternate time message prefix"
> +	help
> +	  Activate alternate time prefix in pr_info_show_time
> +
> +	  The primary use of the instrumentation is to aid field
> +	  analysis of Battery and Power usage.  The instrumentation
> +	  may also help triage and synchronize kernel logs and user
> +	  space activity logs at key displacements.
> +	config PR_INFO_SHOW_TIME_MONOTONIC
> +		bool "monotonic"
> +		help
> +		  Deactivate alternate time prefix in pr_info_show_time.
> +		  Doing so because monotonic time is part of the normal
> +		  printk time logging.
> +
> +		  Print only the supplied message in pr_info_show_time,
> +		  indistinguishable from pr_info.

I think this should not exist. a new Kconfig option to enable
something that is already there?


> +	config PR_INFO_SHOW_TIME_REALTIME
> +		bool "realtime"
> +		select PR_INFO_SHOW_TIME
> +		help
> +		  Activate alternate time prefix in pr_info_show_time
> +
> +		  The primary use of the instrumentation is to aid field
> +		  analysis of Battery and Power usage.  The instrumentation
> +		  may also help triage and synchronize kernel logs and user
> +		  space activity logs at key displacements.  For instance
> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_REALTIME
> +		  continues, and the timestamps help re-orient post-analysis.
> +
> +		  Prefix realtime [<epoch>.<ns>U] timestamp in pr_info_show_time
> +	config PR_INFO_SHOW_TIME_BOOTTIME
> +		bool "boottime"
> +		select PR_INFO_SHOW_TIME
> +		help
> +		  Activate alternate time prefix in pr_info_show_time
> +
> +		  The primary use of the instrumentation is to aid field
> +		  analysis of Battery and Power usage.  The instrumentation
> +		  may also help triage and synchronize kernel logs and user
> +		  space activity logs at key displacements.  For instance
> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_BOOTTIME
> +		  continues, and the timestamps help re-orient post-analysis.
> +
> +		  Prefix boottime [<epoch>.<ns>B] timestamp in pr_info_show_time
> +endchoice


dunno, I'm still not sure I see why this "add a special prefix to some
messages" needs to be part of generic printk(). sorry.

	-ss

Re: [PATCH v5] printk: Add pr_info_show_time

[Luis R. Rodriguez]

On Thu, Jul 20, 2017 at 11:24:22AM -0700, Mark Salyzyn wrote:
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 98fe715522e8..0d63c3fb4e24 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -30,6 +30,58 @@ config CONSOLE_LOGLEVEL_DEFAULT
>  	  usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
>  	  option.
>  
> +# set if time is being printed in pr_info_show_time()
> +config PR_INFO_SHOW_TIME
> +	bool
> +
> +choice
> +	prompt "pr_info_show_time() alternate time message prefix"
> +	help
> +	  Activate alternate time prefix in pr_info_show_time
> +
> +	  The primary use of the instrumentation is to aid field
> +	  analysis of Battery and Power usage.  The instrumentation
> +	  may also help triage and synchronize kernel logs and user
> +	  space activity logs at key displacements.
> +	config PR_INFO_SHOW_TIME_MONOTONIC
> +		bool "monotonic"
> +		help
> +		  Deactivate alternate time prefix in pr_info_show_time.
> +		  Doing so because monotonic time is part of the normal
> +		  printk time logging.
> +
> +		  Print only the supplied message in pr_info_show_time,
> +		  indistinguishable from pr_info.
> +	config PR_INFO_SHOW_TIME_REALTIME
> +		bool "realtime"
> +		select PR_INFO_SHOW_TIME
> +		help
> +		  Activate alternate time prefix in pr_info_show_time
> +
> +		  The primary use of the instrumentation is to aid field
> +		  analysis of Battery and Power usage.  The instrumentation
> +		  may also help triage and synchronize kernel logs and user
> +		  space activity logs at key displacements.  For instance
> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_REALTIME
> +		  continues, and the timestamps help re-orient post-analysis.
> +
> +		  Prefix realtime [<epoch>.<ns>U] timestamp in pr_info_show_time
> +	config PR_INFO_SHOW_TIME_BOOTTIME
> +		bool "boottime"
> +		select PR_INFO_SHOW_TIME
> +		help
> +		  Activate alternate time prefix in pr_info_show_time
> +
> +		  The primary use of the instrumentation is to aid field
> +		  analysis of Battery and Power usage.  The instrumentation
> +		  may also help triage and synchronize kernel logs and user
> +		  space activity logs at key displacements.  For instance
> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_BOOTTIME
> +		  continues, and the timestamps help re-orient post-analysis.
> +
> +		  Prefix boottime [<epoch>.<ns>B] timestamp in pr_info_show_time
> +endchoice

There is no depends magic anywhere here, so none of this actually has complex
dependencies, this is just boot time preference setup, and for that I think a
boot param and sysctl value could easily not only enable the same but *also*
enable run time ability to swap between these. Even for the branch performance
consideration can't jump labels be used to address that if there is a concern
for that?

I think that would also make the code easier to read and remove all this kconfig
extra stuff. Then its just a run time thing.

Also, should there be no checks for time being available and ready before this
is used?

  Luis

Re: [PATCH v5] printk: Add pr_info_show_time

[Mark Salyzyn]

On 07/20/2017 07:00 PM, Luis R. Rodriguez wrote:
> On Thu, Jul 20, 2017 at 11:24:22AM -0700, Mark Salyzyn wrote:
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 98fe715522e8..0d63c3fb4e24 100644
>> --- a/lib/Kconfig.debug
>> +++ b/lib/Kconfig.debug
>> @@ -30,6 +30,58 @@ config CONSOLE_LOGLEVEL_DEFAULT
>>   	  usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
>>   	  option.
>>   
>> +# set if time is being printed in pr_info_show_time()
>> +config PR_INFO_SHOW_TIME
>> +	bool
>> +
>> +choice
>> +	prompt "pr_info_show_time() alternate time message prefix"
>> +	help
>> +	  Activate alternate time prefix in pr_info_show_time
>> +
>> +	  The primary use of the instrumentation is to aid field
>> +	  analysis of Battery and Power usage.  The instrumentation
>> +	  may also help triage and synchronize kernel logs and user
>> +	  space activity logs at key displacements.
>> +	config PR_INFO_SHOW_TIME_MONOTONIC
>> +		bool "monotonic"
>> +		help
>> +		  Deactivate alternate time prefix in pr_info_show_time.
>> +		  Doing so because monotonic time is part of the normal
>> +		  printk time logging.
>> +
>> +		  Print only the supplied message in pr_info_show_time,
>> +		  indistinguishable from pr_info.
>> +	config PR_INFO_SHOW_TIME_REALTIME
>> +		bool "realtime"
>> +		select PR_INFO_SHOW_TIME
>> +		help
>> +		  Activate alternate time prefix in pr_info_show_time
>> +
>> +		  The primary use of the instrumentation is to aid field
>> +		  analysis of Battery and Power usage.  The instrumentation
>> +		  may also help triage and synchronize kernel logs and user
>> +		  space activity logs at key displacements.  For instance
>> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_REALTIME
>> +		  continues, and the timestamps help re-orient post-analysis.
>> +
>> +		  Prefix realtime [<epoch>.<ns>U] timestamp in pr_info_show_time
>> +	config PR_INFO_SHOW_TIME_BOOTTIME
>> +		bool "boottime"
>> +		select PR_INFO_SHOW_TIME
>> +		help
>> +		  Activate alternate time prefix in pr_info_show_time
>> +
>> +		  The primary use of the instrumentation is to aid field
>> +		  analysis of Battery and Power usage.  The instrumentation
>> +		  may also help triage and synchronize kernel logs and user
>> +		  space activity logs at key displacements.  For instance
>> +		  CLOCK_MONOTONIC stops while suspended, while CLOCK_BOOTTIME
>> +		  continues, and the timestamps help re-orient post-analysis.
>> +
>> +		  Prefix boottime [<epoch>.<ns>B] timestamp in pr_info_show_time
>> +endchoice
> There is no depends magic anywhere here, so none of this actually has complex
> dependencies, this is just boot time preference setup, and for that I think a
> boot param and sysctl value could easily not only enable the same but *also*
> enable run time ability to swap between these. Even for the branch performance
> consideration can't jump labels be used to address that if there is a concern
> for that?
Can we walk before we run? config parameters would still be needed to 
establish the default given that hibernate restore() happens before 
init() is even started. Boot parameters are on some Android platforms 
stretched to the limit and are under the control of the BootLoader which 
differs from the tools needs.

In Android's battery analysis case, there is no reason to change it at 
runtime, and would lead to confusion or DOSing of the facilities.

Once we are outside of the pr_info macros and the convenience of 
##__VA_ARGS__, we will have to code up vsprintf functionality and off to 
a buffer, so I am still pressuring myself to inline the facility even if 
we add boot params and/or sysctl.

Those changes can be added later?
> I think that would also make the code easier to read and remove all this kconfig
> extra stuff. Then its just a run time thing.
>
> Also, should there be no checks for time being available and ready before this
> is used?

Agreed, I started out in PM, RTC and others, it was safe. Once I declare 
a General Use function in printk.h I doomed the function(s) to abuse. 
(However, all the use cases are currently _only_ when time is 
available). Will look into protecting it.
>
>    Luis

-- Mark

Re: [PATCH v5] printk: Add pr_info_show_time

[Pavel Machek]

> For example, the persistent clock that is used to report
> "Suspended for" message, although very useful, is not present on all
> platforms.  It is currently standardized for millisecond precision.

Fix that on your platforms, instead?

								Pavel

Re: [PATCH v5] printk: Add pr_info_show_time

[Mark Salyzyn]

On 07/22/2017 02:40 AM, Pavel Machek wrote:
>> For example, the persistent clock that is used to report
>> "Suspended for" message, although very useful, is not present on all
>> platforms.  It is currently standardized for millisecond precision.
> Fix that on your platforms, instead?
>
> 								Pavel

lol :-)

That is a _hardware_ issue. For a vast majority of them, the persistent 
read-only clock requires a LTE, always-on ready to wakeup device for a 
phone call, correction factor from a separate driver. In some cases the 
persistent clock requires a hardware re-init sequence to a pmic 
controller that occurs higher up in the resume chain. For those where it 
is possible, please remember there are 25K different Android devices, 
represented in nearly 2B hands. Feel free to tell all the implementors 
just how important a continuously accessible working 100% tuned accurate 
persistent clock is when _this_ _one_ flawed (ms accuracy, no lte 
correction while asleep) print is the only place which gains from said 
access ;-). I am blue in the face just working with the limited set I 
have influence on.

And yet, add a simple print of realtime clock at suspend and resume 
points higher up in the chain always works regardless of the hardware or 
the driver skills of the vendor building the devices.


-- Mark