Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote:
> Commit-ID:  310b454a8653ea60d3eb21ce5ab03a282a32fbe1
> Gitweb:     http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1
> Author:     Prarit Bhargava <prarit@xxxxxxxxxx>
> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
> Committer:  Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> CommitDate: Tue, 26 Sep 2017 10:38:07 +0200
> 
> printk: Add monotonic, boottime, and realtime timestamps
> 
> printk.time=1/CONFIG_PRINTK_TIME=1 adds a unmodified local hardware clock
> timestamp to printk messages.  The local hardware clock loses time each
> day making it difficult to determine exactly when an issue has occurred in
> the kernel log, and making it difficult to determine how kernel and
> hardware issues relate to each other.
> 
> Make printk output different timestamps by adding options for no timestamp,
> the local hardware clock, monotonic clock, boottime clock, and clock
> realtime. The default clock can be selected via:
> 
>  - Kconfig
>  - Kernel command line parameter
>  - Sysfs file
> 
> Note, that existing user space tools might be confused by selecting clock
> realtime, so handle with care.

pmladek found a compile warning due to printk_time being unused.  I will post a
v14 on LKML shortly.

P.

> 
> [jstultz: Reworked Kconfig settings to avoid defconfig noise]
> 
> Signed-off-by: Prarit Bhargava <prarit@xxxxxxxxxx>
> Signed-off-by: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
> Cc: Joel Fernandes <joelaf@xxxxxxxxxx>
> Cc: Geert Uytterhoeven <geert+renesas@xxxxxxxxx>
> Cc: linux-doc@xxxxxxxxxxxxxxx
> Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
> Cc: Deepa Dinamani <deepa.kernel@xxxxxxxxx>
> Cc: Christoffer Dall <cdall@xxxxxxxxxx>
> Cc: "Jason A. Donenfeld" <Jason@xxxxxxxxx>
> Cc: Jonathan Corbet <corbet@xxxxxxx>
> Cc: "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx>
> Cc: Petr Mladek <pmladek@xxxxxxxx>
> Cc: Kees Cook <keescook@xxxxxxxxxxxx>
> Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
> Cc: Nicholas Piggin <npiggin@xxxxxxxxx>
> Cc: Josh Poimboeuf <jpoimboe@xxxxxxxxxx>
> Cc: Greg Kroah-Hartman <gregkh@xxxxxxxxxxxxxxxxxxx>
> Cc: Stephen Boyd <sboyd@xxxxxxxxxxxxxx>
> Cc: Mark Salyzyn <salyzyn@xxxxxxxxxxx>
> Cc: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
> Cc: "Luis R. Rodriguez" <mcgrof@xxxxxxxxxx>
> Cc: Olof Johansson <olof@xxxxxxxxx>
> Cc: Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx>
> Link: https://lkml.kernel.org/r/1505757060-2004-4-git-send-email-prarit@xxxxxxxxxx
> 
> ---
>  Documentation/admin-guide/kernel-parameters.txt |   6 +-
>  kernel/printk/printk.c                          | 130 +++++++++++++++++++++++-
>  lib/Kconfig.debug                               |  48 ++++++++-
>  3 files changed, 176 insertions(+), 8 deletions(-)
> 
> diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
> index 0549662..9a84483 100644
> --- a/Documentation/admin-guide/kernel-parameters.txt
> +++ b/Documentation/admin-guide/kernel-parameters.txt
> @@ -3211,8 +3211,10 @@
>  			ratelimit - ratelimit the logging
>  			Default: ratelimit
>  
> -	printk.time=	Show timing data prefixed to each printk message line
> -			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
> +	printk.time=	Show timestamp prefixed to each printk message line
> +			Format: <string>
> +				(0/N/n/disable, 1/Y/y/local,
> +				 b/boot, m/monotonic, r/realtime (in UTC))
>  
>  	processor.max_cstate=	[HW,ACPI]
>  			Limit processor to maximum C-state
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 512f7c2..5e0bf2e 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -576,6 +576,9 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
>  	return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
>  }
>  
> +static u64 printk_get_first_ts(void);
> +static u64 (*printk_get_ts)(void) = printk_get_first_ts;
> +
>  /* insert record into the buffer, discard old ones, update heads */
>  static int log_store(int facility, int level,
>  		     enum log_flags flags, u64 ts_nsec,
> @@ -624,7 +627,7 @@ static int log_store(int facility, int level,
>  	if (ts_nsec > 0)
>  		msg->ts_nsec = ts_nsec;
>  	else
> -		msg->ts_nsec = local_clock();
> +		msg->ts_nsec = printk_get_ts();
>  	memset(log_dict(msg) + dict_len, 0, pad_len);
>  	msg->len = size;
>  
> @@ -1201,14 +1204,130 @@ static inline void boot_delay_msec(int level)
>  }
>  #endif
>  
> -static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
> -module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
> +/**
> + * enum timestamp_sources - Timestamp sources for printk() messages.
> + * @PRINTK_TIME_DISABLED: No time stamp.
> + * @PRINTK_TIME_LOCAL: Local hardware clock timestamp.
> + * @PRINTK_TIME_BOOT: Boottime clock timestamp.
> + * @PRINTK_TIME_MONO: Monotonic clock timestamp.
> + * @PRINTK_TIME_REAL: Realtime clock timestamp.
> + */
> +enum timestamp_sources {
> +	PRINTK_TIME_DISABLED = 0,
> +	PRINTK_TIME_LOCAL = 1,
> +	PRINTK_TIME_BOOT = 2,
> +	PRINTK_TIME_MONO = 3,
> +	PRINTK_TIME_REAL = 4,
> +};
> +
> +static const char * const timestamp_sources_str[5] = {
> +	"disabled",
> +	"local",
> +	"boottime",
> +	"monotonic",
> +	"realtime",
> +};
> +
> +static int printk_time = CONFIG_PRINTK_TIME_TYPE;
> +
> +static int printk_set_ts_source(enum timestamp_sources ts_source)
> +{
> +	int err = 0;
> +
> +	switch (ts_source) {
> +	case PRINTK_TIME_LOCAL:
> +		printk_get_ts = local_clock;
> +		break;
> +	case PRINTK_TIME_BOOT:
> +		printk_get_ts = ktime_get_boot_fast_ns;
> +		break;
> +	case PRINTK_TIME_MONO:
> +		printk_get_ts = ktime_get_mono_fast_ns;
> +		break;
> +	case PRINTK_TIME_REAL:
> +		printk_get_ts = ktime_get_real_fast_ns;
> +		break;
> +	case PRINTK_TIME_DISABLED:
> +	/*
> +	 * The timestamp is always stored into the log buffer.
> +	 * Keep the current one.
> +	 */
> +		break;
> +	default:
> +		err = -EINVAL;
> +		break;
> +	}
> +
> +	if (!err)
> +		printk_time = ts_source;
> +	return err;
> +}
> +
> +static u64 printk_get_first_ts(void)
> +{
> +	printk_set_ts_source(printk_time);
> +
> +	/* Fallback for invalid or disabled timestamp source */
> +	if (printk_get_ts == printk_get_first_ts)
> +		printk_get_ts = local_clock;
> +
> +	return printk_get_ts();
> +}
> +
> +static int param_set_time(const char *val, const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +	int time_source = -1;
> +	int ts;
> +	int err;
> +
> +	if (strlen(param) == 1) {
> +		/* Preserve legacy boolean settings */
> +		if ((param[0] == '0') || (param[0] == 'n') ||
> +		    (param[0] == 'N'))
> +			time_source = PRINTK_TIME_DISABLED;
> +		if ((param[0] == '1') || (param[0] == 'y') ||
> +		    (param[0] == 'Y'))
> +			time_source = PRINTK_TIME_LOCAL;
> +	}
> +	if (time_source == -1) {
> +		for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) {
> +			if (!strncmp(timestamp_sources_str[ts], param,
> +				     strlen(param))) {
> +				time_source = ts;
> +				break;
> +			}
> +		}
> +	}
> +
> +	err = printk_set_ts_source(time_source);
> +	if (err) {
> +		pr_warn("printk: invalid timestamp option %s\n", param);
> +		return err;
> +	}
> +
> +	pr_info("printk: timestamp set to %s\n",
> +		timestamp_sources_str[printk_time]);
> +	return 0;
> +}
> +
> +static int param_get_time(char *buffer, const struct kernel_param *kp)
> +{
> +	return scnprintf(buffer, PAGE_SIZE, "%s",
> +			 timestamp_sources_str[printk_time]);
> +}
> +
> +static struct kernel_param_ops printk_time_ops = {
> +	.set = param_set_time,
> +	.get = param_get_time,
> +};
> +module_param_cb(time, &printk_time_ops, NULL, 0644);
>  
>  static size_t print_time(u64 ts, char *buf)
>  {
>  	unsigned long rem_nsec;
>  
> -	if (!printk_time)
> +	if (printk_time == PRINTK_TIME_DISABLED)
>  		return 0;
>  
>  	rem_nsec = do_div(ts, 1000000000);
> @@ -1631,7 +1750,7 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
>  		cont.facility = facility;
>  		cont.level = level;
>  		cont.owner = current;
> -		cont.ts_nsec = local_clock();
> +		cont.ts_nsec = printk_get_ts();
>  		cont.flags = flags;
>  	}
>  
> @@ -1861,6 +1980,7 @@ static size_t msg_print_text(const struct printk_log *msg,
>  			     bool syslog, char *buf, size_t size) { return 0; }
>  static bool suppress_message_printing(int level) { return false; }
>  
> +static int printk_time;
>  #endif /* CONFIG_PRINTK */
>  
>  #ifdef CONFIG_EARLY_PRINTK
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 2689b7c..c6401d3 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -8,12 +8,58 @@ config PRINTK_TIME
>  	  messages to be added to the output of the syslog() system
>  	  call and at the console.
>  
> +choice
> +	prompt "printk default clock timestamp" if PRINTK_TIME
> +	default PRINTK_TIME_LOCAL if PRINTK_TIME
> +	help
> +	  This option is selected by setting one of
> +	  PRINTK_TIME_[DISABLE|LOCAL|BOOT|MONO|REAL] and causes time stamps of
> +	  the printk() messages to be added to the output of the syslog()
> +	  system call and at the console.
> +
>  	  The timestamp is always recorded internally, and exported
>  	  to /dev/kmsg. This flag just specifies if the timestamp should
>  	  be included, not that the timestamp is recorded.
>  
>  	  The behavior is also controlled by the kernel command line
> -	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
> +	  parameter printk.time. See
> +	  Documentation/admin-guide/kernel-parameters.rst
> +
> +config PRINTK_TIME_LOCAL
> +	bool "Local Clock"
> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the unadjusted hardware clock.
> +
> +config PRINTK_TIME_BOOT
> +	bool "Boot Time Clock"
> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted boottime clock.
> +
> +config PRINTK_TIME_MONO
> +	bool "Monotonic Clock"
> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted monotonic clock.
> +
> +config PRINTK_TIME_REAL
> +	bool "Real Time Clock"
> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted realtime clock (UTC).
> +endchoice
> +
> +config PRINTK_TIME_TYPE
> +	int
> +	depends on PRINTK
> +	range 0 4
> +	default 0 if !PRINTK_TIME
> +	default 1 if PRINTK_TIME_LOCAL
> +	default 2 if PRINTK_TIME_BOOT
> +	default 3 if PRINTK_TIME_MONO
> +	default 4 if PRINTK_TIME_REAL
> +
>  
>  config CONSOLE_LOGLEVEL_DEFAULT
>  	int "Default console loglevel (1-15)"
>