[PATCH 2/2] printk: Add boottime and real timestamps

[Prarit Bhargava]

printk.time=1/CONFIG_PRINTK_TIME=Y timestamps printks with an unmodified
hardware clock timestamp.  This clock loses time each day making it
difficult to determine when an issue has occurred in the kernel log.

Modify printk.time to output local, monotonic, or a real timestamp.
Modify the output of /sys/module/printk/parameters/time to output the type
of clock so userspace programs can interpret the timestamp.

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

Signed-off-by: Prarit Bhargava <prarit@xxxxxxxxxx>
Cc: Mark Salyzyn <salyzyn@xxxxxxxxxxx>
Cc: Jonathan Corbet <corbet@xxxxxxx>
Cc: Petr Mladek <pmladek@xxxxxxxx>
Cc: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
Cc: Steven Rostedt <rostedt@xxxxxxxxxxx>
Cc: John Stultz <john.stultz@xxxxxxxxxx>
Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: Stephen Boyd <sboyd@xxxxxxxxxxxxxx>
Cc: Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx>
Cc: Greg Kroah-Hartman <gregkh@xxxxxxxxxxxxxxxxxxx>
Cc: "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx>
Cc: Christoffer Dall <cdall@xxxxxxxxxx>
Cc: Deepa Dinamani <deepa.kernel@xxxxxxxxx>
Cc: Ingo Molnar <mingo@xxxxxxxxxx>
Cc: Joel Fernandes <joelaf@xxxxxxxxxx>
Cc: Kees Cook <keescook@xxxxxxxxxxxx>
Cc: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
Cc: Geert Uytterhoeven <geert+renesas@xxxxxxxxx>
Cc: "Luis R. Rodriguez" <mcgrof@xxxxxxxxxx>
Cc: Nicholas Piggin <npiggin@xxxxxxxxx>
Cc: "Jason A. Donenfeld" <Jason@xxxxxxxxx>
Cc: Olof Johansson <olof@xxxxxxxxx>
Cc: "Theodore Ts'o" <tytso@xxxxxxx>
Cc: Josh Poimboeuf <jpoimboe@xxxxxxxxxx>
Cc: linux-doc@xxxxxxxxxxxxxxx


---
 Documentation/admin-guide/kernel-parameters.txt |  6 +-
 include/linux/timekeeping.h                     |  1 +
 kernel/printk/printk.c                          | 77 +++++++++++++++++++++----
 kernel/time/timekeeping.c                       | 14 +++++
 lib/Kconfig.debug                               |  7 ++-
 5 files changed, 89 insertions(+), 16 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index c3b14abf9da4..c03240d057b1 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -3188,8 +3188,10 @@
 			ratelimit - ratelimit the logging
 			Default: ratelimit
 
-	printk.time=	Show timing data prefixed to each printk message line
-			Format: <string>  (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/unadjusted HW,
+				 2 = monotonic, 3 = real)
 
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h
index ddc229ff6d1e..adb84af42deb 100644
--- a/include/linux/timekeeping.h
+++ b/include/linux/timekeeping.h
@@ -239,6 +239,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_boot_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 26cf6cadd267..35536369a56d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,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,
@@ -624,7 +626,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;
 
@@ -1203,26 +1205,60 @@ static inline void boot_delay_msec(int level)
 #endif
 
 static int printk_time = CONFIG_PRINTK_TIME;
+static int printk_time_setting; /* initial setting */
 
+/*
+ * 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_set(const char *val, const struct kernel_param *kp)
 {
 	char *param = strstrip((char *)val);
+	int _printk_time;
 
 	if (strlen(param) != 1)
 		return -EINVAL;
 
-	if (!strncmp("0", param, 1) || !strncmp("n", param, 1) ||
-	    !strncmp("N", param, 1)) {
-		printk_time = 0;
-	} else if (!strncmp("1", param, 1) || !strncmp("y", param, 1) ||
-		   !strncmp("Y", param, 1)) {
-		printk_time = 1;
-	} else {
-		pr_warn("printk: invalid timestamp value %s.\n", param);
+	switch (param[0]) {
+	case '0':
+	case 'n':
+	case 'N':
+		_printk_time = 0; /* none/disabled */
+		break;
+	case '1':
+	case 'y':
+	case 'Y':
+		_printk_time = 1; /* local unadjusted HW clock */
+		break;
+	case '2':
+		_printk_time = 2; /* boot time */
+		break;
+	case '3':
+		_printk_time = 3; /* real time */
+		break;
+	default:
+		pr_warn("printk: invalid timestamp value\n");
+		return -EINVAL;
+	}
+
+	/*
+	 * Only allow enabling and disabling of the current printk_time
+	 * setting.  Changing it from one setting to another confuses
+	 * userspace.
+	 */
+	if (printk_time_setting == 0) {
+		printk_time_setting = _printk_time;
+	} else if ((printk_time_setting != _printk_time) &&
+		   (_printk_time != 0)) {
+		pr_warn("printk: timestamp can only be set to 0 or %d ",
+			printk_time_setting);
 		return -EINVAL;
 	}
 
-	pr_info("printk: timestamp set to %d.\n", printk_time);
+	printk_time = _printk_time;
+	pr_info("printk: timestamp set to %d.", printk_time);
 	return 0;
 }
 
@@ -1237,6 +1273,21 @@ static int printk_time_get(char *buffer, const struct kernel_param *kp)
 };
 module_param_cb(time, &printk_time_ops, NULL, S_IRUGO | S_IWUSR);
 
+static u64 printk_get_ts(void)
+{
+	u64 mono, offset_real;
+
+	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)
 {
 	unsigned long rem_nsec;
@@ -1675,7 +1726,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;
 	}
 
@@ -2691,6 +2742,10 @@ static int __init printk_late_init(void)
 	struct console *con;
 	int ret;
 
+	/* initialize printk_time settings */
+	if (printk_time_setting == 0)
+		printk_time_setting = printk_time;
+
 	for_each_console(con) {
 		if (!keep_bootcon && con->flags & CON_BOOT) {
 			/*
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index cedafa008de5..96f06a16c51f 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -25,6 +25,7 @@
 #include <linux/stop_machine.h>
 #include <linux/pvclock_gtod.h>
 #include <linux/compiler.h>
+#include <linux/sched/clock.h>
 
 #include "tick-internal.h"
 #include "ntp_internal.h"
@@ -45,6 +46,7 @@
 
 static DEFINE_RAW_SPINLOCK(timekeeper_lock);
 static struct timekeeper shadow_timekeeper;
+static int timekeeping_active;
 
 /**
  * struct tk_fast - NMI safe timekeeper
@@ -477,6 +479,16 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_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 u64 cycles_at_suspend;
 
@@ -1530,6 +1542,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 5b1662ec546f..6cd38a25f8ea 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -1,8 +1,8 @@
 menu "printk and dmesg options"
 
 config PRINTK_TIME
-	int "Show timing information on printks (0-1)"
-	range 0 1
+	int "Show timing information on printks (0-3)"
+	range 0 3
 	default "0"
 	depends on PRINTK
 	help
@@ -13,7 +13,8 @@ config PRINTK_TIME
 	  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. 0 disables the
-	  timestamp and 1 uses the local clock.
+	  timestamp and 1 uses the local clock, 2 uses the monotonic clock, and
+	  3 uses real clock.
 
 	  The behavior is also controlled by the kernel command line
 	  parameter printk.time=1. See Documentation/admin-guide/kernel-parameters.rst
-- 
1.8.5.5