Re: [PATCH v5] printk: Add pr_info_show_time

Sergey Senozhatsky
2017-07-21T00:21:08Z

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