From patchwork Thu Aug 17 04:46:46 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: John Stultz X-Patchwork-Id: 110295 Delivered-To: patches@linaro.org Received: by 10.140.95.78 with SMTP id h72csp1685675qge; Wed, 16 Aug 2017 21:46:53 -0700 (PDT) X-Received: by 10.84.229.13 with SMTP id b13mr4328793plk.352.1502945213179; Wed, 16 Aug 2017 21:46:53 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1502945213; cv=none; d=google.com; s=arc-20160816; b=lAPd1qyGFkH0Q2NzWJf81+6oGHv0OIpsuP3i/aP6cc37B8zRFnFVTGWN2qzWvrNqNu ZX2Kyn1Vcic2svUSbUOvA473MyeANHBtdudZvv2EqGqzMrFBr0M8RQBbIi7RC91DUU2E R6pDSIKXCYRzJttzzrFi2dADW9Cq0xtdhJEu13gUPvFBURq5+tv84rYK7aKib/Of9Dj4 NAktCZbCdItNVtcJkSzwP5dF01LhMI7m+3Sqm5Rqj4okl7noXaBn2h6CsoAUVd9jBYwb Pb0W9C0rDv35iqIvOL0yArAWJw7gqWgUNq+jCLJqZhqFcrfMlQSGsYEHRIYrsZTMX6ua TjMg== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=references:in-reply-to:message-id:date:subject:cc:to:from :dkim-signature:arc-authentication-results; bh=3WgI4iHT/Qv2FU3rY8RZz0ARXwsHaI5/Yfm8pvbb5Os=; b=XjwV3MkuBPZkUugKe7hZBmJO6ClAM/hcNy7L8pfcwXohcE18FyMmdCl37KcQgTuhAT kXPvM+uvtW+g1Y+ekYz7+JhHqKGrgKowgF9ctaxm472n9j8PdARKXpb3XiZVWLM2tBDw B9M//TXZd6MlDFhw7YKwu/y1WM4RQfMhparOpE0+4c6bnxSACmwDIgR0T2y/cKr1R6g/ 9LP0+MImPgK/f/ylqurdunZ9m+X76JvOtY2rm/wIwrzFYNNkvzCN5IPKgJnV9YvNtkFQ Lf/KN1O3TfWmzoFxhi3ACtRA3z46xpYbIRsu/EOGRm9WZ3ak31L4XZiD/eRIrWpFRtQb cWxw== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@linaro.org header.s=google header.b=Xr8GHcCP; spf=pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c05::233 as permitted sender) smtp.mailfrom=john.stultz@linaro.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linaro.org Return-Path: Received: from mail-pg0-x233.google.com (mail-pg0-x233.google.com. [2607:f8b0:400e:c05::233]) by mx.google.com with ESMTPS id i4si1549200pfc.426.2017.08.16.21.46.53 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 16 Aug 2017 21:46:53 -0700 (PDT) Received-SPF: pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c05::233 as permitted sender) client-ip=2607:f8b0:400e:c05::233; Authentication-Results: mx.google.com; dkim=pass header.i=@linaro.org header.s=google header.b=Xr8GHcCP; spf=pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c05::233 as permitted sender) smtp.mailfrom=john.stultz@linaro.org; dmarc=pass (p=NONE sp=NONE dis=NONE) header.from=linaro.org Received: by mail-pg0-x233.google.com with SMTP id y129so34786585pgy.4 for ; Wed, 16 Aug 2017 21:46:53 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references; bh=3WgI4iHT/Qv2FU3rY8RZz0ARXwsHaI5/Yfm8pvbb5Os=; b=Xr8GHcCP8v4XX1JOXuu3xdlhdAzJ0lI2VhCMGgg9/5tDXgFJlpgO9saCU0yxIVJQpn bRuVKL7AzGVXhQjaGlVuzxVXb8EEs66rXZifG43+muV/pAqqZS1DwdMHOfspEfPopgv3 CInz2AN6p8x5qiiflOLuOHRxYj0hMBfW51a1c= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=3WgI4iHT/Qv2FU3rY8RZz0ARXwsHaI5/Yfm8pvbb5Os=; b=fub/z9B8jXDiYBj8jDnZMpio/Ns1zkr3ZdMEAqL6PJ013pDUnuY+HmtkQgQnkx9fKQ SI69+De/ipa7mE8RTIH1b/B8+2lpn5HI1HeEKZd/m4tM0Fo2oq6npQhHXr7p+3QFUBZZ OaTTLPKGTejSroAgM5FEjNiggYyqmvdpZ1r2KNgenAKYDsvZtGX/AvXn/3CemkQs0/gl G8LbS2qzTh5ScZUTZT2LZCXqaESej5pCB//mk5D0GYQl0tjWiRLTYqtJiZaqkRAoRcix zUG8OEdg0kwWhHLX+vNJ/uMaQvpMs17pUlquy7IlGr8H679G3kxMK+hIDrgLXMe2ToUw qF7w== X-Gm-Message-State: AHYfb5hmmjVgREjYOZZkGMswuhJaHo2auxnzT2/KaBFoXSTxGGFFIP4B JZs3ga5AQ97aHP5QE0k= X-Received: by 10.84.176.131 with SMTP id v3mr4509705plb.142.1502945212704; Wed, 16 Aug 2017 21:46:52 -0700 (PDT) Return-Path: Received: from localhost.localdomain ([2601:1c2:1002:83f0:4e72:b9ff:fe99:466a]) by smtp.gmail.com with ESMTPSA id y8sm4488466pfi.159.2017.08.16.21.46.50 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 16 Aug 2017 21:46:51 -0700 (PDT) From: John Stultz To: Prarit Bhargava Cc: Mark Salyzyn , Jonathan Corbet , Petr Mladek , Sergey Senozhatsky , Steven Rostedt , John Stultz , Thomas Gleixner , Stephen Boyd , Andrew Morton , Greg Kroah-Hartman , "Paul E. McKenney" , Christoffer Dall , Deepa Dinamani , Ingo Molnar , Joel Fernandes , Kees Cook , Peter Zijlstra , Geert Uytterhoeven , "Luis R. Rodriguez" , Nicholas Piggin , "Jason A. Donenfeld" , Olof Johansson , Josh Poimboeuf , linux-doc@vger.kernel.org Subject: [PATCH] printk: Add monotonic, boottime, and realtime timestamps Date: Wed, 16 Aug 2017 21:46:46 -0700 Message-Id: <1502945206-18161-1-git-send-email-john.stultz@linaro.org> X-Mailer: git-send-email 2.7.4 In-Reply-To: References: From: Prarit Bhargava Prarit, So I took my own shot at cleaning up the Kconfig settings to make it a bit more sane in my opinion. This should allow the legacy defconfigs to just work, and avoids all the defconfig churn in the patch. I almost went through to try to simplify the code and make PRINTK_TIME_DISABLE = 0 and to get rid of PRINTK_TIME_UNDEFINED, as that seems like extra complexity that could probably be done simpler, but I didn't quite have the time to get my head around it all, so I left it be. But you might want to see if it can't be further simplified (ie: initialize it to CONFIG_PRINTK_TIME_VAL and then override it by the boot parameter if specified). Anwyay, let me know what you think, and feel free to adopt this along with any other changes you have planned. thanks -john 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. 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 | 147 +++++++++++++++++++++++- kernel/time/timekeeping.c | 5 + lib/Kconfig.debug | 54 ++++++++- 5 files changed, 205 insertions(+), 8 deletions(-) -- 2.7.4 Signed-off-by: John Stultz diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index d9c171c..1ba277e 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) processor.max_cstate= [HW,ACPI] Limit processor to maximum C-state diff --git a/include/linux/timekeeping.h b/include/linux/timekeeping.h index ddc229f..80ca2fa 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 fc47863..fe208dc 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,141 @@ 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_VAL; +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: + 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; + } + + /* + * Only allow enabling and disabling of the current printk_time + * setting. Changing it from one setting to another confuses + * userspace. + */ + if (printk_time_source == PRINTK_TIME_UNDEFINED) + printk_time_source = _printk_time; + else if ((printk_time_source != _printk_time) && + (_printk_time != PRINTK_TIME_DISABLE)) { + pr_warn("printk: timestamp can only be set to 0, disabled, or %s\n", + timestamp_sources_str[printk_time_source]); + return -EINVAL; + } + + 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 +1773,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 +2003,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 +2792,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 2cb31ff..77d140e 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 98fe715..83683e9ad 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -8,12 +8,64 @@ 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" + default PRINTK_TIME_LOCAL if PRINTK_TIME + default PRINTK_TIME_DISABLE 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_DISABLE + bool "Disabled" if !PRINTK_TIME + help + Selecting this option disables the time stamps of printk(). + +config PRINTK_TIME_LOCAL + bool "Local Clock" if PRINTK_TIME + 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" if PRINTK_TIME + 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" if PRINTK_TIME + 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" if PRINTK_TIME + 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_DISABLE + 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)"