Re: [PATCH v2] printk: Add boottime and real timestamps

[Luis R. Rodriguez]

On Tue, Aug 01, 2017 at 08:55:28AM -0400, Prarit Bhargava wrote:
> diff --git a/arch/x86/configs/x86_64_defconfig b/arch/x86/configs/x86_64_defconfig
> index 4a4b16e56d35..23da8e5297a1 100644
> --- a/arch/x86/configs/x86_64_defconfig
> +++ b/arch/x86/configs/x86_64_defconfig
> @@ -283,7 +283,13 @@ CONFIG_NLS_CODEPAGE_437=y
>  CONFIG_NLS_ASCII=y
>  CONFIG_NLS_ISO8859_1=y
>  CONFIG_NLS_UTF8=y
> -CONFIG_PRINTK_TIME=y
> +# CONFIG_PRINTK_TIME_DISABLE is not set
> +CONFIG_PRINTK_TIME_LOCAL=Y
> +# CONFIG_PRINTK_TIME_DISABLE is not set
> +CONFIG_PRINTK_TIME_LOCAL=Y
> +# CONFIG_PRINTK_TIME_DISABLE is not set
> +CONFIG_PRINTK_TIME_LOCAL=Y
> +CONFIG_PRINTK_TIME=1
>  # CONFIG_ENABLE_WARN_DEPRECATED is not set
>  CONFIG_MAGIC_SYSRQ=y
>  # CONFIG_UNUSED_SYMBOLS is not set

You've gone trigger paste happy here.

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..672a649b90d8 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -576,6 +576,8 @@ 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_ts(void);
> +
>  /* 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 +626,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;
>  
> @@ -1202,8 +1204,89 @@ 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);
> +static int printk_time = CONFIG_PRINTK_TIME;
> +static int printk_time_setting; /* initial setting */

If you use an enum for printk_time_setting you can then kdoc'ify
each setting and also match the values names on kconfig. With this
you can move the big comment below onto the kdoc for the enum.
You can then nicely expand on the documentation to explain what
compromises were made for providing time if timekeeping_init() was
not called yet.

/**
 * enum printk_time_setting - description
 * @PRINTK_TIME_DISABLE: description
 * @PRINTK_TIME_LOCAL: description
 * @PRINTK_TIME_MONO: description
 * @PRINTK_TIME_REAL: description - you can go into the 32-bit issue here
 */
enum printk_time_setting {
	PRINTK_TIME_DISABLE = 0,
	PRINTK_TIME_LOCAL = 1,
	PRINTK_TIME_MONO = 2,
	PRINTK_TIME_REAL = 3,
};

And since you are kdoc'ifying consider later adding proper rst format docs
for printk and then pegging this kdoc entry into it. Unfortunately I only
see Documentation/printk-formats.txt and Documentation/x86/earlyprintk.txt,
is that all we have on printk docs?

> +
> +/*
> + * Real clock & 32-bit systems:  Selecting the real clock printk timestamp may
> + * lead to unlikely situations where a timestamp is wrong because the real time
> + * offset is read without the protection of a sequence lock in the call to
> + * ktime_get_log_ts() in printk_get_ts() below.
> + */
> +static int printk_time_set(const char *val, const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +	int _printk_time;
> +
> +	if (strlen(param) != 1)
> +		return -EINVAL;
> +
> +	switch (param[0]) {
> +	case '0':
> +	case 'n':
> +	case 'N':
> +		_printk_time = 0; /* none/disabled */
> +		break;
> +	case '1':
> +	case 'y':
> +	case 'Y':
> +		_printk_time = 1; /* local unadjusted HW clock */
> +		break;
> +	case '2':
> +		_printk_time = 2; /* monotonic */
> +		break;
> +	case '3':
> +		_printk_time = 3; /* realtime */
> +		break;
> +	default:
> +		pr_warn("printk: invalid timestamp value\n");
> +		return -EINVAL;
> +	}
> +
> +	/*
> +	 * Only allow enabling and disabling of the current printk_time
> +	 * setting.  Changing it from one setting to another confuses
> +	 * userspace.
> +	 */
> +	if (printk_time_setting == 0) {
> +		printk_time_setting = _printk_time;
> +	} else if ((printk_time_setting != _printk_time) &&
> +		   (_printk_time != 0)) {
> +		pr_warn("printk: timestamp can only be set to 0 or %d ",
> +			printk_time_setting);
> +		return -EINVAL;
> +	}
> +
> +	printk_time = _printk_time;
> +	pr_info("printk: timestamp set to %d.", printk_time);

Then here you can also add a respective conversion for describing what the enum
was, "%s (%d)", printk_time_desc(printk_time), printk_time) which will make it
easier to understand what was done at init in the log.

  Luis