printk: Add new timestamps

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.

Quoted 5 lines · 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.

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?

Quoted 6 lines · Mark Salyzyn

Quoted 5 lines · 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.

Quoted 6 lines

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.

Quoted 16 lines · Prarit Bhargava

Quoted 12 lines · Mark Salyzyn

Quoted 5 lines · 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.

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)

Quoted 1 line

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

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.

kernel/printk/printk.c +8 -2

index fc47863f629c..3c46217629fd 100644
@@ -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.

kernel/printk/printk.c +9 -0

+	"disabled",
+	"local",
+	"boottime",
+	"monotonic",
+	"realtime",
+};
+
+/**
+ * printk_get_real_ns: - Return a realtime timestamp for printk messages

kernel/printk/printk.c +36 -0

+}
+
+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)) {

kernel/printk/printk.c +3 -1

+};
+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;
 

kernel/printk/printk.c +1 -1

 	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;
 	}
 

lib/Kconfig.debug +25 -1

index 98fe715522e8..0262770d6bc5 100644
@@ -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

Quoted 31 lines · 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.

kernel/printk/printk.c +8 -2

index fc47863f629c..3c46217629fd 100644
@@ -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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1225

Quoted 10 lines

kernel/printk/printk.c +10 -0

+ * @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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1226

Quoted 1 line

kernel/printk/printk.c +1 -0

+	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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1227

Quoted 3 lines

kernel/printk/printk.c +1 -0

+	PRINTK_TIME_DISABLE = 1,

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

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1235

Quoted 9 lines

kernel/printk/printk.c +8 -0

+	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"?

Quoted 7 lines

kernel/printk/printk.c +7 -0

+/**
+ * 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)

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1254

Quoted 5 lines

kernel/printk/printk.c +5 -0

+{
+	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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1260

Quoted 7 lines

kernel/printk/printk.c +6 -0

+{
+	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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1272

Quoted 13 lines

kernel/printk/printk.c +12 -0

+		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.

From your comment it looks like you're okay with me leaving it defined, just

Quoted 41 lines

kernel/printk/printk.c +40 -0

+}
+
+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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1318

Quoted 6 lines

kernel/printk/printk.c +6 -0

+		 */
+		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

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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1321

Quoted 3 lines

kernel/printk/printk.c +3 -0

+
+	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.

Quoted 4 lines

kernel/printk/printk.c +2 -0

+		printk_set_timestamp();
 
+

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1333

Quoted 10 lines

kernel/printk/printk.c +10 -0

+	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.

kernel/printk/printk.c static inline void boot_delay_msec(int level) · line 1337

Quoted 5 lines

kernel/printk/printk.c +4 -0

+
+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.

Quoted 67 lines

kernel/printk/printk.c +4 -2

+};
+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;
 	}
 

lib/Kconfig.debug +31 -1

index 98fe715522e8..0262770d6bc5 100644
@@ -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

lib/Kconfig.debug config PRINTK_TIME · line 50

Quoted 4 lines

lib/Kconfig.debug +4 -0

+	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.

lib/Kconfig.debug config PRINTK_TIME · line 61

Quoted 12 lines

lib/Kconfig.debug +11 -0

+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.

Quoted 5 lines · Petr Mladek

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.

Quoted 4 lines

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.