[PATCH 0/2 v7] printk: Add new timestamps

[PATCH 0/2 v7] printk: Add new timestamps

[Prarit Bhargava]

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.

Add monotonic, boottime, and real clock timestamps in addition to the existing
local hardware clock timestamp.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Cc: Mark Salyzyn <salyzyn@android.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Christoffer Dall <cdall@linaro.org>
Cc: Deepa Dinamani <deepa.kernel@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Joel Fernandes <joelaf@google.com>
Cc: Prarit Bhargava <prarit@redhat.com>
Cc: Kees Cook <keescook@chromium.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Geert Uytterhoeven <geert+renesas@glider.be>
Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
Cc: Nicholas Piggin <npiggin@gmail.com>
Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
Cc: Olof Johansson <olof@lixom.net>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: linux-doc@vger.kernel.org
[jstultz: reworked Kconfig settings to avoid defconfig noise]
Signed-off-by: John Stultz <john.stultz@linaro.org>

Prarit Bhargava (2):
  time: Make fast functions return 0 before timekeeping is initialized
  printk: Add monotonic, boottime, and realtime timestamps

 Documentation/admin-guide/kernel-parameters.txt |   6 +-
 include/linux/timekeeping.h                     |   1 +
 kernel/printk/printk.c                          | 150 +++++++++++++++++++++++-
 kernel/time/timekeeping.c                       |  46 ++++++--
 lib/Kconfig.debug                               |  48 +++++++-
 5 files changed, 232 insertions(+), 19 deletions(-)

-- 
1.8.5.5

[PATCH 1/2 v7] time: Make fast functions return 0 before timekeeping is initialized

[Prarit Bhargava]

printk timestamps will be extended to include mono and boot time by using
the fast timekeeping functions ktime_get_mono|boot_fast_ns() functions.
The functions can return garbage before timekeeping is initialized
resulting in garbage timestamps.

The fast time functions must return 0 before timekeeping is initialized.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Suggested-by: Peter Zijlstra <peterz@infradead.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
---
 kernel/time/timekeeping.c | 47 +++++++++++++++++++++++++++++++++--------------
 1 file changed, 33 insertions(+), 14 deletions(-)

diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index cedafa008de5..d111039e0245 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -60,8 +60,39 @@ struct tk_fast {
 	struct tk_read_base	base[2];
 };
 
-static struct tk_fast tk_fast_mono ____cacheline_aligned;
-static struct tk_fast tk_fast_raw  ____cacheline_aligned;
+/* Suspend-time cycles value for halted fast timekeeper. */
+static u64 cycles_at_suspend;
+
+static u64 dummy_clock_read(struct clocksource *cs)
+{
+	return cycles_at_suspend;
+}
+
+static struct clocksource dummy_clock = {
+	.read = dummy_clock_read,
+};
+
+static struct tk_fast tk_fast_mono ____cacheline_aligned = {
+	.base = {
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+	},
+};
+
+static struct tk_fast tk_fast_raw  ____cacheline_aligned = {
+	.base = {
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+		(struct tk_read_base){
+			.clock = &dummy_clock,
+		},
+	},
+};
 
 /* flag for if timekeeping is suspended */
 int __read_mostly timekeeping_suspended;
@@ -477,18 +508,6 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
-/* Suspend-time cycles value for halted fast timekeeper. */
-static u64 cycles_at_suspend;
-
-static u64 dummy_clock_read(struct clocksource *cs)
-{
-	return cycles_at_suspend;
-}
-
-static struct clocksource dummy_clock = {
-	.read = dummy_clock_read,
-};
-
 /**
  * halt_fast_timekeeper - Prevent fast timekeeper from accessing clocksource.
  * @tk: Timekeeper to snapshot.
-- 
1.8.5.5

[PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

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.

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
without the protection of a sequence lock when printk_get_ts() is set
printk_get_real_ns().

v2: Use peterz's suggested Kconfig options.  Merge patchset together.
Fix i386 !CONFIG_PRINTK builds.

v3: Fixed x86_64_defconfig. Added printk_time_type enum and
printk_time_str for better output. Added BOOTTIME clock functionality.

v4: Fix messages, add additional printk.time options, and fix configs.

v5: Renaming of structures, and allow printk_time_set() to
evaluate substrings of entries (eg: allow 'r', 'real', 'realtime').  From
peterz, make fast functions return 0 until timekeeping is initialized
(removes timekeeping_active & ktime_get_boot|real_log_ts() suggested by
 tglx and adds ktime_get_real_offset()).  Switch to a function pointer
for printk_get_ts() and reference fast functions.  Make timestamp_sources enum
match choice options for CONFIG_PRINTK_TIME (adds PRINTK_TIME_UNDEFINED).

v6: Define PRINTK_TIME_UNDEFINED for !CONFIG_PRINTK builds.  Separate
timekeeping changes into separate patch.  Minor include file cleanup.

v7: Add default case to printk_set_timestamp() and add PRINTK_TIME_DEBUG
for users that want to set timestamp to different values during runtime.
Add jstultz' Kconfig to avoid defconfig churn.

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Cc: Mark Salyzyn <salyzyn@android.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Stephen Boyd <sboyd@codeaurora.org>
Cc: Andrew Morton <akpm@linux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Christoffer Dall <cdall@linaro.org>
Cc: Deepa Dinamani <deepa.kernel@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Joel Fernandes <joelaf@google.com>
Cc: Prarit Bhargava <prarit@redhat.com>
Cc: Kees Cook <keescook@chromium.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Geert Uytterhoeven <geert+renesas@glider.be>
Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
Cc: Nicholas Piggin <npiggin@gmail.com>
Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
Cc: Olof Johansson <olof@lixom.net>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: linux-doc@vger.kernel.org
[jstultz: reworked Kconfig settings to avoid defconfig noise]
Signed-off-by: John Stultz <john.stultz@linaro.org>
---
 Documentation/admin-guide/kernel-parameters.txt |   6 +-
 include/linux/timekeeping.h                     |   1 +
 kernel/printk/printk.c                          | 150 +++++++++++++++++++++++-
 kernel/time/timekeeping.c                       |   5 +
 lib/Kconfig.debug                               |  48 +++++++-
 5 files changed, 202 insertions(+), 8 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index d9c171ce4190..1ba277ecbf24 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: <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,
+				 b/boot, m/monotonic, r/realtime)
 
 	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..80ca2fa22b6a 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_real_offset(void);
 
 /*
  * Timespec interfaces utilizing the ktime based ones
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..3c46217629fd 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -576,6 +576,9 @@ 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_set_timestamp(void);
+static u64 (*printk_get_ts)(void) = printk_set_timestamp;
+
 /* 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 +627,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;
 
@@ -1202,14 +1205,144 @@ 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 = CONFIG_PRINTK_TIME_TYPE;
+static int printk_time_source;
+
+/**
+ * enum timestamp_sources - Timestamp sources for printk() messages.
+ * @PRINTK_TIME_UNDEFINED: Timestamp undefined.  This option is not selectable
+ * from the configs, and is used as a reference in the code.
+ * @PRINTK_TIME_DISABLE: 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.  On 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 when printk_get_ts() is set to
+ * printk_get_real_ns().
+ */
+enum timestamp_sources {
+	PRINTK_TIME_UNDEFINED = 0,
+	PRINTK_TIME_DISABLE = 1,
+	PRINTK_TIME_LOCAL = 2,
+	PRINTK_TIME_BOOT = 3,
+	PRINTK_TIME_MONO = 4,
+	PRINTK_TIME_REAL = 5,
+};
+
+static const char * const timestamp_sources_str[6] = {
+	"undefined",
+	"disabled",
+	"local",
+	"boottime",
+	"monotonic",
+	"realtime",
+};
+
+/**
+ * printk_get_real_ns: - Return a realtime timestamp for printk messages
+ * On 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.
+ */
+static u64 printk_get_real_ns(void)
+{
+	return ktime_get_mono_fast_ns() + ktime_get_real_offset();
+}
+
+static u64 printk_set_timestamp(void)
+{
+	switch (printk_time) {
+	case PRINTK_TIME_LOCAL:
+	case PRINTK_TIME_DISABLE:
+	default:
+		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 = printk_get_real_ns;
+		break;
+	}
+	return printk_get_ts();
+}
+
+static int printk_time_set(const char *val, const struct kernel_param *kp)
+{
+	char *param = strstrip((char *)val);
+	int _printk_time = PRINTK_TIME_UNDEFINED;
+	int ts;
+
+	if (strlen(param) == 1) {
+		/* Preserve legacy boolean settings */
+		if ((param[0] == '0') || (param[0] == 'n') ||
+		    (param[0] == 'N'))
+			_printk_time = PRINTK_TIME_DISABLE;
+		if ((param[0] == '1') || (param[0] == 'y') ||
+		    (param[0] == 'Y'))
+			_printk_time = PRINTK_TIME_LOCAL;
+	}
+	if (_printk_time == PRINTK_TIME_UNDEFINED) {
+		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 == PRINTK_TIME_UNDEFINED) {
+		pr_warn("printk: invalid timestamp option %s\n", param);
+		return -EINVAL;
+	}
+
+	if (printk_time_source == PRINTK_TIME_UNDEFINED)
+		printk_time_source = _printk_time;
+#ifndef PRINTK_TIME_DEBUG
+	else if ((printk_time_source != _printk_time) &&
+		 (_printk_time != PRINTK_TIME_DISABLE)) {
+		/*
+		 * Only allow enabling and disabling of the current printk_time
+		 * setting.  Changing it from one setting to another confuses
+		 * userspace.
+		 */
+		pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
+			timestamp_sources_str[printk_time_source]);
+		return -EINVAL;
+	}
+#endif
+
+	printk_time = _printk_time;
+	if (printk_time_source > PRINTK_TIME_DISABLE)
+		printk_set_timestamp();
+
+	pr_info("printk: timestamp set to %s\n",
+		timestamp_sources_str[printk_time]);
+	return 0;
+}
+
+static int printk_time_get(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 = printk_time_set,
+	.get = printk_time_get,
+};
+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_DISABLE)
 		return 0;
 
 	rem_nsec = do_div(ts, 1000000000);
@@ -1643,7 +1776,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;
 	}
 
@@ -1873,6 +2006,9 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
+#define PRINTK_TIME_UNDEFINED 0
+static int printk_time;
+static int printk_time_source;
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2659,6 +2795,10 @@ static int __init printk_late_init(void)
 	struct console *con;
 	int ret;
 
+	/* initialize printk_time settings */
+	if (printk_time_source == PRINTK_TIME_UNDEFINED)
+		printk_time_source = 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 d111039e0245..de07bb5ffef5 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -508,6 +508,11 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
+u64 ktime_get_real_offset(void)
+{
+	return ktime_to_ns(tk_core.timekeeper.offs_real);
+}
+
 /**
  * halt_fast_timekeeper - Prevent fast timekeeper from accessing clocksource.
  * @tk: Timekeeper to snapshot.
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 98fe715522e8..0262770d6bc5 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"
+	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"
+	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"
+	help
+	  Selecting this option causes the time stamps of printk() to be
+	  stamped with the adjusted realtime clock.
+endchoice
+
+config PRINTK_TIME_TYPE
+	int
+	depends on PRINTK
+	range 1 5
+	default 1 if !PRINTK_TIME
+	default 2 if PRINTK_TIME_LOCAL
+	default 3 if PRINTK_TIME_BOOT
+	default 4 if PRINTK_TIME_MONO
+	default 5 if PRINTK_TIME_REAL
+
 
 config CONSOLE_LOGLEVEL_DEFAULT
 	int "Default console loglevel (1-15)"
-- 
1.8.5.5

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Mark Salyzyn]

On 08/17/2017 06:15 AM, 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.
Congrats, greatly eases merges into older kernels, and has eliminated 
the churn this could place on all the configured systems out there.

Sadly, one of my suggestions did not quite go the way I expected ;-} 
easy to correct, and fix (I missed a spot in my original suggestion, as 
code changed underfoot over the set ;-/). (see bottom)

<discussion type="maybe out of the scope for this patch">

I am not convinced that user space is entirely at a disadvantage with 
this 'feature' enabled. Before interpreting it can read 
/sys/module/printk/parameters/time, then sniff for the flowing content 
for time breaks (watch for printk: timestamp set to <string>). Of 
course, the value in 'time' is current, so it would be _wrong_ during 
flow of previous content until the first time break shows up if it 
really was being switched that often.

(echo local ; echo disabled ; echo boottime ; echo monotonic ; echo 
realtime ; echo local ) > /sys/module/printk/parameters/time

[  473.589169] printk: timestamp set to local
printk: timestamp set to disabled
[  473.545384] printk: timestamp set to boottime
[  473.549924] printk: timestamp set to monotonic
[1502957708.055265] printk: timestamp set to realtime
[  473.612024] printk: timestamp set to local

A 'fix' would be to add a letter after the timestamp if not local. For 
example:

[  473.589169] printk: timestamp set to local
printk: timestamp set to disabled
[  473.545384b] printk: timestamp set to boottime
[  473.549924m] printk: timestamp set to monotonic
[1502957708.055265U] printk: timestamp set to realtime
[  473.612024] printk: timestamp set to local

(I used U instead of r, because it is actually UTC, and did not add 'l' 
because it is a long standing default)

But there would be concern over a change in time format API, so maybe it 
should be relegated to a CONFIG_PRINTK_TIME_DEBUG 'feature' only to add 
the timebase letters?

</discussion>

. . .

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8817ed5ee6a3..2e3321f6604b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1273,7 +1273,7 @@ static int printk_time_set(const char *val, const 
struct kernel_param *kp)

         if (printk_time_source == PRINTK_TIME_UNDEFINED)
                 printk_time_source = _printk_time;
-#ifndef PRINTK_TIME_DEBUG
+#ifndef CONFIG_PRINTK_TIME_DEBUG
         else if ((printk_time_source != _printk_time) &&
                  (_printk_time != PRINTK_TIME_DISABLE)) {
                 /*

@@ -1288,7 +1288,9 @@ static int printk_time_set(const char *val, const 
struct kernel_param *kp)
  #endif

         printk_time = _printk_time;
+#ifndef CONFIG_PRINTK_TIME_DEBUG
         if (printk_time_source > PRINTK_TIME_DISABLE)
+#endif
                 printk_set_timestamp();

         pr_info("printk: timestamp set to %s\n",

> +
> +config PRINTK_TIME_TYPE
> +	int
> +	depends on PRINTK
> +	range 1 5
> +	default 1 if !PRINTK_TIME
> +	default 2 if PRINTK_TIME_LOCAL
> +	default 3 if PRINTK_TIME_BOOT
> +	default 4 if PRINTK_TIME_MONO
> +	default 5 if PRINTK_TIME_REAL
> +
>   
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 1fb23d851ca2..2517ed69d7f8 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -60,6 +60,22 @@ config PRINTK_TIME_TYPE
      default 4 if PRINTK_TIME_MONO
      default 5 if PRINTK_TIME_REAL

+config PRINTK_TIME_DEBUG
+    bool "Allow runtime reselection of any timebase on printks"
+    depends on PRINTK
+    help
+      Selecting this option causes time stamps of the printk()
+      messages to be changed freely at runtime on the output of
+      the syslog() system call and at the console. Without this
+      option, one can only enable or disable the configuration
+      selected timebase.
+
+      Runtime adjustment can be set via
+      /sys/module/printk/paramters/time as follows with a string:
+      0/N/n/disable, 1/Y/y/local, b/boot, m/monotonic, r/realtime.
+      eg: echo local >/sys/module/printk/parameters/time
+          echo realtime >/sys/module/printk/parameters/time
+
  config MESSAGE_LOGLEVEL_DEFAULT
      int "Default message log level (1-15)"
      range 1 15

The last bit should probably be adjusted to eliminate details, maybe 
keep the example as it will stand the test of time, and merely reference 
the Documentation tree w.r.t. printk.time=

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 08/17/2017 11:30 AM, Mark Salyzyn wrote:
> On 08/17/2017 06:15 AM, 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.
> Congrats, greatly eases merges into older kernels, and has eliminated the churn
> this could place on all the configured systems out there.
> 
> Sadly, one of my suggestions did not quite go the way I expected ;-} easy to
> correct, and fix (I missed a spot in my original suggestion, as code changed
> underfoot over the set ;-/). (see bottom)

Added.  I will send out v8 shortly.

> 
> <discussion type="maybe out of the scope for this patch">
> 
> I am not convinced that user space is entirely at a disadvantage with this
> 'feature' enabled. Before interpreting it can read
> /sys/module/printk/parameters/time, then sniff for the flowing content for time
> breaks (watch for printk: timestamp set to <string>). Of course, the value in
> 'time' is current, so it would be _wrong_ during flow of previous content until
> the first time break shows up if it really was being switched that often.
> 
> (echo local ; echo disabled ; echo boottime ; echo monotonic ; echo realtime ;
> echo local ) > /sys/module/printk/parameters/time
> 
> [  473.589169] printk: timestamp set to local
> printk: timestamp set to disabled
> [  473.545384] printk: timestamp set to boottime
> [  473.549924] printk: timestamp set to monotonic
> [1502957708.055265] printk: timestamp set to realtime
> [  473.612024] printk: timestamp set to local
> 
> A 'fix' would be to add a letter after the timestamp if not local. For example:
> 
> [  473.589169] printk: timestamp set to local
> printk: timestamp set to disabled
> [  473.545384b] printk: timestamp set to boottime
> [  473.549924m] printk: timestamp set to monotonic
> [1502957708.055265U] printk: timestamp set to realtime
> [  473.612024] printk: timestamp set to local
> 
> (I used U instead of r, because it is actually UTC, and did not add 'l' because
> it is a long standing default)
> 
> But there would be concern over a change in time format API, so maybe it should
> be relegated to a CONFIG_PRINTK_TIME_DEBUG 'feature' only to add the timebase
> letters?

... then you wouldn't be able to use dmesg, etc., to get proper timestamp
conversions. :(  I'm not going to code dmesg for that because, as you point out
it is outside of the scope of this patch.  Maybe we can do something in future
for this?

P.

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Petr Mladek]

On Tue 2017-08-22 10:09:40, Prarit Bhargava wrote:
> 
> 
> On 08/17/2017 11:30 AM, Mark Salyzyn wrote:
> > On 08/17/2017 06:15 AM, 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.
> > Congrats, greatly eases merges into older kernels, and has eliminated the churn
> > this could place on all the configured systems out there.
> > 
> > Sadly, one of my suggestions did not quite go the way I expected ;-} easy to
> > correct, and fix (I missed a spot in my original suggestion, as code changed
> > underfoot over the set ;-/). (see bottom)
> 
> Added.  I will send out v8 shortly.

It might make sense to wait a bit. I am in the middle of v7 review and
have several comments.

I would suggest to slow down this a bit anyway. You sent 7 versions
within three weeks. It improved nicely over time. But I think that
I am not the only one who has troubles to follow.

Best Regards,
Petr

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 08/22/2017 10:23 AM, Petr Mladek wrote:
> On Tue 2017-08-22 10:09:40, Prarit Bhargava wrote:
>>
>>
>> On 08/17/2017 11:30 AM, Mark Salyzyn wrote:
>>> On 08/17/2017 06:15 AM, 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.
>>> Congrats, greatly eases merges into older kernels, and has eliminated the churn
>>> this could place on all the configured systems out there.
>>>
>>> Sadly, one of my suggestions did not quite go the way I expected ;-} easy to
>>> correct, and fix (I missed a spot in my original suggestion, as code changed
>>> underfoot over the set ;-/). (see bottom)
>>
>> Added.  I will send out v8 shortly.
> 
> It might make sense to wait a bit. I am in the middle of v7 review and
> have several comments.
> 
> I would suggest to slow down this a bit anyway. You sent 7 versions
> within three weeks. It improved nicely over time. But I think that
> I am not the only one who has troubles to follow.
> 

np Petr.  I will hold off on v8.

P.

> Best Regards,
> Petr
> 

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Petr Mladek]

On Thu 2017-08-17 09:15:39, 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..3c46217629fd 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,14 +1205,144 @@ 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 = CONFIG_PRINTK_TIME_TYPE;
> +static int printk_time_source;
> +
> +/**
> + * enum timestamp_sources - Timestamp sources for printk() messages.
> + * @PRINTK_TIME_UNDEFINED: Timestamp undefined.  This option is not selectable
> + * from the configs, and is used as a reference in the code.
> + * @PRINTK_TIME_DISABLE: 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.  On 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 when printk_get_ts() is set to
> + * printk_get_real_ns().
> + */
> +enum timestamp_sources {

I guess that this might be static. Also it is related to the
PRINTK_TIME_TYPE Kconfig option. So the name should be
enum printk_time_type or so.


> +	PRINTK_TIME_UNDEFINED = 0,

I would use -1 for PRINTK_TIME_UNDEFINED or I would remove it
completely, see below. Then we could use 0 for PRINTK_TIME_DISABLED
which is more expected.


> +	PRINTK_TIME_DISABLE = 1,

This should be PRINTK_TIME_DISABLED to be in sync with
the string and style of the other flags.


> +	PRINTK_TIME_LOCAL = 2,
> +	PRINTK_TIME_BOOT = 3,
> +	PRINTK_TIME_MONO = 4,
> +	PRINTK_TIME_REAL = 5,
> +};
> +
> +static const char * const timestamp_sources_str[6] = {
> +	"undefined",

Do we really need the string "undefined"? Is user able
to see or enter it?


> +	"disabled",
> +	"local",
> +	"boottime",
> +	"monotonic",
> +	"realtime",
> +};
> +
> +/**
> + * printk_get_real_ns: - Return a realtime timestamp for printk messages
> + * On 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.
> + */
> +static u64 printk_get_real_ns(void)
> +{
> +	return ktime_get_mono_fast_ns() + ktime_get_real_offset();
> +}
> +
> +static u64 printk_set_timestamp(void)

I would rename this function to printk_set_ts_func() or so.
It will be more clear the it sets the function pointer.


> +{
> +	switch (printk_time) {
> +	case PRINTK_TIME_LOCAL:
> +	case PRINTK_TIME_DISABLE:
> +	default:
> +		printk_get_ts = local_clock;

The PRINTK_TIME_DISABLE case is more complicated. We should set
printk_get_ts only when it has not been set yet. Otherwise,
we should keep storing the same type of time stamps into
to the log buffer and keep it consistent.


> +		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 = printk_get_real_ns;
> +		break;
> +	}
> +	return printk_get_ts();

On one hand, this side effect helps to reuse the same code but it
looks too hacky to me. Another possibility would be to create:

static u64 printk_get_first_ts()
{
	printk_set_ts_function();

	return printk_get_ts();
}

and initialize:

static u64 (*printk_get_ts)(void) = printk_get_first_ts();

Another side effect is that we might not need PRINTK_TIME_UNDEFINED.


> +}
> +
> +static int printk_time_set(const char *val, const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +	int _printk_time = PRINTK_TIME_UNDEFINED;
> +	int ts;
> +
> +	if (strlen(param) == 1) {
> +		/* Preserve legacy boolean settings */
> +		if ((param[0] == '0') || (param[0] == 'n') ||
> +		    (param[0] == 'N'))
> +			_printk_time = PRINTK_TIME_DISABLE;
> +		if ((param[0] == '1') || (param[0] == 'y') ||
> +		    (param[0] == 'Y'))
> +			_printk_time = PRINTK_TIME_LOCAL;
> +	}
> +	if (_printk_time == PRINTK_TIME_UNDEFINED) {
> +		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 == PRINTK_TIME_UNDEFINED) {
> +		pr_warn("printk: invalid timestamp option %s\n", param);
> +		return -EINVAL;
> +	}
> +
> +	if (printk_time_source == PRINTK_TIME_UNDEFINED)
> +		printk_time_source = _printk_time;
> +#ifndef PRINTK_TIME_DEBUG
> +	else if ((printk_time_source != _printk_time) &&
> +		 (_printk_time != PRINTK_TIME_DISABLE)) {
> +		/*
> +		 * Only allow enabling and disabling of the current printk_time
> +		 * setting.  Changing it from one setting to another confuses
> +		 * userspace.
> +		 */
> +		pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
> +			timestamp_sources_str[printk_time_source]);
> +		return -EINVAL;
> +	}
> +#endif

Do we really need this complication? I guess that people will
touch this option only for debugging purposes. Then they
should know what they are doing and the below printed
pr_info() should be enough.

Note that this does not prevent the first change from the compiled
in default to one selected by command line parameter. We must not
prevent it. Otherwise, people would not be able to change
it at all.

I mean that we need to make sure that the first switch
is handled reasonably. Then also more switches might
be OK.


And this brings an important question. Do you have any plans
to update userspace for this change (dmesg, crash, syslogd,
other loggers)?

If I compile the kernel with CONFIG_PRINTK_TIME_LOCAL=y
and boot with printk.time=realtime. Then I get
the following output from dmesg --time-format=iso:

2017-08-23T09:38:10,000000+0200 RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
2017-08-23T09:38:10,000000+0200 NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16
2017-08-23T09:38:10,000000+0200         Offload RCU callbacks from CPUs: .
2065-04-14T17:16:20,287498+0200 Console: colour dummy device 80x25
2065-04-14T17:16:20,287498+0200 console [tty0] enabled
2065-04-14T17:16:20,287498+0200 console [ttyS0] enabled

I would like to see patches for at least one tool (dmesg)
that would make it working properly. It will prove that
the kernel side allows userspace to handle this
a reasonable way.


> +
> +	printk_time = _printk_time;
> +	if (printk_time_source > PRINTK_TIME_DISABLE)

Ah, this actually prevents replacing the printk_get_ts
with local_clock. IMHO, it will be more clear and safe
if we handle this in printk_set_timestamp() as suggested above.


> +		printk_set_timestamp();
>
> +
> +	pr_info("printk: timestamp set to %s\n",
> +		timestamp_sources_str[printk_time]);
> +	return 0;
> +}
> +
> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
> +{
> +	return scnprintf(buffer, PAGE_SIZE, "%s",
> +			 timestamp_sources_str[printk_time]);
> +}

I know that it would make the code more complicated. But
I really like the approach used by /sys/power/disk or
/sys/power/pm_test. They list all possible values
and put the selected one into [] brackets.

Well, this might be done in a separate patch.
I am not 100% sure that this actually does not break some
rules for sysfs.


> +
> +static struct kernel_param_ops printk_time_ops = {
> +	.set = printk_time_set,
> +	.get = printk_time_get,

It seems that an often used naming scheme is:

   .set = param_set_<param_name>
   .get = param_get_<param_name>

Please, use it. It think that they make the meaning more obvious.

> +};
> +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_DISABLE)
>  		return 0;
>  
>  	rem_nsec = do_div(ts, 1000000000);
> @@ -1643,7 +1776,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;
>  	}
>  
> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
> index 98fe715522e8..0262770d6bc5 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"
> +	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"
> +	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"
> +	help
> +	  Selecting this option causes the time stamps of printk() to be
> +	  stamped with the adjusted realtime clock.

It might make sense to point out that this is in UTC. I would mention
this also in kernel-parameters. The discussion about an older version
of this patchset suggests that this is not widely known.


> +endchoice
> +
> +config PRINTK_TIME_TYPE
> +	int
> +	depends on PRINTK
> +	range 1 5
> +	default 1 if !PRINTK_TIME
> +	default 2 if PRINTK_TIME_LOCAL
> +	default 3 if PRINTK_TIME_BOOT
> +	default 4 if PRINTK_TIME_MONO
> +	default 5 if PRINTK_TIME_REAL

I am surprised that this even force PRINTK_TIME_TYPE to be
in sync with the above choice. I would expect that "default"
would still allow to set another value here and make
it inconsistent. For example I tried to define:

CONFIG_PRINTK_TIME=y
CONFIG_PRINTK_TIME_LOCAL=y
CONFIG_PRINTK_TIME_TYPE=4

But "make" automatically fixed this to

CONFIG_PRINTK_TIME=y
CONFIG_PRINTK_TIME_LOCAL=y
CONFIG_PRINTK_TIME_TYPE=2

which is great. I hope that we could rely on this.


Best Regards,
Petr

PS: I agree that this functionality would be useful. My main
concern is how to "always" display the time correctly, especially
by userpace tools. It does not make sense to solve the other
rather cosmetic probles until we have a good answer for
the main one.

Note that we could store the information about the time
type for each line in struct printk_log for each line.
There are two unused bits in log_flags (one is LOG_NOCONS).
The question is how to pass it to userspace.

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 08/23/2017 04:45 AM, Petr Mladek wrote:
> On Thu 2017-08-17 09:15:39, 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..3c46217629fd 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -1202,14 +1205,144 @@ 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 = CONFIG_PRINTK_TIME_TYPE;
>> +static int printk_time_source;
>> +
>> +/**
>> + * enum timestamp_sources - Timestamp sources for printk() messages.
>> + * @PRINTK_TIME_UNDEFINED: Timestamp undefined.  This option is not selectable
>> + * from the configs, and is used as a reference in the code.
>> + * @PRINTK_TIME_DISABLE: 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.  On 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 when printk_get_ts() is set to
>> + * printk_get_real_ns().
>> + */
>> +enum timestamp_sources {
> 
> I guess that this might be static. Also it is related to the
> PRINTK_TIME_TYPE Kconfig option. So the name should be
> enum printk_time_type or so.
> 
> 
>> +	PRINTK_TIME_UNDEFINED = 0,
> 
> I would use -1 for PRINTK_TIME_UNDEFINED or I would remove it
> completely, see below. Then we could use 0 for PRINTK_TIME_DISABLED
> which is more expected.

FIXED along with adjustment of configs (see below).

> 
> 
>> +	PRINTK_TIME_DISABLE = 1,
> 
> This should be PRINTK_TIME_DISABLED to be in sync with
> the string and style of the other flags.
>

FIXED.

> 
>> +	PRINTK_TIME_LOCAL = 2,
>> +	PRINTK_TIME_BOOT = 3,
>> +	PRINTK_TIME_MONO = 4,
>> +	PRINTK_TIME_REAL = 5,
>> +};
>> +
>> +static const char * const timestamp_sources_str[6] = {
>> +	"undefined",
> 
> Do we really need the string "undefined"? 

It is only included to keep timestamp_sources_str & the enum in sync.
FIXED & removed with adjustment of configs & enum.

<snip>

>> +/**
>> + * printk_get_real_ns: - Return a realtime timestamp for printk messages
>> + * On 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.
>> + */
>> +static u64 printk_get_real_ns(void)
>> +{
>> +	return ktime_get_mono_fast_ns() + ktime_get_real_offset();
>> +}
>> +
>> +static u64 printk_set_timestamp(void)
> 
> I would rename this function to printk_set_ts_func() or so.
> It will be more clear the it sets the function pointer.
> 

FIXED.

> 
>> +{
>> +	switch (printk_time) {
>> +	case PRINTK_TIME_LOCAL:
>> +	case PRINTK_TIME_DISABLE:
>> +	default:
>> +		printk_get_ts = local_clock;
> 
> The PRINTK_TIME_DISABLE case is more complicated. We should set
> printk_get_ts only when it has not been set yet. Otherwise,
> we should keep storing the same type of time stamps into
> to the log buffer and keep it consistent.
> 

I think you've figured this out below.... but for other readers,
printk_time_set() does not call printk_set_timestamp with
printk_time = PRINTK_TIME_DISABLE.

> 
>> +		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 = printk_get_real_ns;
>> +		break;
>> +	}
>> +	return printk_get_ts();
> 
> On one hand, this side effect helps to reuse the same code but it
> looks too hacky to me. Another possibility would be to create:
> 
> static u64 printk_get_first_ts()
> {
> 	printk_set_ts_function();
> 
> 	return printk_get_ts();
> }
> 
> and initialize:
> 
> static u64 (*printk_get_ts)(void) = printk_get_first_ts();
> 

FIXED.

> Another side effect is that we might not need PRINTK_TIME_UNDEFINED.
> 

I tried to do this, however, I still need PRINTK_TIME_UNDEFINED to indicate
that printk_time_source is not set.  PRINTK_TIME_UNDEFINED "reads" better IMO.
>From your comment it looks like you're okay with me leaving it defined, just
not as 0.  I have changed it to -1.  FIXED.

> 
>> +}
>> +
>> +static int printk_time_set(const char *val, const struct kernel_param *kp)
>> +{
>> +	char *param = strstrip((char *)val);
>> +	int _printk_time = PRINTK_TIME_UNDEFINED;
>> +	int ts;
>> +
>> +	if (strlen(param) == 1) {
>> +		/* Preserve legacy boolean settings */
>> +		if ((param[0] == '0') || (param[0] == 'n') ||
>> +		    (param[0] == 'N'))
>> +			_printk_time = PRINTK_TIME_DISABLE;
>> +		if ((param[0] == '1') || (param[0] == 'y') ||
>> +		    (param[0] == 'Y'))
>> +			_printk_time = PRINTK_TIME_LOCAL;
>> +	}
>> +	if (_printk_time == PRINTK_TIME_UNDEFINED) {
>> +		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 == PRINTK_TIME_UNDEFINED) {
>> +		pr_warn("printk: invalid timestamp option %s\n", param);
>> +		return -EINVAL;
>> +	}
>> +
>> +	if (printk_time_source == PRINTK_TIME_UNDEFINED)
>> +		printk_time_source = _printk_time;
>> +#ifndef PRINTK_TIME_DEBUG
>> +	else if ((printk_time_source != _printk_time) &&
>> +		 (_printk_time != PRINTK_TIME_DISABLE)) {
>> +		/*
>> +		 * Only allow enabling and disabling of the current printk_time
>> +		 * setting.  Changing it from one setting to another confuses
>> +		 * userspace.
>> +		 */
>> +		pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n",
>> +			timestamp_sources_str[printk_time_source]);
>> +		return -EINVAL;
>> +	}
>> +#endif
> 
> Do we really need this complication? I guess that people will

This has been requested multiple times by Mark Salyzyn <salyzyn@android.com>.
It does not add any additional complexity beyond a (recently requested)
config option.  I like the option FWIW and I just forgot to include it (sorry
Mark) in earlier versions.  I like Mark's idea of adding 'b', r', etc.,
to the timestamps but have put it off for future effort... but your suggestion
below is a better approach [1].  After some discussion with Mark,
I'll see what I can do after this initial patchset is completed.

<snip>

> 
> 
> And this brings an important question. Do you have any plans
> to update userspace for this change (dmesg, crash, syslogd,
> other loggers)?

I mentioned this in an earlier version of these patches -- I have code for
dmesg.  crash, as I said before, doesn't need to be modified according to
Dave Anderson.  dmesg, from util-linux, requires *this* patchset to be in
Linus' tree before they will even look at a patch.

> 
> If I compile the kernel with CONFIG_PRINTK_TIME_LOCAL=y
> and boot with printk.time=realtime. Then I get
> the following output from dmesg --time-format=iso:
> 
> 2017-08-23T09:38:10,000000+0200 RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
> 2017-08-23T09:38:10,000000+0200 NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16
> 2017-08-23T09:38:10,000000+0200         Offload RCU callbacks from CPUs: .
> 2065-04-14T17:16:20,287498+0200 Console: colour dummy device 80x25
> 2065-04-14T17:16:20,287498+0200 console [tty0] enabled
> 2065-04-14T17:16:20,287498+0200 console [ttyS0] enabled
> 

Yes, you've pointed this out before and I have a solution for dmesg.

> I would like to see patches for at least one tool (dmesg)
> that would make it working properly. It will prove that
> the kernel side allows userspace to handle this
> a reasonable way.
> 
> 
>> +
>> +	printk_time = _printk_time;
>> +	if (printk_time_source > PRINTK_TIME_DISABLE)
> 
> Ah, this actually prevents replacing the printk_get_ts
> with local_clock. IMHO, it will be more clear and safe
> if we handle this in printk_set_timestamp() as suggested above.
> 

FIXED.

> 
>> +		printk_set_timestamp();
>>
>> +
>> +	pr_info("printk: timestamp set to %s\n",
>> +		timestamp_sources_str[printk_time]);
>> +	return 0;
>> +}
>> +
>> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
>> +{
>> +	return scnprintf(buffer, PAGE_SIZE, "%s",
>> +			 timestamp_sources_str[printk_time]);
>> +}
> 
> I know that it would make the code more complicated. But
> I really like the approach used by /sys/power/disk or
> /sys/power/pm_test. They list all possible values
> and put the selected one into [] brackets.
> 

I like the idea too, however, I think that complicates things with userspace
(which as you point out is something that we really need to be concerned
with).  I am using /sys/modules/printk/parameters/time to indicate the
timestamp to userspace.

With my code, userspace would see "realtime" or "disabled".  With your
suggested change they would see "disabled [realtime]".  I think that
file needs to be a simple as possible and be a single entry for userspace
to consume.  IMHO.

> Well, this might be done in a separate patch.
> I am not 100% sure that this actually does not break some
> rules for sysfs.
> 

I don't see anything that says I must list every available option
but I only did a quick overview of the docs.

> 
>> +
>> +static struct kernel_param_ops printk_time_ops = {
>> +	.set = printk_time_set,
>> +	.get = printk_time_get,
> 
> It seems that an often used naming scheme is:
> 
>    .set = param_set_<param_name>
>    .get = param_get_<param_name>
> 
> Please, use it. It think that they make the meaning more obvious.

FIXED.

> 
>> +};
>> +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_DISABLE)
>>  		return 0;
>>  
>>  	rem_nsec = do_div(ts, 1000000000);
>> @@ -1643,7 +1776,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;
>>  	}
>>  
>> diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
>> index 98fe715522e8..0262770d6bc5 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"
>> +	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"
>> +	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"
>> +	help
>> +	  Selecting this option causes the time stamps of printk() to be
>> +	  stamped with the adjusted realtime clock.
> 
> It might make sense to point out that this is in UTC. I would mention
> this also in kernel-parameters. The discussion about an older version
> of this patchset suggests that this is not widely known.
> 

FIXED in Kconfig & kernel-parameters.txt.

> 
>> +endchoice
>> +
>> +config PRINTK_TIME_TYPE
>> +	int
>> +	depends on PRINTK
>> +	range 1 5
>> +	default 1 if !PRINTK_TIME
>> +	default 2 if PRINTK_TIME_LOCAL
>> +	default 3 if PRINTK_TIME_BOOT
>> +	default 4 if PRINTK_TIME_MONO
>> +	default 5 if PRINTK_TIME_REAL
> 
> I am surprised that this even force PRINTK_TIME_TYPE to be
> in sync with the above choice. I would expect that "default"
> would still allow to set another value here and make
> it inconsistent. For example I tried to define:
> 

Aside: I have changed to 0-4 range to remove "undefined" from
timestamp_sources_str[], and modified additional code to reflect the change.

> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=4
> 
> But "make" automatically fixed this to
> 
> CONFIG_PRINTK_TIME=y
> CONFIG_PRINTK_TIME_LOCAL=y
> CONFIG_PRINTK_TIME_TYPE=2
> 
> which is great. I hope that we could rely on this.
> 

Yes, I think this among the reasons why peterz & John recommended this method.

> 
> Best Regards,
> Petr
>

> PS: I agree that this functionality would be useful. My main
> concern is how to "always" display the time correctly, especially
> by userpace tools. It does not make sense to solve the other
> rather cosmetic probles until we have a good answer for
> the main one.
> 

[1]:  Mark ... this is an interesting idea we should pursue in the future,
as I think it would nicely solve your request for the timestamp info.

> Note that we could store the information about the time
> type for each line in struct printk_log for each line.
> There are two unused bits in log_flags (one is LOG_NOCONS).
> The question is how to pass it to userspace.
>

P.

Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime timestamps

[John Stultz]

On Wed, Aug 23, 2017 at 11:31 AM, Prarit Bhargava <prarit@redhat.com> wrote:
> On 08/23/2017 04:45 AM, Petr Mladek wrote:
>> I know that it would make the code more complicated. But
>> I really like the approach used by /sys/power/disk or
>> /sys/power/pm_test. They list all possible values
>> and put the selected one into [] brackets.
>>
>
> I like the idea too, however, I think that complicates things with userspace
> (which as you point out is something that we really need to be concerned
> with).  I am using /sys/modules/printk/parameters/time to indicate the
> timestamp to userspace.
>
> With my code, userspace would see "realtime" or "disabled".  With your
> suggested change they would see "disabled [realtime]".  I think that
> file needs to be a simple as possible and be a single entry for userspace
> to consume.  IMHO.
>
>> Well, this might be done in a separate patch.
>> I am not 100% sure that this actually does not break some
>> rules for sysfs.
>>
>
> I don't see anything that says I must list every available option
> but I only did a quick overview of the docs.

I think the issue is that sysfs uses a "one value per file" rule.  So
a value can be a list of possible options or the current option being
used, but mixing a list of options with some formatting to also
communicate the current option isn't strictly following the rule.
This is why we have available_clocksources and current_clocksource
entries.

That said, its not something that has been perfectly followed, so I'm
not sure how much of an issue it really is. I suspect GregKH would be
the gatekeeper on that.

thanks
-john