Skip to contentSkip to conversation

printk: Add new timestamps

PATCH Superseded Prarit Bhargava 2 participants 4 messages Aug 25, 2017

Subsystems (4)

v9 of 12 Superseded Latest is v12 →

lore
Share & tools
lore
#0 lore raw

v9 cover 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.

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

Cc Mark Salyzyn <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Petr Mladek <[email protected]>
Cc Sergey Senozhatsky <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc John Stultz <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Stephen Boyd <[email protected]>
Cc Andrew Morton <[email protected]>
Cc Greg Kroah-Hartman <[email protected]>
Cc "Paul E. McKenney" <[email protected]>
Cc Christoffer Dall <[email protected]>
Cc Deepa Dinamani <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Joel Fernandes <[email protected]>
Cc Prarit Bhargava <[email protected]>
Cc Kees Cook <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Geert Uytterhoeven <[email protected]>
Cc "Luis R. Rodriguez" <[email protected]>
Cc Nicholas Piggin <[email protected]>
Cc "Jason A. Donenfeld" <[email protected]>
Cc Olof Johansson <[email protected]>
Cc Josh Poimboeuf <[email protected]>
[jstultz: reworked Kconfig settings to avoid defconfig noise]

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                          | 142 +++++++++++++++++++++++-
 kernel/time/timekeeping.c                       |  54 +++++++--
 lib/Kconfig.debug                               |  65 ++++++++++-
 5 files changed, 249 insertions(+), 19 deletions(-)
Signature · 1 line
1.8.5.5
#1 lore raw

PATCH v9 1/2 time: Make fast functions return 0 before timekeeping is initialized

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.

---
 kernel/time/timekeeping.c | 47 +++++++++++++++++++++++++++++++++--------------
 1 file changed, 33 insertions(+), 14 deletions(-)
kernel/time/timekeeping.c +33 -14
index cedafa008de5..d111039e0245 100644
@@ -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.
Signature · 1 line
1.8.5.5
#2 lore raw

PATCH v9 2/2 printk: Add monotonic, boottime, and realtime timestamps

In reply to 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 is read without the protection of a sequence lock when printk_get_ts() is set to __ktime_get_real_fast_ns_unsafe().

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.

v8: Add CONFIG_PRINTK_TIME_DEBUG to allow timestamp runtime switching. Rename PRINTK_TIME_DISABLE to PRINTK_TIME_DISABLED. Rename printk_set_timestamp() to printk_set_ts_func(). Separate printk_set_ts_func() and printk_get_first_ts() portions. Rename param functions. Adjust configs, enum, and timestamp_sources_str to be 0-4. Add mention realtime clock is UTC in Documentation.

v9: Fix typo. Add __ktime_get_real_fast_ns_unsafe().

Cc Mark Salyzyn <[email protected]>
Cc Jonathan Corbet <[email protected]>
Cc Petr Mladek <[email protected]>
Cc Sergey Senozhatsky <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc John Stultz <[email protected]>
Cc Thomas Gleixner <[email protected]>
Cc Stephen Boyd <[email protected]>
Cc Andrew Morton <[email protected]>
Cc Greg Kroah-Hartman <[email protected]>
Cc "Paul E. McKenney" <[email protected]>
Cc Christoffer Dall <[email protected]>
Cc Deepa Dinamani <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Joel Fernandes <[email protected]>
Cc Prarit Bhargava <[email protected]>
Cc Kees Cook <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc Geert Uytterhoeven <[email protected]>
Cc "Luis R. Rodriguez" <[email protected]>
Cc Nicholas Piggin <[email protected]>
Cc "Jason A. Donenfeld" <[email protected]>
Cc Olof Johansson <[email protected]>
Cc Josh Poimboeuf <[email protected]>
[jstultz: reworked Kconfig settings to avoid defconfig noise]
---
 Documentation/admin-guide/kernel-parameters.txt |   6 +-
 include/linux/timekeeping.h                     |   1 +
 kernel/printk/printk.c                          | 142 +++++++++++++++++++++++-
 kernel/time/timekeeping.c                       |  13 +++
 lib/Kconfig.debug                               |  65 ++++++++++-
 5 files changed, 219 insertions(+), 8 deletions(-)
Documentation/admin-guide/kernel-parameters.txt +4 -2
index d9c171ce4190..8d6b194533af 100644
@@ -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 (in UTC))
 
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
include/linux/timekeeping.h +1 -0
index ddc229ff6d1e..7ef0b0da0e74 100644
@@ -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_fast_ns_unsafe(void);
 
 /*
  * Timespec interfaces utilizing the ktime based ones
kernel/printk/printk.c +137 -5

183 lines not on this page · raw message

kernel/time/timekeeping.c +13 -0
index d111039e0245..9463606951b1 100644
@@ -509,6 +509,19 @@ u64 notrace ktime_get_boot_fast_ns(void)
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
 /**
+ * __ktime_get_real_fast_ns_unsafe: - Return an unsafe realtime value
+ * On 32-bit systems may lead to unlikely situations where the result is wrong
+ * because the real time offset is read without the protection of a sequence
+ * lock.
+ */
+u64 __ktime_get_real_fast_ns_unsafe(void)
+{
+	struct timekeeper *tk = &tk_core.timekeeper;
+
+	return (ktime_get_mono_fast_ns() + ktime_to_ns(tk->offs_real));
+}
+
+/**
  * halt_fast_timekeeper - Prevent fast timekeeper from accessing clocksource.
  * @tk: Timekeeper to snapshot.
  *
lib/Kconfig.debug +64 -1

82 lines not on this page · raw message

Signature · 1 line
1.8.5.5
#3 lore raw

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

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

Quoted 6 lines · Prarit Bhargava
kernel/printk/printk.c +6 -0
+
+	if (printk_time_source == PRINTK_TIME_UNDEFINED)
+		printk_time_source = _printk_time;
+#ifndef CONFIG_PRINTK_TIME_DEBUG
+	else if ((printk_time_source != _printk_time) &&
+		 (_printk_time != PRINTK_TIME_DISABLED)) {

You can avoid the #ifdef ugliness by writing this as:

    } else if (IS_ENABLED(CONFIG_PRINTK_DEBUG) &&
    	       printk_time_source != _prinkt_time &&
	       _printk_time != PRINTK_TIME_DISABLED) {

Aside of that I'm not too fond of that extra config switch. Why shouldn't we allow the admin to switch between time sources as he sees fit by default? It's not Joe user who is allowed to do that and in general we give admins the biggest guns we have to shoot themself in the foot.

Seriously, switching it is not making anything explode, insecure or whatever dangerous. It's merily changing the time stamp source so dmesg and syslog get harder to parse.

Thanks,

tglx