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