Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime timestamps

[Petr Mladek <pmladek@suse.com>]

On Tue 2017-09-05 08:06:41, Prarit Bhargava wrote:
> 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 in real time.
> 
> Make printk output different timestamps by adding options for no
> timestamp, the local hardware clock, the monotonic clock, the boottime
> clock, and the real clock.  Allow a user to pick one of the clocks by
> using the printk.time kernel parameter.  Output the type of clock in
> /sys/module/printk/parameters/time so userspace programs can interpret the
> timestamp.
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..5aaeb1ebd26c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,14 +1205,113 @@ 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 void printk_set_ts_func(void)
> +{
> +	switch (printk_time) {
> +	case PRINTK_TIME_LOCAL:
> +	case PRINTK_TIME_DISABLED:
> +	default:
> +		printk_get_ts = local_clock;
> +		break;

This is slightly confusing. One would expect that local_clock()
will be used when "disabled" is written into
/sys/module/printk/parameters/time. But it is not true
because this function is not called in that case.

I know that you do this to avoid recursion in
printk_get_first_ts(), I know because I read the discussion
about an older version of the patch. But this is less
obvious from the code.


> +	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;
> +	}
> +}

I think that it would be cleaner the following way:

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;
}

Then we could avoid the recursion directly in printk_get_first_ts().

> +
> +static u64 printk_get_first_ts(void)
> +{
> +	printk_set_ts_func();

	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 _printk_time = -1;
> +	int ts;
  	int err;
> +
> +	if (strlen(param) == 1) {
> +		/* Preserve legacy boolean settings */
> +		if ((param[0] == '0') || (param[0] == 'n') ||
> +		    (param[0] == 'N'))
> +			_printk_time = PRINTK_TIME_DISABLED;
> +		if ((param[0] == '1') || (param[0] == 'y') ||
> +		    (param[0] == 'Y'))
> +			_printk_time = PRINTK_TIME_LOCAL;
> +	}
> +	if (_printk_time == -1) {
> +		for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) {
> +			if (!strncmp(timestamp_sources_str[ts], param,
> +				     strlen(param))) {
> +				_printk_time = ts;
> +				break;
> +			}
> +		}
> +	}
> +	if (_printk_time == -1) {
> +		pr_warn("printk: invalid timestamp option %s\n", param);
> +		return -EINVAL;
> +	}
> +
> +	printk_time = _printk_time;
> +	if (printk_time > PRINTK_TIME_DISABLED)
> +		printk_set_ts_func();

Finally, we could replace the above two sections by:

	err = printk_set_ts_source(_printk_time);
	if (err) {
		pr_warn("printk: invalid timestamp option %s\n", param);
		return err;
	}

Also I would rename the variable "_pritnk_time" to "time_source"
in this function.

> +	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);

> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index c617b9d1d6cb..e9e1798415fa 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 "CLOCK_BOOTTIME"

s/CLOCK_BOOTTIME/Boot time clock/

It will make it easier to read and consistent with the local
clock option.

> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted boottime clock.
> +
> +config PRINTK_TIME_MONO
> +	bool "CLOCK_MONOTONIC"

same here

> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted monotonic clock.
> +
> +config PRINTK_TIME_REAL
> +	bool "CLOCK_REALTIME"

and here

> +	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
> +

I am still slightly nervous that external tools would need updating.
Also they might have troubles to interpret the time stamps especially
when the source is changed at runtime via
/sys/module/printk/parameters/time.

On the other hand, we do not change the default behavior. You sent
me a patch against dmesg. It was trivial and worked well. Also we
got positive (constructive) feedback from several people. Therefore
I am getting open for this change.

Best Regards,
Petr

PS: Please, do not forget to handle the complains from
Thomas Gleixner in the first patch.