Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 08/23/2017 04:45 AM, Petr Mladek wrote:
> On Thu 2017-08-17 09:15:39, 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..3c46217629fd 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1202,14 +1205,144 @@ 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_TYPE;
>> +static int printk_time_source;
>> +
>> +/**
>> + * enum timestamp_sources - Timestamp sources for printk() messages.
>> + * @PRINTK_TIME_UNDEFINED: Timestamp undefined.  This option is not selectable
>> + * from the configs, and is used as a reference in the code.
>> + * @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 when printk_get_ts() is set to
>> + * printk_get_real_ns().
>> + */
>> +enum timestamp_sources {
> 
> I guess that this might be static. Also it is related to the
> PRINTK_TIME_TYPE Kconfig option. So the name should be
> enum printk_time_type or so.
> 
> 
>> +	PRINTK_TIME_UNDEFINED = 0,
> 
> I would use -1 for PRINTK_TIME_UNDEFINED or I would remove it
> completely, see below. Then we could use 0 for PRINTK_TIME_DISABLED
> which is more expected.

FIXED along with adjustment of configs (see below).

> 
> 
>> +	PRINTK_TIME_DISABLE = 1,
> 
> This should be PRINTK_TIME_DISABLED to be in sync with
> the string and style of the other flags.
>

FIXED.

> 
>> +	PRINTK_TIME_LOCAL = 2,
>> +	PRINTK_TIME_BOOT = 3,
>> +	PRINTK_TIME_MONO = 4,
>> +	PRINTK_TIME_REAL = 5,
>> +};
>> +
>> +static const char * const timestamp_sources_str[6] = {
>> +	"undefined",
> 
> Do we really need the string "undefined"? 

It is only included to keep timestamp_sources_str & the enum in sync.
FIXED & removed with adjustment of configs & enum.

<snip>

>> +/**
>> + * printk_get_real_ns: - Return a realtime timestamp for printk messages
>> + * 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.
>> + */
>> +static u64 printk_get_real_ns(void)
>> +{
>> +	return ktime_get_mono_fast_ns() + ktime_get_real_offset();
>> +}
>> +
>> +static u64 printk_set_timestamp(void)
> 
> I would rename this function to printk_set_ts_func() or so.
> It will be more clear the it sets the function pointer.
> 

FIXED.

> 
>> +{
>> +	switch (printk_time) {
>> +	case PRINTK_TIME_LOCAL:
>> +	case PRINTK_TIME_DISABLE:
>> +	default:
>> +		printk_get_ts = local_clock;
> 
> The PRINTK_TIME_DISABLE case is more complicated. We should set
> printk_get_ts only when it has not been set yet. Otherwise,
> we should keep storing the same type of time stamps into
> to the log buffer and keep it consistent.
> 

I think you've figured this out below.... but for other readers,
printk_time_set() does not call printk_set_timestamp with
printk_time = PRINTK_TIME_DISABLE.

> 
>> +		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 = printk_get_real_ns;
>> +		break;
>> +	}
>> +	return printk_get_ts();
> 
> On one hand, this side effect helps to reuse the same code but it
> looks too hacky to me. Another possibility would be to create:
> 
> static u64 printk_get_first_ts()
> {
> 	printk_set_ts_function();
> 
> 	return printk_get_ts();
> }
> 
> and initialize:
> 
> static u64 (*printk_get_ts)(void) = printk_get_first_ts();
> 

FIXED.

> Another side effect is that we might not need PRINTK_TIME_UNDEFINED.
> 

I tried to do this, however, I still need PRINTK_TIME_UNDEFINED to indicate
that printk_time_source is not set.  PRINTK_TIME_UNDEFINED "reads" better IMO.
>From your comment it looks like you're okay with me leaving it defined, just
not as 0.  I have changed it to -1.  FIXED.

> 
>> +}
>> +
>> +static int printk_time_set(const char *val, const struct kernel_param *kp)
>> +{
>> +	char *param = strstrip((char *)val);
>> +	int _printk_time = PRINTK_TIME_UNDEFINED;
>> +	int ts;
>> +
>> +	if (strlen(param) == 1) {
>> +		/* Preserve legacy boolean settings */
>> +		if ((param[0] == '0') || (param[0] == 'n') ||
>> +		    (param[0] == 'N'))
>> +			_printk_time = PRINTK_TIME_DISABLE;
>> +		if ((param[0] == '1') || (param[0] == 'y') ||
>> +		    (param[0] == 'Y'))
>> +			_printk_time = PRINTK_TIME_LOCAL;
>> +	}
>> +	if (_printk_time == PRINTK_TIME_UNDEFINED) {
>> +		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 == PRINTK_TIME_UNDEFINED) {
>> +		pr_warn("printk: invalid timestamp option %s\n", param);
>> +		return -EINVAL;
>> +	}
>> +
>> +	if (printk_time_source == PRINTK_TIME_UNDEFINED)
>> +		printk_time_source = _printk_time;
>> +#ifndef PRINTK_TIME_DEBUG
>> +	else if ((printk_time_source != _printk_time) &&
>> +		 (_printk_time != PRINTK_TIME_DISABLE)) {
>> +		/*
>> +		 * Only allow enabling and disabling of the current printk_time
>> +		 * setting.  Changing it from one setting to another confuses
>> +		 * userspace.
>> +		 */
>> +		pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
>> +			timestamp_sources_str[printk_time_source]);
>> +		return -EINVAL;
>> +	}
>> +#endif
> 
> Do we really need this complication? I guess that people will

This has been requested multiple times by Mark Salyzyn <salyzyn@xxxxxxxxxxx>.
It does not add any additional complexity beyond a (recently requested)
config option.  I like the option FWIW and I just forgot to include it (sorry
Mark) in earlier versions.  I like Mark's idea of adding 'b', r', etc.,
to the timestamps but have put it off for future effort... but your suggestion
below is a better approach [1].  After some discussion with Mark,
I'll see what I can do after this initial patchset is completed.

<snip>

> 
> 
> And this brings an important question. Do you have any plans
> to update userspace for this change (dmesg, crash, syslogd,
> other loggers)?

I mentioned this in an earlier version of these patches -- I have code for
dmesg.  crash, as I said before, doesn't need to be modified according to
Dave Anderson.  dmesg, from util-linux, requires *this* patchset to be in
Linus' tree before they will even look at a patch.

> 
> If I compile the kernel with CONFIG_PRINTK_TIME_LOCAL=y
> and boot with printk.time=realtime. Then I get
> the following output from dmesg --time-format=iso:
> 
> 2017-08-23T09:38:10,000000+0200 RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
> 2017-08-23T09:38:10,000000+0200 NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16
> 2017-08-23T09:38:10,000000+0200         Offload RCU callbacks from CPUs: .
> 2065-04-14T17:16:20,287498+0200 Console: colour dummy device 80x25
> 2065-04-14T17:16:20,287498+0200 console [tty0] enabled
> 2065-04-14T17:16:20,287498+0200 console [ttyS0] enabled
> 

Yes, you've pointed this out before and I have a solution for dmesg.

> I would like to see patches for at least one tool (dmesg)
> that would make it working properly. It will prove that
> the kernel side allows userspace to handle this
> a reasonable way.
> 
> 
>> +
>> +	printk_time = _printk_time;
>> +	if (printk_time_source > PRINTK_TIME_DISABLE)
> 
> Ah, this actually prevents replacing the printk_get_ts
> with local_clock. IMHO, it will be more clear and safe
> if we handle this in printk_set_timestamp() as suggested above.
> 

FIXED.

> 
>> +		printk_set_timestamp();
>>
>> +
>> +	pr_info("printk: timestamp set to %s\n",
>> +		timestamp_sources_str[printk_time]);
>> +	return 0;
>> +}
>> +
>> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
>> +{
>> +	return scnprintf(buffer, PAGE_SIZE, "%s",
>> +			 timestamp_sources_str[printk_time]);
>> +}
> 
> I know that it would make the code more complicated. But
> I really like the approach used by /sys/power/disk or
> /sys/power/pm_test. They list all possible values
> and put the selected one into [] brackets.
> 

I like the idea too, however, I think that complicates things with userspace
(which as you point out is something that we really need to be concerned
with).  I am using /sys/modules/printk/parameters/time to indicate the
timestamp to userspace.

With my code, userspace would see "realtime" or "disabled".  With your
suggested change they would see "disabled [realtime]".  I think that
file needs to be a simple as possible and be a single entry for userspace
to consume.  IMHO.

> Well, this might be done in a separate patch.
> I am not 100% sure that this actually does not break some
> rules for sysfs.
> 

I don't see anything that says I must list every available option
but I only did a quick overview of the docs.

> 
>> +
>> +static struct kernel_param_ops printk_time_ops = {
>> +	.set = printk_time_set,
>> +	.get = printk_time_get,
> 
> It seems that an often used naming scheme is:
> 
>    .set = param_set_<param_name>
>    .get = param_get_<param_name>
> 
> Please, use it. It think that they make the meaning more obvious.

FIXED.

> 
>> +};
>> +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_DISABLE)
>>  		return 0;
>>  
>>  	rem_nsec = do_div(ts, 1000000000);
>> @@ -1643,7 +1776,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;
>>  	}
>>  
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 98fe715522e8..0262770d6bc5 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"
>> +	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"
>> +	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"
>> +	help
>> +	  Selecting this option causes the time stamps of printk() to be
>> +	  stamped with the adjusted realtime clock.
> 
> It might make sense to point out that this is in UTC. I would mention
> this also in kernel-parameters. The discussion about an older version
> of this patchset suggests that this is not widely known.
> 

FIXED in Kconfig & kernel-parameters.txt.

> 
>> +endchoice
>> +
>> +config PRINTK_TIME_TYPE
>> +	int
>> +	depends on PRINTK
>> +	range 1 5
>> +	default 1 if !PRINTK_TIME
>> +	default 2 if PRINTK_TIME_LOCAL
>> +	default 3 if PRINTK_TIME_BOOT
>> +	default 4 if PRINTK_TIME_MONO
>> +	default 5 if PRINTK_TIME_REAL
> 
> I am surprised that this even force PRINTK_TIME_TYPE to be
> in sync with the above choice. I would expect that "default"
> would still allow to set another value here and make
> it inconsistent. For example I tried to define:
> 

Aside: I have changed to 0-4 range to remove "undefined" from
timestamp_sources_str[], and modified additional code to reflect the change.

> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=4
> 
> But "make" automatically fixed this to
> 
> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=2
> 
> which is great. I hope that we could rely on this.
> 

Yes, I think this among the reasons why peterz & John recommended this method.

> 
> Best Regards,
> Petr
>

> PS: I agree that this functionality would be useful. My main
> concern is how to "always" display the time correctly, especially
> by userpace tools. It does not make sense to solve the other
> rather cosmetic probles until we have a good answer for
> the main one.
> 

[1]:  Mark ... this is an interesting idea we should pursue in the future,
as I think it would nicely solve your request for the timestamp info.

> Note that we could store the information about the time
> type for each line in struct printk_log for each line.
> There are two unused bits in log_flags (one is LOG_NOCONS).
> The question is how to pass it to userspace.
>

P.