From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751869AbdHGROR (ORCPT ); Mon, 7 Aug 2017 13:14:17 -0400 Received: from mx2.suse.de ([195.135.220.15]:58653 "EHLO mx1.suse.de" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1751426AbdHGROP (ORCPT ); Mon, 7 Aug 2017 13:14:15 -0400 Date: Mon, 7 Aug 2017 19:14:12 +0200 From: "Luis R. Rodriguez" To: Prarit Bhargava Cc: linux-kernel@vger.kernel.org, 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: Re: [PATCH v3] printk: Add boottime and real timestamps Message-ID: <20170807171412.GK27873@wotan.suse.de> References: <1501809524-496-1-git-send-email-prarit@redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1501809524-496-1-git-send-email-prarit@redhat.com> User-Agent: Mutt/1.6.0 (2016-04-01) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu, Aug 03, 2017 at 09:18:44PM -0400, Prarit Bhargava wrote: > index fc47863f629c..8f093dd0a733 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1202,8 +1204,119 @@ 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; > +static int printk_time_setting; > + > +/** > + * enum printk_time_type - Timestamp types for printk() messages. > + * @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 in the call to ktime_get_log_ts() > + * in printk_get_ts() below. You can expand on this or the actual routines that use this in kdoc form. > + */ > +enum printk_time_type { > + PRINTK_TIME_DISABLE = 0, > + PRINTK_TIME_LOCAL = 1, > + PRINTK_TIME_BOOT = 2, > + PRINTK_TIME_MONO = 3, > + PRINTK_TIME_REAL = 4, > +}; > + > +static const char * const printk_time_str[5] = { > + "disabled", > + "local hardware", > + "boottime", > + "monotonic", > + "realtime", > +}; > + > +static int printk_time_set(const char *val, const struct kernel_param *kp) > +{ > + char *param = strstrip((char *)val); > + int _printk_time; > + > + if (strlen(param) != 1) > + return -EINVAL; > + > + switch (param[0]) { > + case '0': > + case 'n': > + case 'N': > + _printk_time = PRINTK_TIME_DISABLE; > + break; > + case '1': > + case 'y': > + case 'Y': > + _printk_time = PRINTK_TIME_LOCAL; > + break; > + case '2': > + _printk_time = PRINTK_TIME_BOOT; > + break; > + case '3': > + _printk_time = PRINTK_TIME_MONO; > + break; > + case '4': > + _printk_time = PRINTK_TIME_REAL; > + break; > + default: > + pr_warn("printk: invalid timestamp value\n"); > + 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_setting == PRINTK_TIME_DISABLE) { > + printk_time_setting = _printk_time; > + } else if ((printk_time_setting != _printk_time) && > + (_printk_time != 0)) { > + pr_warn("printk: timestamp can only be set to 0(disabled) or %d(%s) ", > + printk_time_setting, > + printk_time_str[printk_time_setting]); > + return -EINVAL; > + } > + > + printk_time = _printk_time; > + pr_info("printk: timestamp set to %d(%s).", > + printk_time, printk_time_str[printk_time]); > + return 0; > +} > + > +static int printk_time_get(char *buffer, const struct kernel_param *kp) > +{ > + return scnprintf(buffer, PAGE_SIZE, "%d", 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 u64 printk_get_ts(void) > +{ > + u64 mono, offset_real; > + > + if (printk_time <= PRINTK_TIME_LOCAL) > + return local_clock(); > + > + if (printk_time == PRINTK_TIME_BOOT) > + return ktime_get_boot_log_ts(); > + > + mono = ktime_get_real_log_ts(&offset_real); > + > + if (printk_time == PRINTK_TIME_MONO) > + return mono; > + > + return mono + offset_real; > +} > > static size_t print_time(u64 ts, char *buf) > { > @@ -1643,7 +1756,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 +1986,8 @@ 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; } > > +static int printk_time; > +static int printk_time_setting; > #endif /* CONFIG_PRINTK */ > > #ifdef CONFIG_EARLY_PRINTK > > @@ -2659,6 +2774,10 @@ static int __init printk_late_init(void) > struct console *con; > int ret; > > + /* initialize printk_time settings */ > + if (printk_time_setting == 0) > + printk_time_setting = printk_time; > + Note printk_late_init() is a late_initcall(). This means if the printk_time_setting was disabled it will take a while to enable it. Enabling it is done at the device_initcall(), so if printk setting is disabled but a user enables it with a toggle of the module param there is a period of time during which time resolution would be different. Perhaps for some this is not useful information but for others I think this would be very valuable. There is also something to say about the time in between initializing access to ktime_get_mono_fast_ns(), how early is this reliable? All these things could be mentioned on the documentation. Luis