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

2016-04-22 Thread Andrew Morton 
On Fri, 22 Apr 2016 08:03:09 -0400 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().

Looks OK to me.  Timekeeping stuff makes my head spin nowadays but I
trust you've sorted out the obvious deadlock/reentrancy/etc issues. 
I'll toss it in for some testing.

> @@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level)
>  
>  static int printk_time = 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)
>  {
> @@ -1063,6 +1071,14 @@ static int printk_time_param_set(const char *val,
>   case 'y':
>   printk_time = 1;
>   break;
> + /* 2 = monotonic clock */
> + case '2':
> + printk_time = 2;
> + break;
> + /* 3 = real clock */
> + case '3':
> + printk_time = 3;
> + break;

Maybe it's time to enumerate these values.

>   default:
>   pr_warn("printk: invalid timestamp value\n");
>   return -EINVAL;
> @@ -1080,6 +1096,21 @@ static struct kernel_param_ops printk_time_param_ops = 
> {
>  
>  module_param_cb(time, _time_param_ops, _time, S_IRUGO);
>  
> +static u64 printk_get_ts(void)
> +{
> + u64 mono, offset_real;
> +
> + if (printk_time <= 1)
> + return local_clock();
> +
> + mono = ktime_get_log_ts(_real);
> +
> + if (printk_time == 2)
> + return mono;
> +
> + return mono + offset_real;
> +}

Because the magic constants set a bad example for any children in the
audience.

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

2016-04-22 Thread Andrew Morton 
On Fri, 22 Apr 2016 08:03:09 -0400 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().

Looks OK to me.  Timekeeping stuff makes my head spin nowadays but I
trust you've sorted out the obvious deadlock/reentrancy/etc issues. 
I'll toss it in for some testing.

> @@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level)
>  
>  static int printk_time = 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)
>  {
> @@ -1063,6 +1071,14 @@ static int printk_time_param_set(const char *val,
>   case 'y':
>   printk_time = 1;
>   break;
> + /* 2 = monotonic clock */
> + case '2':
> + printk_time = 2;
> + break;
> + /* 3 = real clock */
> + case '3':
> + printk_time = 3;
> + break;

Maybe it's time to enumerate these values.

>   default:
>   pr_warn("printk: invalid timestamp value\n");
>   return -EINVAL;
> @@ -1080,6 +1096,21 @@ static struct kernel_param_ops printk_time_param_ops = 
> {
>  
>  module_param_cb(time, _time_param_ops, _time, S_IRUGO);
>  
> +static u64 printk_get_ts(void)
> +{
> + u64 mono, offset_real;
> +
> + if (printk_time <= 1)
> + return local_clock();
> +
> + mono = ktime_get_log_ts(_real);
> +
> + if (printk_time == 2)
> + return mono;
> +
> + return mono + offset_real;
> +}

Because the magic constants set a bad example for any children in the
audience.

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

2016-04-22 Thread 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
[v5]: Modify configs to accept [0-3]
[v6]: Implement Kconfig changes from Petr Mladek, fix CONFIG_PRINTK_TIME=0
and dmesg bug

Cc: Cc: Petr Mladek 
Cc: John Stultz 
Cc: Xunlei Pang 
Cc: Thomas Gleixner 
Cc: Baolin Wang 
Cc: Andrew Morton 
Cc: Greg Kroah-Hartman 
Cc: Petr Mladek 
Cc: Tejun Heo 
Cc: Peter Hurley 
Cc: Vasily Averin 
Cc: Joe Perches 
Signed-off-by: Prarit Bhargava 
---
 Documentation/kernel-parameters.txt |6 --
 include/linux/timekeeping.h |1 +
 kernel/printk/printk.c  |   35 +--
 kernel/time/timekeeping.c   |   13 +
 lib/Kconfig.debug   |7 ---
 5 files changed, 55 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt 
b/Documentation/kernel-parameters.txt
index 79c3e28..95cd7fe 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3111,8 +3111,10 @@ bytes respectively. Such letter suffixes can also be 
entirely omitted.
Format:   (1/Y/y=enable, 0/N/n=disable)
default: disabled
 
-   printk.time=Show timing data prefixed to each printk message line
-   Format:   (1/Y/y=enable, 0/N/n=disable)
+   printk.time=Show timestamp prefixed to each printk message line
+   Format: 
+   (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 96f37be..9b57867 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 18dee96..48a8214 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -424,6 +424,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,
@@ -472,7 +474,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;
 
@@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level)

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

2016-04-22 Thread 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
[v5]: Modify configs to accept [0-3]
[v6]: Implement Kconfig changes from Petr Mladek, fix CONFIG_PRINTK_TIME=0
and dmesg bug

Cc: Cc: Petr Mladek 
Cc: John Stultz 
Cc: Xunlei Pang 
Cc: Thomas Gleixner 
Cc: Baolin Wang 
Cc: Andrew Morton 
Cc: Greg Kroah-Hartman 
Cc: Petr Mladek 
Cc: Tejun Heo 
Cc: Peter Hurley 
Cc: Vasily Averin 
Cc: Joe Perches 
Signed-off-by: Prarit Bhargava 
---
 Documentation/kernel-parameters.txt |6 --
 include/linux/timekeeping.h |1 +
 kernel/printk/printk.c  |   35 +--
 kernel/time/timekeeping.c   |   13 +
 lib/Kconfig.debug   |7 ---
 5 files changed, 55 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt 
b/Documentation/kernel-parameters.txt
index 79c3e28..95cd7fe 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3111,8 +3111,10 @@ bytes respectively. Such letter suffixes can also be 
entirely omitted.
Format:   (1/Y/y=enable, 0/N/n=disable)
default: disabled
 
-   printk.time=Show timing data prefixed to each printk message line
-   Format:   (1/Y/y=enable, 0/N/n=disable)
+   printk.time=Show timestamp prefixed to each printk message line
+   Format: 
+   (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 96f37be..9b57867 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 18dee96..48a8214 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -424,6 +424,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,
@@ -472,7 +474,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;
 
@@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level)
 
 static int printk_time = 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