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

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

[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-2] allowing a user to specify an adjusted
clock to use with printk timestamps.  The hardware clock, or the existing
functionality, is preserved by default.

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

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 |    5 +++--
 include/linux/timekeeping.h         |    1 +
 kernel/printk/printk.c              |   26 ++++++++++++++++++++++----
 kernel/time/timekeeping.c           |   13 +++++++++++++
 lib/Kconfig.debug                   |    2 +-
 5 files changed, 40 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 87d40a7..2cf6692 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3060,8 +3060,9 @@ 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: [0-2]  (0 = disable,
+					1 = monotonic clock, 2 = 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..ea786a7 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,24 @@ 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);
+/* 0 = disabled, 1 = monotonic, 2 = real clock */
+module_param_named(time, printk_time, int, S_IRUGO | S_IWUSR);
+
+static u64 printk_get_ts(void)
+{
+	u64 mono, offset_real;
+
+	if (!printk_time)
+		return 0;
+
+	mono = ktime_get_log_ts(&offset_real);
+
+	if (printk_time == 1)
+		return mono;
+
+	return mono + offset_real;
+}
 
 static size_t print_time(u64 ts, char *buf)
 {
@@ -1614,7 +1632,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..3c3751d 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-2]. 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

[Thomas Gleixner]

Prarit,

On Mon, 25 Jan 2016, Prarit Bhargava wrote:
> diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
> index 87d40a7..2cf6692 100644
> --- a/Documentation/kernel-parameters.txt
> +++ b/Documentation/kernel-parameters.txt
> @@ -3060,8 +3060,9 @@ 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: [0-2]  (0 = disable,
> +					1 = monotonic clock, 2 = real clock)

Doesn't this break systems, which have 'Y/y' on the command line?

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

Just for the record: The fast timekeeper stops across the inner workings of
suspend/resume. But I think that doesn't matter much.

Otherwise, this looks good now.

Thanks,

	tglx

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

[Prarit Bhargava]

On 01/26/2016 03:34 PM, Thomas Gleixner wrote:
> Prarit,
> 
> On Mon, 25 Jan 2016, Prarit Bhargava wrote:
>> diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
>> index 87d40a7..2cf6692 100644
>> --- a/Documentation/kernel-parameters.txt
>> +++ b/Documentation/kernel-parameters.txt
>> @@ -3060,8 +3060,9 @@ 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: [0-2]  (0 = disable,
>> +					1 = monotonic clock, 2 = real clock)
> 
> Doesn't this break systems, which have 'Y/y' on the command line?

I'll fix this by converting to using module_param_cb() and comparing input
strings instead.

Aside: One thing I would also like to add is the ability to also do
printk.time=[real] for real timestamping.  I think that's easier to parse for
end users.

> 
>>  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();
> 
> Just for the record: The fast timekeeper stops across the inner workings of
> suspend/resume. But I think that doesn't matter much.

I've had to debug s/r before using the sysfs interface.  It is nice to have that
with a proper timestamp because a lot of the failures are in the driver suspend
and resume paths.  I could easily change the options to:

0 = disable
1 = local clock (which along with 0 would maintain the current state of things)
2 = monotonic
3 = real

P.

> 
> Otherwise, this looks good now.
> 
> Thanks,
> 
> 	tglx
> 
> 
> 
> 

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

[Thomas Gleixner]

On Tue, 26 Jan 2016, Prarit Bhargava wrote:
> On 01/26/2016 03:34 PM, Thomas Gleixner wrote:
> > Just for the record: The fast timekeeper stops across the inner workings of
> > suspend/resume. But I think that doesn't matter much.
> 
> I've had to debug s/r before using the sysfs interface.  It is nice to have that
> with a proper timestamp because a lot of the failures are in the driver suspend
> and resume paths.  I could easily change the options to:

The timekeeper suspends/resumes in the syscore section, so the driver part is
not affected.
 
> 0 = disable
> 1 = local clock (which along with 0 would maintain the current state of things)
> 2 = monotonic
> 3 = real

Yes, that works.

Btw, you need to document, that REAL can occasionally provide a wrong value on
32bit machines in case that a concurrent update of the realtime offset happens
(settimeofday, leap seconds ...). That's because we access real_offset w/o the
seqcount protection. It's probably hard to achieve, but it might happen.

Thanks,

	tglx