[PATCH] printk, allow different timestamps for printk.time [v2]

[PATCH] printk, allow different timestamps for printk.time [v2]

[Prarit Bhargava]

Over the past years I've seen many reports of bugs that include
time-stamped kernel logs (enabled when CONFIG_PRINTK_TIME=y or
print.time=1 is specified as a kernel parameter) that do not align
with either external time stamped logs or /var/log/messages.  This
also makes determining the time of a failure difficult in cases where
/var/log/messages is unavailable.

For example,

[root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date
Thu Dec 17 13:58:31 EST 2015
Thu Dec 17 13:58:31 EST 2015

which displays

[83973.768912] Hello!

on the serial console.

Running a script to convert this to the stamped time,

[root@intel-wildcatpass-06 ~]# ./human.sh  | tail -1
[Thu Dec 17 13:59:57 2015] Hello!

which is already off by 1 minute and 26 seconds off after ~24 hours of
uptime.

This occurs because the time stamp is obtained from a call to
local_clock() which (on x86) is a direct call to the hardware.  These
hardware clock reads are not modified by the standard ntp or ptp protocol,
while the other timestamps are, and that results in situations external
time sources are further and further offset from the kernel log
timestamps.

This patch introduces printk.time=[0-3] allowing a user to specify an adjusted
clock to use with printk timestamps.  The hardware clock, or the existing
functionality, is preserved by default.

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().

[v2]: use NMI safe timekeeping access functions
[v3]: use tglx's ktime_get_log_ts() suggestion to get monotonic & real clocks
[v4]: Fix kernel parameters

Cc: John Stultz <john.stultz@linaro.org>
Cc: Xunlei Pang <pang.xunlei@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Baolin Wang <baolin.wang@linaro.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Petr Mladek <pmladek@suse.cz>
Cc: Tejun Heo <tj@kernel.org>
Cc: Peter Hurley <peter@hurleysoftware.com>
Cc: Vasily Averin <vvs@virtuozzo.com>
Cc: Joe Perches <joe@perches.com>
Signed-off-by: Prarit Bhargava <prarit@redhat.com>
---
 Documentation/kernel-parameters.txt |    6 ++-
 include/linux/timekeeping.h         |    1 +
 kernel/printk/printk.c              |   79 +++++++++++++++++++++++++++++++++--
 kernel/time/timekeeping.c           |   13 ++++++
 lib/Kconfig.debug                   |    2 +-
 5 files changed, 94 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 87d40a7..32f8dba 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3060,8 +3060,10 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 			default: disabled
 
-	printk.time=	Show timing data prefixed to each printk message line
-			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
+	printk.time=	Show timestamp prefixed to each printk message line
+			Format: <string>
+				(0/N/n = disable, 1/Y/y = local clock,
+				2 = monotonic clock, 3 = real clock)
 
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
index ec89d84..0b99a84 100644
--- a/include/linux/timekeeping.h
+++ b/include/linux/timekeeping.h
@@ -233,6 +233,7 @@ static inline u64 ktime_get_raw_ns(void)
 
 extern u64 ktime_get_mono_fast_ns(void);
 extern u64 ktime_get_raw_fast_ns(void);
+extern u64 ktime_get_log_ts(u64 *offset_real);
 
 /*
  * Timespec interfaces utilizing the ktime based ones
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index c963ba5..19ec0d1 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -420,6 +420,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,
@@ -468,7 +470,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;
 
@@ -1035,8 +1037,77 @@ 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 = IS_ENABLED(CONFIG_PRINTK_TIME);
+
+/*
+ * 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_param_set(const char *val,
+				 const struct kernel_param *kp)
+{
+	char *param = strstrip((char *)val);
+
+	if (strlen(param) != 1)
+		return -EINVAL;
+
+	switch (param[0]) {
+	/* 0/N/n = disabled */
+	case '0':
+	case 'N':
+	case 'n':
+		printk_time = 0;
+		break;
+	/* 1/Y/y = local clock */
+	case '1':
+	case 'Y':
+	case 'y':
+		printk_time = 1;
+		break;
+	/* 2 = monotonic clock */
+	case '2':
+		printk_time = 2;
+		break;
+	/* 3 = real clock */
+	case '3':
+		printk_time = 3;
+		break;
+	default:
+		pr_warn("printk: invalid timestamp value\n");
+		return -EINVAL;
+		break;
+	}
+
+	pr_info("printk: timestamp set to %d.\n", printk_time);
+	return 0;
+}
+
+static struct kernel_param_ops printk_time_param_ops = {
+	.set = printk_time_param_set,
+	.get = param_get_int,
+};
+
+module_param_cb(time, &printk_time_param_ops, &printk_time, S_IRUGO | S_IWUSR);
+
+static u64 printk_get_ts(void)
+{
+	u64 mono, offset_real;
+
+	if (printk_time == 0)
+		return 0;
+
+	if (printk_time == 1)
+		return local_clock();
+
+	mono = ktime_get_log_ts(&offset_real);
+
+	if (printk_time == 2)
+		return mono;
+
+	return mono + offset_real;
+}
 
 static size_t print_time(u64 ts, char *buf)
 {
@@ -1614,7 +1685,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
-		cont.ts_nsec = local_clock();
+		cont.ts_nsec = printk_get_ts();
 		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 34b4ced..698e1a2 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -43,6 +43,7 @@ static struct {
 
 static DEFINE_RAW_SPINLOCK(timekeeper_lock);
 static struct timekeeper shadow_timekeeper;
+static int timekeeping_active;
 
 /**
  * struct tk_fast - NMI safe timekeeper
@@ -401,6 +402,16 @@ u64 ktime_get_raw_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_raw_fast_ns);
 
+u64 ktime_get_log_ts(u64 *offset_real)
+{
+	*offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
+
+	if (timekeeping_active)
+		return ktime_get_mono_fast_ns();
+	else
+		return local_clock();
+}
+
 /* Suspend-time cycles value for halted fast timekeeper. */
 static cycle_t cycles_at_suspend;
 
@@ -1267,6 +1278,8 @@ void __init timekeeping_init(void)
 
 	write_seqcount_end(&tk_core.seq);
 	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
+
+	timekeeping_active = 1;
 }
 
 /* time in seconds when suspend began for persistent clock */
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index ecb9e75..6d0ddb0 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -13,7 +13,7 @@ config PRINTK_TIME
 	  be included, not that the timestamp is recorded.
 
 	  The behavior is also controlled by the kernel command line
-	  parameter printk.time=1. See Documentation/kernel-parameters.txt
+	  parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt
 
 config MESSAGE_LOGLEVEL_DEFAULT
 	int "Default message log level (1-7)"
-- 
1.7.9.3

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Vasily Averin]

Dear Prarit,

I have no objections about your patch,
bit in fact I doubt we really need to convert each timestamp in kernel logs.
How do you think is it probably better to convert only one timestamp per screen ?
I.e. convert it in each 25th string only?
Or just do it once per N seconds?
And do not replace original timestamp but add converted one?

Thank you,
	Vasily Averin

On 28.01.2016 15:43, Prarit Bhargava wrote:
> Over the past years I've seen many reports of bugs that include
> time-stamped kernel logs (enabled when CONFIG_PRINTK_TIME=y or
> print.time=1 is specified as a kernel parameter) that do not align
> with either external time stamped logs or /var/log/messages.  This
> also makes determining the time of a failure difficult in cases where
> /var/log/messages is unavailable.
> 
> For example,
> 
> [root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date
> Thu Dec 17 13:58:31 EST 2015
> Thu Dec 17 13:58:31 EST 2015
> 
> which displays
> 
> [83973.768912] Hello!
> 
> on the serial console.
> 
> Running a script to convert this to the stamped time,
> 
> [root@intel-wildcatpass-06 ~]# ./human.sh  | tail -1
> [Thu Dec 17 13:59:57 2015] Hello!
> 
> which is already off by 1 minute and 26 seconds off after ~24 hours of
> uptime.
> 
> This occurs because the time stamp is obtained from a call to
> local_clock() which (on x86) is a direct call to the hardware.  These
> hardware clock reads are not modified by the standard ntp or ptp protocol,
> while the other timestamps are, and that results in situations external
> time sources are further and further offset from the kernel log
> timestamps.
> 
> This patch introduces printk.time=[0-3] allowing a user to specify an adjusted
> clock to use with printk timestamps.  The hardware clock, or the existing
> functionality, is preserved by default.
> 
> 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().
> 
> [v2]: use NMI safe timekeeping access functions
> [v3]: use tglx's ktime_get_log_ts() suggestion to get monotonic & real clocks
> [v4]: Fix kernel parameters
> 
> Cc: John Stultz <john.stultz@linaro.org>
> Cc: Xunlei Pang <pang.xunlei@linaro.org>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Baolin Wang <baolin.wang@linaro.org>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> Cc: Petr Mladek <pmladek@suse.cz>
> Cc: Tejun Heo <tj@kernel.org>
> Cc: Peter Hurley <peter@hurleysoftware.com>
> Cc: Vasily Averin <vvs@virtuozzo.com>
> Cc: Joe Perches <joe@perches.com>
> Signed-off-by: Prarit Bhargava <prarit@redhat.com>
> ---
>  Documentation/kernel-parameters.txt |    6 ++-
>  include/linux/timekeeping.h         |    1 +
>  kernel/printk/printk.c              |   79 +++++++++++++++++++++++++++++++++--
>  kernel/time/timekeeping.c           |   13 ++++++
>  lib/Kconfig.debug                   |    2 +-
>  5 files changed, 94 insertions(+), 7 deletions(-)
> 
> diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
> index 87d40a7..32f8dba 100644
> --- a/Documentation/kernel-parameters.txt
> +++ b/Documentation/kernel-parameters.txt
> @@ -3060,8 +3060,10 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
>  			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
>  			default: disabled
>  
> -	printk.time=	Show timing data prefixed to each printk message line
> -			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
> +	printk.time=	Show timestamp prefixed to each printk message line
> +			Format: <string>
> +				(0/N/n = disable, 1/Y/y = local clock,
> +				2 = monotonic clock, 3 = real clock)
>  
>  	processor.max_cstate=	[HW,ACPI]
>  			Limit processor to maximum C-state
> diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
> index ec89d84..0b99a84 100644
> --- a/include/linux/timekeeping.h
> +++ b/include/linux/timekeeping.h
> @@ -233,6 +233,7 @@ static inline u64 ktime_get_raw_ns(void)
>  
>  extern u64 ktime_get_mono_fast_ns(void);
>  extern u64 ktime_get_raw_fast_ns(void);
> +extern u64 ktime_get_log_ts(u64 *offset_real);
>  
>  /*
>   * Timespec interfaces utilizing the ktime based ones
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index c963ba5..19ec0d1 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -420,6 +420,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,
> @@ -468,7 +470,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;
>  
> @@ -1035,8 +1037,77 @@ 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 = IS_ENABLED(CONFIG_PRINTK_TIME);
> +
> +/*
> + * 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_param_set(const char *val,
> +				 const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +
> +	if (strlen(param) != 1)
> +		return -EINVAL;
> +
> +	switch (param[0]) {
> +	/* 0/N/n = disabled */
> +	case '0':
> +	case 'N':
> +	case 'n':
> +		printk_time = 0;
> +		break;
> +	/* 1/Y/y = local clock */
> +	case '1':
> +	case 'Y':
> +	case 'y':
> +		printk_time = 1;
> +		break;
> +	/* 2 = monotonic clock */
> +	case '2':
> +		printk_time = 2;
> +		break;
> +	/* 3 = real clock */
> +	case '3':
> +		printk_time = 3;
> +		break;
> +	default:
> +		pr_warn("printk: invalid timestamp value\n");
> +		return -EINVAL;
> +		break;
> +	}
> +
> +	pr_info("printk: timestamp set to %d.\n", printk_time);
> +	return 0;
> +}
> +
> +static struct kernel_param_ops printk_time_param_ops = {
> +	.set = printk_time_param_set,
> +	.get = param_get_int,
> +};
> +
> +module_param_cb(time, &printk_time_param_ops, &printk_time, S_IRUGO | S_IWUSR);
> +
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time == 0)
> +		return 0;
> +
> +	if (printk_time == 1)
> +		return local_clock();
> +
> +	mono = ktime_get_log_ts(&offset_real);
> +
> +	if (printk_time == 2)
> +		return mono;
> +
> +	return mono + offset_real;
> +}
>  
>  static size_t print_time(u64 ts, char *buf)
>  {
> @@ -1614,7 +1685,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
>  		cont.facility = facility;
>  		cont.level = level;
>  		cont.owner = current;
> -		cont.ts_nsec = local_clock();
> +		cont.ts_nsec = printk_get_ts();
>  		cont.flags = 0;
>  		cont.cons = 0;
>  		cont.flushed = false;
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> index 34b4ced..698e1a2 100644
> --- a/kernel/time/timekeeping.c
> +++ b/kernel/time/timekeeping.c
> @@ -43,6 +43,7 @@ static struct {
>  
>  static DEFINE_RAW_SPINLOCK(timekeeper_lock);
>  static struct timekeeper shadow_timekeeper;
> +static int timekeeping_active;
>  
>  /**
>   * struct tk_fast - NMI safe timekeeper
> @@ -401,6 +402,16 @@ u64 ktime_get_raw_fast_ns(void)
>  }
>  EXPORT_SYMBOL_GPL(ktime_get_raw_fast_ns);
>  
> +u64 ktime_get_log_ts(u64 *offset_real)
> +{
> +	*offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
> +
> +	if (timekeeping_active)
> +		return ktime_get_mono_fast_ns();
> +	else
> +		return local_clock();
> +}
> +
>  /* Suspend-time cycles value for halted fast timekeeper. */
>  static cycle_t cycles_at_suspend;
>  
> @@ -1267,6 +1278,8 @@ void __init timekeeping_init(void)
>  
>  	write_seqcount_end(&tk_core.seq);
>  	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
> +
> +	timekeeping_active = 1;
>  }
>  
>  /* time in seconds when suspend began for persistent clock */
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index ecb9e75..6d0ddb0 100644
> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -13,7 +13,7 @@ config PRINTK_TIME
>  	  be included, not that the timestamp is recorded.
>  
>  	  The behavior is also controlled by the kernel command line
> -	  parameter printk.time=1. See Documentation/kernel-parameters.txt
> +	  parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt
>  
>  config MESSAGE_LOGLEVEL_DEFAULT
>  	int "Default message log level (1-7)"
> 

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Prarit Bhargava]

On 01/28/2016 07:52 AM, Vasily Averin wrote:
> Dear Prarit,
> 

Hi Vasily,  Thanks for your suggestions.

> I have no objections about your patch,
> bit in fact I doubt we really need to convert each timestamp in kernel logs.
> How do you think is it probably better to convert only one timestamp per screen ?

How do you measure a screen? :)

> I.e. convert it in each 25th string only?

While your suggestion does work for a flood of messages this will miss
situations where an event occurred hours/minutes/seconds earlier leading to a
panic.

> Or just do it once per N seconds?

I've tried several other versions of the patch and other userspace options (such
as "date +%N > /tmp/kmsg" every second, setting up a timer to dump the real
time,  etc.).  Assuming that the disks didn't die (which was also part of the
problem I have seen) the printk buffer is finite in size and it is easy to fill
the buffer if you're not careful.

> And do not replace original timestamp but add converted one?

I'm not sure I see the benefit of having two timestamps but if someone really
wanted that I could add an additional patch to do it.

At the end of the day I need to be able to determine in real time what happened
on a system and to make that as easy as possible for a human to read.

P.

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Vasily Averin]

On 28.01.2016 16:17, Prarit Bhargava wrote:
> On 01/28/2016 07:52 AM, Vasily Averin wrote:
>> Dear Prarit,
>>
> 
> Hi Vasily,  Thanks for your suggestions.
> 
>> I have no objections about your patch,
>> bit in fact I doubt we really need to convert each timestamp in kernel logs.
>> How do you think is it probably better to convert only one timestamp per screen ?
> 
> How do you measure a screen? :)

I mean 80x25, but you're right, it makes sense to do it configurable.

>> I.e. convert it in each 25th string only?
> 
> While your suggestion does work for a flood of messages this will miss
> situations where an event occurred hours/minutes/seconds earlier leading to a
> panic.
> 
>> Or just do it once per N seconds?
> 
> I've tried several other versions of the patch and other userspace options (such
> as "date +%N > /tmp/kmsg" every second, setting up a timer to dump the real
> time,  etc.).  Assuming that the disks didn't die (which was also part of the
> problem I have seen) the printk buffer is finite in size and it is easy to fill
> the buffer if you're not careful.
> 
>> And do not replace original timestamp but add converted one?
> 
> I'm not sure I see the benefit of having two timestamps but if someone really
> wanted that I could add an additional patch to do it.

I investigate periodically various "node hangs" issues,
without saved vmcore, /var/log/messages, net or serial console.
All what I have is screenshot on local console, in worst case 80x25.

I'm ready to lose ~10 characters on each string for short timesetamp,
and of course I would be happy to know real date of these messages.
But for me it's enough to see full date once per screen, 
and have short relative timestamp on other strings.

> At the end of the day I need to be able to determine in real time what happened
> on a system and to make that as easy as possible for a human to read.
> 
> P.
> 

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Petr Mladek]

On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote:
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time == 0)
> +		return 0;
> +
> +	if (printk_time == 1)
> +		return local_clock();
> +
> +	mono = ktime_get_log_ts(&offset_real);
> +
> +	if (printk_time == 2)
> +		return mono;
> +
> +	return mono + offset_real;

At least dmesg is not capable to read the absolute size of the
real time. It expects offset against the start of the timekeeping
stuff or so. I get this:

$> dmesg | tail -n 5
[    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    0.000000] printk: timestamp set to 0.
[  179.983704] printk: timestamp set to 1.
[  181.895655] printk: timestamp set to 2.
[1454602412.026424] printk: timestamp set to 3.

$dmesg -T -S | tail -n 5
[Thu Feb  4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[Thu Feb  4 17:10:27 2016] printk: timestamp set to 0.
[Thu Feb  4 17:13:26 2016] printk: timestamp set to 1.
[Thu Feb  4 17:13:28 2016] printk: timestamp set to 2.
[Fri Mar 10 09:23:59 2062] printk: timestamp set to 3.

Please, note that the last entry points to the year 2062.


> --- a/lib/Kconfig.debug
> +++ b/lib/Kconfig.debug
> @@ -13,7 +13,7 @@ config PRINTK_TIME
>  	  be included, not that the timestamp is recorded.
>  
>  	  The behavior is also controlled by the kernel command line
> -	  parameter printk.time=1. See Documentation/kernel-parameters.txt
> +	  parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt

Please, mention there the mention of the numbers. The cross reference
is annoying if you look at the help when configuring kernel build.

Also there is a mismatch between the values and the type of
CONFIG_PRINTK_TIME. You should change it to

	int "Show timing information on printks"
	range 0 3

Then you need to update the default value for all
architectures in all arch/*/configs/*_defconfig

It seems that it is enabled in most architectures. I would suggest
to define

      default "1"

in lib/Kconfig.debug. Then you could remove the definition from
most defconfigs. The advantage is that even "make oldconfig"
will propose reasonable default.

Best Regards,
Petr

PS: Please, put version number to the subject, e.g. [PATCH v4].
It makes it slightly easier to orientate in the variants ;-)

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Prarit Bhargava]

On 02/04/2016 11:48 AM, Petr Mladek wrote:
> On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote:
>> +static u64 printk_get_ts(void)
>> +{
>> +	u64 mono, offset_real;
>> +
>> +	if (printk_time == 0)
>> +		return 0;
>> +
>> +	if (printk_time == 1)
>> +		return local_clock();
>> +
>> +	mono = ktime_get_log_ts(&offset_real);
>> +
>> +	if (printk_time == 2)
>> +		return mono;
>> +
>> +	return mono + offset_real;
> 
> At least dmesg is not capable to read the absolute size of the
> real time. It expects offset against the start of the timekeeping
> stuff or so. I get this:
> 
> $> dmesg | tail -n 5
> [    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [    0.000000] printk: timestamp set to 0.

^^^ Hmm ... I'll have to think about that.

> [  179.983704] printk: timestamp set to 1.
> [  181.895655] printk: timestamp set to 2.
> [1454602412.026424] printk: timestamp set to 3.
> 
> $dmesg -T -S | tail -n 5
> [Thu Feb  4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [Thu Feb  4 17:10:27 2016] printk: timestamp set to 0.
> [Thu Feb  4 17:13:26 2016] printk: timestamp set to 1.
> [Thu Feb  4 17:13:28 2016] printk: timestamp set to 2.
> [Fri Mar 10 09:23:59 2062] printk: timestamp set to 3.

Yes, this is a known issue that someone else previously brought to my attention
on LKML.  I will have to modify dmesg once this code is stabilized.

> 
> Please, note that the last entry points to the year 2062.
> 
> 
>> --- a/lib/Kconfig.debug
>> +++ b/lib/Kconfig.debug
>> @@ -13,7 +13,7 @@ config PRINTK_TIME
>>  	  be included, not that the timestamp is recorded.
>>  
>>  	  The behavior is also controlled by the kernel command line
>> -	  parameter printk.time=1. See Documentation/kernel-parameters.txt
>> +	  parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt
> 
> Please, mention there the mention of the numbers. The cross reference
> is annoying if you look at the help when configuring kernel build.

I can certainly make that change and provide better documentation.

> 
> Also there is a mismatch between the values and the type of
> CONFIG_PRINTK_TIME. You should change it to
> 
> 	int "Show timing information on printks"
> 	range 0 3

I don't think that's what CONFIG_PRINTK_TIME does.  All CONFIG_PRINTK_TIME does
is turn the timestamping on or off.

IOW,

CONFIG_PRINTK_TIME=n results in

IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

and CONFIG_PRINTK_TIME=y results in

[    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready

I explicitly did NOT want to change the behavior of CONFIG_PRINTK_TIME.

P.

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Thomas Gleixner]

On Thu, 4 Feb 2016, Petr Mladek wrote:
> On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote:
> > +static u64 printk_get_ts(void)
> > +{
> > +	u64 mono, offset_real;
> > +
> > +	if (printk_time == 0)
> > +		return 0;
> > +
> > +	if (printk_time == 1)
> > +		return local_clock();
> > +
> > +	mono = ktime_get_log_ts(&offset_real);
> > +
> > +	if (printk_time == 2)
> > +		return mono;
> > +
> > +	return mono + offset_real;
> 
> At least dmesg is not capable to read the absolute size of the
> real time. It expects offset against the start of the timekeeping
> stuff or so. I get this:
> 
> $> dmesg | tail -n 5
> [    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [    0.000000] printk: timestamp set to 0.
> [  179.983704] printk: timestamp set to 1.
> [  181.895655] printk: timestamp set to 2.
> [1454602412.026424] printk: timestamp set to 3.
> 
> $dmesg -T -S | tail -n 5
> [Thu Feb  4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [Thu Feb  4 17:10:27 2016] printk: timestamp set to 0.
> [Thu Feb  4 17:13:26 2016] printk: timestamp set to 1.
> [Thu Feb  4 17:13:28 2016] printk: timestamp set to 2.
> [Fri Mar 10 09:23:59 2062] printk: timestamp set to 3.
> 
> Please, note that the last entry points to the year 2062.

That's a problem of dmesg -T -S. It doesn't know that the timestamp (3) is
actually CLOCKTIME_REAL already:

-> 1454602412 / (3600 * 24 * 365)
 = 46.1251
-> 1970 + 46
 = 2016
 
Thanks,

	tglx

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Petr Mladek]

On Thu 2016-02-04 12:03:27, Prarit Bhargava wrote:
> 
> 
> On 02/04/2016 11:48 AM, Petr Mladek wrote:
> > On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote:
> >> +static u64 printk_get_ts(void)
> >> +{
> >> +	u64 mono, offset_real;
> >> +
> >> +	if (printk_time == 0)
> >> +		return 0;
> >> +
> >> +	if (printk_time == 1)
> >> +		return local_clock();
> >> +
> >> +	mono = ktime_get_log_ts(&offset_real);
> >> +
> >> +	if (printk_time == 2)
> >> +		return mono;
> >> +
> >> +	return mono + offset_real;
> > 
> > At least dmesg is not capable to read the absolute size of the
> > real time. It expects offset against the start of the timekeeping
> > stuff or so. I get this:
> > 
> > $> dmesg | tail -n 5
> > [    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> > [    0.000000] printk: timestamp set to 0.
> 
> ^^^ Hmm ... I'll have to think about that.
> 
> > [  179.983704] printk: timestamp set to 1.
> > [  181.895655] printk: timestamp set to 2.
> > [1454602412.026424] printk: timestamp set to 3.
> > 
> > $dmesg -T -S | tail -n 5
> > [Thu Feb  4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> > [Thu Feb  4 17:10:27 2016] printk: timestamp set to 0.
> > [Thu Feb  4 17:13:26 2016] printk: timestamp set to 1.
> > [Thu Feb  4 17:13:28 2016] printk: timestamp set to 2.
> > [Fri Mar 10 09:23:59 2062] printk: timestamp set to 3.
> 
> Yes, this is a known issue that someone else previously brought to my attention
> on LKML.

It was me ;-)

> I will have to modify dmesg once this code is stabilized.

But how will dmesg detect when the time is a real time or an offset?
There is still a bit available in struct printk_log in the flags
variable but...

Also note that there are more tools that might need to get updated.
For example, "crash" and maybe "gdb" are able to print the messages
from the crashdump.

I still think that it might be easier to convert the real time to
the offset before storing it.


> > Please, note that the last entry points to the year 2062.
> > 
> > 
> >> --- a/lib/Kconfig.debug
> >> +++ b/lib/Kconfig.debug
> >> @@ -13,7 +13,7 @@ config PRINTK_TIME
> >>  	  be included, not that the timestamp is recorded.
> >>  
> >>  	  The behavior is also controlled by the kernel command line
> >> -	  parameter printk.time=1. See Documentation/kernel-parameters.txt
> >> +	  parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt
> > 
> > Please, mention there the mention of the numbers. The cross reference
> > is annoying if you look at the help when configuring kernel build.
> 
> I can certainly make that change and provide better documentation.
> 
> > 
> > Also there is a mismatch between the values and the type of
> > CONFIG_PRINTK_TIME. You should change it to
> > 
> > 	int "Show timing information on printks"
> > 	range 0 3
> 
> I don't think that's what CONFIG_PRINTK_TIME does.  All CONFIG_PRINTK_TIME does
> is turn the timestamping on or off.
> 
> IOW,
> 
> CONFIG_PRINTK_TIME=n results in
> 
> IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> 
> and CONFIG_PRINTK_TIME=y results in
> 
> [    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> 
> I explicitly did NOT want to change the behavior of CONFIG_PRINTK_TIME.

But why? IMHO, it would be much more practical and clear
if both CONFIG_PRINTK_TIME and the command line parameter
printk.time have exactly the same meaning.

I am not aware of any other couple where the corresponding
config and commandline options have different meaning.

Best Regards,
Petr

Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Prarit Bhargava]

On 02/08/2016 10:51 AM, Petr Mladek wrote:
> On Thu 2016-02-04 12:03:27, Prarit Bhargava wrote:
>>
>>
>> On 02/04/2016 11:48 AM, Petr Mladek wrote:
>>> On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote:
>>>> +static u64 printk_get_ts(void)
>>>> +{
>>>> +	u64 mono, offset_real;
>>>> +
>>>> +	if (printk_time == 0)
>>>> +		return 0;
>>>> +
>>>> +	if (printk_time == 1)
>>>> +		return local_clock();
>>>> +
>>>> +	mono = ktime_get_log_ts(&offset_real);
>>>> +
>>>> +	if (printk_time == 2)
>>>> +		return mono;
>>>> +
>>>> +	return mono + offset_real;
>>>
>>> At least dmesg is not capable to read the absolute size of the
>>> real time. It expects offset against the start of the timekeeping
>>> stuff or so. I get this:
>>>
>>> $> dmesg | tail -n 5
>>> [    7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
>>> [    0.000000] printk: timestamp set to 0.
>>
>> ^^^ Hmm ... I'll have to think about that.
>>
>>> [  179.983704] printk: timestamp set to 1.
>>> [  181.895655] printk: timestamp set to 2.
>>> [1454602412.026424] printk: timestamp set to 3.
>>>
>>> $dmesg -T -S | tail -n 5
>>> [Thu Feb  4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
>>> [Thu Feb  4 17:10:27 2016] printk: timestamp set to 0.
>>> [Thu Feb  4 17:13:26 2016] printk: timestamp set to 1.
>>> [Thu Feb  4 17:13:28 2016] printk: timestamp set to 2.
>>> [Fri Mar 10 09:23:59 2062] printk: timestamp set to 3.
>>
>> Yes, this is a known issue that someone else previously brought to my attention
>> on LKML.
> 
> It was me ;-)
> 
>> I will have to modify dmesg once this code is stabilized.
> 
> But how will dmesg detect when the time is a real time or an offset?
> There is still a bit available in struct printk_log in the flags
> variable but...
> 
> Also note that there are more tools that might need to get updated.
> For example, "crash" and maybe "gdb" are able to print the messages
> from the crashdump.
> 
> I still think that it might be easier to convert the real time to
> the offset before storing it.

Hmm ... good point.  I guess I was still thinking about my original patch that
had introduced /sys/modules/printk/parameters/clock which userspace could read.

tglx, any objection to the suggested changes here?  I would have to modify all
the configs, etc. so that CONFIG_PRINTK_TIME was an int instead of a bool.

P.