Re: [PATCH 2/2 v10] printk: Add monotonic, boottime, and realtime timestamps
On Mon, 28 Aug 2017, Prarit Bhargava wrote: > diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c > index d111039e0245..9463606951b1 100644 > --- a/kernel/time/timekeeping.c > +++ b/kernel/time/timekeeping.c > @@ -509,6 +509,19 @@ u64 notrace ktime_get_boot_fast_ns(void) > EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns); Why is this still in the middle of the printk hodgepodge? > /** > + * __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)); > +} And no, this function is just horrible, both in name and implementation. This can be done without that unprotected and racy access to the realtime offset. Patch below. Thanks, tglx 8<--- Subject: timekeeping: Provide NMI safe access to clock realtime From: Thomas Gleixner Date: Thu, 31 Aug 2017 17:12:48 +0200 The configurable printk timestamping wants access to clock realtime. Right now there is no ktime_get_real_fast_ns() accessor because reading the monotonic base and the realtime offset cannot be done atomically. Contrary to boot time this offset can change during runtime and cause half updated readouts. struct tk_read_base was fully packed when the fast timekeeper access was implemented. commit ceea5e3771ed ("time: Fix clock->read(clock) race around clocksource changes") removed the 'read' function pointer from the structure, but of course left the comment stale. So now the structure can fit a new 64bit member w/o violating the cache line constraints. Add real_base to tk_read_base and update it in the fast timekeeper update sequence. Implement an accessor which follows the same scheme as the accessor to clock monotonic, but uses the new real_base to access clock real time. The runtime overhead for updating real_base is minimal as it just adds two cache hot values and stores into the same an already dirtied cache line. Signed-off-by: Thomas Gleixner --- include/linux/timekeeper_internal.h |6 +- include/linux/timekeeping.h |1 + kernel/time/timekeeping.c | 35 +++ 3 files changed, 41 insertions(+), 1 deletion(-) --- a/include/linux/timekeeper_internal.h +++ b/include/linux/timekeeper_internal.h @@ -13,19 +13,22 @@ /** * struct tk_read_base - base structure for timekeeping readout * @clock: Current clocksource used for timekeeping. - * @read: Read function of @clock * @mask: Bitmask for two's complement subtraction of non 64bit clocks * @cycle_last: @clock cycle value at last update * @mult: (NTP adjusted) multiplier for scaled math conversion * @shift: Shift value for scaled math conversion * @xtime_nsec: Shifted (fractional) nano seconds offset for readout * @base: ktime_t (nanoseconds) base time for readout + * @base_real: Nanoseconds base value for clock REALTIME readout * * This struct has size 56 byte on 64 bit. Together with a seqcount it * occupies a single 64byte cache line. * * The struct is separate from struct timekeeper as it is also used * for a fast NMI safe accessors. + * + * @base_real is for the fast NMI safe accessor to allow reading clock + * realtime from any context. */ struct tk_read_base { struct clocksource *clock; @@ -35,6 +38,7 @@ struct tk_read_base { u32 shift; u64 xtime_nsec; ktime_t base; + u64 base_real; }; /** --- 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_fast_ns(void); /* * Timespec interfaces utilizing the ktime based ones --- a/kernel/time/timekeeping.c +++ b/kernel/time/timekeeping.c @@ -496,6 +496,39 @@ u64 notrace ktime_get_boot_fast_ns(void) } EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns); + +/* + * See comment for __ktime_get_fast_ns() vs. timestamp ordering + */ +static __always_inline u64 __ktime_get_real_fast_ns(struct tk_fast *tkf) +{ + struct tk_read_base *tkr; + unsigned int seq; + u64 now; + + do { + seq = raw_read_seqcount_latch(&tkf->seq); + tkr = tkf->base + (seq & 0x01); + now = ktime_to_ns(tkr->base_real); + + now += timekeeping_delta_to_ns(tkr, + clocksource_delta( + tk_clock_read(tkr), + tkr->cycle_last, +
[PATCH 2/2 v10] printk: Add monotonic, boottime, and realtime 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. 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(). v10: Remove time parameter restrictions. Signed-off-by: Prarit Bhargava Cc: Mark Salyzyn Cc: Jonathan Corbet Cc: Petr Mladek Cc: Sergey Senozhatsky Cc: Steven Rostedt Cc: John Stultz Cc: Thomas Gleixner Cc: Stephen Boyd Cc: Andrew Morton Cc: Greg Kroah-Hartman Cc: "Paul E. McKenney" Cc: Christoffer Dall Cc: Deepa Dinamani Cc: Ingo Molnar Cc: Joel Fernandes Cc: Prarit Bhargava Cc: Kees Cook Cc: Peter Zijlstra Cc: Geert Uytterhoeven Cc: "Luis R. Rodriguez" Cc: Nicholas Piggin Cc: "Jason A. Donenfeld" Cc: Olof Johansson Cc: Josh Poimboeuf Cc: linux-doc@vger.kernel.org [jstultz: reworked Kconfig settings to avoid defconfig noise] Signed-off-by: John Stultz --- Documentation/admin-guide/kernel-parameters.txt | 6 +- include/linux/timekeeping.h | 1 + kernel/printk/printk.c | 116 +++- kernel/time/timekeeping.c | 13 +++ lib/Kconfig.debug | 48 +- 5 files changed, 176 insertions(+), 8 deletions(-) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index d9c171ce4190..8d6b194533af 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: (1/Y/y=enable, 0/N/n=disable) + printk.time=Show timestamp prefixed to each printk message line + Format: + (0/N/n/disable, 1/Y/y/local, +b/boot, m/monotonic, r/realtime (in UTC)) 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..7ef0b0da0e74 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_fast_ns_unsafe(void); /* * Timespec interfaces utilizing the ktime based ones diff --git a/kernel/printk/