Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1732883 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime  timestamps Petr Mladek <pmladek@suse.com> - 2017-09-15 15:30 +0200
    Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime  timestamps Mark Salyzyn <salyzyn@android.com> - 2017-09-15 16:30 +0200
      Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime  timestamps Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-17 13:00 +0200
        Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime  timestamps Prarit Bhargava <prarit@redhat.com> - 2017-09-19 14:00 +0200
    Re: [PATCH 3/3 v11] printk: Add monotonic, boottime, and realtime  timestamps Prarit Bhargava <prarit@redhat.com> - 2017-09-15 16:50 +0200

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

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.

[toc] | [next] | [standalone]

#1732908

On 09/15/2017 06:28 AM, Petr Mladek wrote:
> 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.
My comment below is a rehash/summary:

In the discussion, it appears that DAC protection is enough to prevent 
flippant changes. The use cases I can imagine for runtime alteration 
fall in two groups, late boot changes after all disks are mounted and 
the application layers have started; or as an aid to debugging where the 
deliberate nature can be accounted for. Change it, erase the logs is the 
KISS solution, so the tools do not have to 'sniff' the stream for 
dynamic changes, likely getting the 'leader' wrong, checking 
/sys/module/printk/parameters/time for the current/last timebase.

To mitigate the 'leader' issue, or post-mortem/off-machine 
interpretation, really for the debugging corner case IMHO, I had 
proposed that local, and perhaps monotonic, time print as-is as they are 
almost(?) imperceptibly different, but that realtime add a U suffix (to 
denote time is UTC), and that boottime add a B suffix (well, because) so 
that tools can discern. Monotonic could have a M suffix if it is really 
a stickler. This proposal would require more disruptive tool 
modifications and should be scoped as a separate effort. I do expect a 
debate regarding upper and lower case ...

I have a patch waiting in the wings here where disruptive time changes 
(suspend/resume/hibernate/restore; maybe date(1), ntpd(8) or embedded 
systems LTE hardware time updates) will report dual timestamps so that 
resynchronization and tracking can happen in post-mortem on the stream, 
I expect to use the above proposal for the 'second' occasional timestamp.

-- Mark

[toc] | [prev] | [next] | [standalone]

#1733437

On (09/15/17 07:29), Mark Salyzyn wrote:
> On 09/15/2017 06:28 AM, Petr Mladek wrote:
> > 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.
> My comment below is a rehash/summary:
> 
> In the discussion, it appears that DAC protection is enough to prevent
> flippant changes. The use cases I can imagine for runtime alteration fall in
> two groups, late boot changes after all disks are mounted and the
> application layers have started; or as an aid to debugging where the
> deliberate nature can be accounted for. Change it, erase the logs is the
> KISS solution, so the tools do not have to 'sniff' the stream for dynamic
> changes, likely getting the 'leader' wrong, checking
> /sys/module/printk/parameters/time for the current/last timebase.
> 
> To mitigate the 'leader' issue, or post-mortem/off-machine interpretation,
> really for the debugging corner case IMHO, I had proposed that local, and
> perhaps monotonic, time print as-is as they are almost(?) imperceptibly
> different, but that realtime add a U suffix (to denote time is UTC), and
> that boottime add a B suffix (well, because) so that tools can discern.
> Monotonic could have a M suffix if it is really a stickler. This proposal
> would require more disruptive tool modifications and should be scoped as a
> separate effort. I do expect a debate regarding upper and lower case ...
> 
> I have a patch waiting in the wings here where disruptive time changes
> (suspend/resume/hibernate/restore; maybe date(1), ntpd(8) or embedded
> systems LTE hardware time updates) will report dual timestamps so that
> resynchronization and tracking can happen in post-mortem on the stream, I
> expect to use the above proposal for the 'second' occasional timestamp.

I'm a bit uncomfortable with the "breaks user space" part. since this
is a strictly debugging option, would it be sufficient to store those
extended timestamps as prefixes of every message?
see (sorry for "self-quoting"):
	lkml.kernel.org/r/20170917062608.GA512@tigerII.localdomain

each message, thus, will be in the following format

[current header: loglevel, timestamp, etc] [extended printk data] message text

extended printk data can contain your monotonic/etc timestamps, and
anything else.

and then it's up to you how do you grep the messages and process the
extended data. but the point is - user space tools (journald, dmesg,
etc.) stays intact. which is kinda nice.

so we can avoid that chicken and egg problem: we break user space
by merging the patchset but user space people don't want to talk
about any fixes until we break those tools.

	-ss

[toc] | [prev] | [next] | [standalone]

#1734835

On 09/17/2017 06:46 AM, Sergey Senozhatsky wrote:

> I'm a bit uncomfortable with the "breaks user space" part. since this
> is a strictly debugging option, would it be sufficient to store those
> extended timestamps as prefixes of every message?
> see (sorry for "self-quoting"):
> 	lkml.kernel.org/r/20170917062608.GA512@tigerII.localdomain
>

Sergey, I haven't forgotten about the above.  It's something
I'm going to look at after this initial patchset is done.

P.

> each message, thus, will be in the following format
> 
> [current header: loglevel, timestamp, etc] [extended printk data] message text
> 
> extended printk data can contain your monotonic/etc timestamps, and
> anything else.
> 
> and then it's up to you how do you grep the messages and process the
> extended data. but the point is - user space tools (journald, dmesg,
> etc.) stays intact. which is kinda nice.
> 
> so we can avoid that chicken and egg problem: we break user space
> by merging the patchset but user space people don't want to talk
> about any fixes until we break those tools.
> 
> 	-ss
> 

[toc] | [prev] | [next] | [standalone]

#1732916

On 09/15/2017 09:28 AM, Petr Mladek wrote:
> 
> 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.

In earlier versions I had logic to prevent switching during runtime.  tglx
requested that it be removed and I removed it.  Personally I fall into the "I'm
going to set it once and never change it" however, as Mark will offer there are
cases where it might be advantageous to change the timestamp.  I think he has a
patch that will append a b/r/etc. to the timestamp so that userspace can
interpret the different timestamps.

P.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web