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

["Luis R. Rodriguez" <mcgrof@kernel.org>]

On Thu, Aug 03, 2017 at 09:18:44PM -0400, Prarit Bhargava wrote:
> index fc47863f629c..8f093dd0a733 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,8 +1204,119 @@ 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;
> +
> +/**
> + * enum printk_time_type - Timestamp types for printk() messages.
> + * @PRINTK_TIME_DISABLE: 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.  On 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.

You can expand on this or the actual routines that use this in kdoc form.

> + */
> +enum printk_time_type {
> +	PRINTK_TIME_DISABLE = 0,
> +	PRINTK_TIME_LOCAL = 1,
> +	PRINTK_TIME_BOOT = 2,
> +	PRINTK_TIME_MONO = 3,
> +	PRINTK_TIME_REAL = 4,
> +};
> +
> +static const char * const printk_time_str[5] = {
> +	"disabled",
> +	"local hardware",
> +	"boottime",
> +	"monotonic",
> +	"realtime",
> +};
> +
> +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 = PRINTK_TIME_DISABLE;
> +		break;
> +	case '1':
> +	case 'y':
> +	case 'Y':
> +		_printk_time = PRINTK_TIME_LOCAL;
> +		break;
> +	case '2':
> +		_printk_time = PRINTK_TIME_BOOT;
> +		break;
> +	case '3':
> +		_printk_time = PRINTK_TIME_MONO;
> +		break;
> +	case '4':
> +		_printk_time = PRINTK_TIME_REAL;
> +		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 == PRINTK_TIME_DISABLE) {
> +		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(disabled) or %d(%s) ",
> +			printk_time_setting,
> +			printk_time_str[printk_time_setting]);
> +		return -EINVAL;
> +	}
> +
> +	printk_time = _printk_time;
> +	pr_info("printk: timestamp set to %d(%s).",
> +		printk_time, printk_time_str[printk_time]);
> +	return 0;
> +}
> +
> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
> +{
> +	return scnprintf(buffer, PAGE_SIZE, "%d", printk_time);
> +}
> +
> +static struct kernel_param_ops printk_time_ops = {
> +	.set = printk_time_set,
> +	.get = printk_time_get,
> +};
> +module_param_cb(time, &printk_time_ops, NULL, 0644);
> +
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time <= PRINTK_TIME_LOCAL)
> +		return local_clock();
> +
> +	if (printk_time == PRINTK_TIME_BOOT)
> +		return ktime_get_boot_log_ts();
> +
> +	mono = ktime_get_real_log_ts(&offset_real);
> +
> +	if (printk_time == PRINTK_TIME_MONO)
> +		return mono;
> +
> +	return mono + offset_real;
> +}
>  
>  static size_t print_time(u64 ts, char *buf)
>  {
> @@ -1643,7 +1756,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;
>  	}
>  
> @@ -1873,6 +1986,8 @@ 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;
> +static int printk_time_setting;
>  #endif /* CONFIG_PRINTK */
>  
>  #ifdef CONFIG_EARLY_PRINTK
>
> @@ -2659,6 +2774,10 @@ static int __init printk_late_init(void)
>  	struct console *con;
>  	int ret;
>  
> +	/* initialize printk_time settings */
> +	if (printk_time_setting == 0)
> +		printk_time_setting = printk_time;
> +

Note printk_late_init() is a late_initcall(). This means if the
printk_time_setting was disabled it will take a while to enable it. Enabling it
is done at the device_initcall(), so if printk setting is disabled but a user
enables it with a toggle of the module param there is a period of time during
which time resolution would be different. Perhaps for some this is not useful
information but for others I think this would be very valuable.

There is also something to say about the time in between initializing access
to ktime_get_mono_fast_ns(), how early is this reliable?

All these things could be mentioned on the documentation.

  Luis