On 09/26/2017 04:42 AM, tip-bot for Prarit Bhargava wrote: > Commit-ID: 310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > Gitweb: http://git.kernel.org/tip/310b454a8653ea60d3eb21ce5ab03a282a32fbe1 > Author: Prarit Bhargava <[email protected]> > AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400 > Committer: Thomas Gleixner <[email protected]> > CommitDate: Tue, 26 Sep 2017 10:38:07 +0200 > > 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. > > Make printk output different timestamps by adding options for no timestamp, > the local hardware clock, monotonic clock, boottime clock, and clock > realtime. The default clock can be selected via: > > - Kconfig > - Kernel command line parameter > - Sysfs file > > Note, that existing user space tools might be confused by selecting clock > realtime, so handle with care.
pmladek found a compile warning due to printk_time being unused. I will post a v14 on LKML shortly. P. > > [jstultz: Reworked Kconfig settings to avoid defconfig noise] > > Signed-off-by: Prarit Bhargava <[email protected]> > Signed-off-by: Thomas Gleixner <[email protected]> > Cc: Joel Fernandes <[email protected]> > Cc: Geert Uytterhoeven <[email protected]> > Cc: [email protected] > Cc: Peter Zijlstra <[email protected]> > Cc: Deepa Dinamani <[email protected]> > Cc: Christoffer Dall <[email protected]> > Cc: "Jason A. Donenfeld" <[email protected]> > Cc: Jonathan Corbet <[email protected]> > Cc: "Paul E. McKenney" <[email protected]> > Cc: Petr Mladek <[email protected]> > Cc: Kees Cook <[email protected]> > Cc: Steven Rostedt <[email protected]> > Cc: Nicholas Piggin <[email protected]> > Cc: Josh Poimboeuf <[email protected]> > Cc: Greg Kroah-Hartman <[email protected]> > Cc: Stephen Boyd <[email protected]> > Cc: Mark Salyzyn <[email protected]> > Cc: Sergey Senozhatsky <[email protected]> > Cc: "Luis R. Rodriguez" <[email protected]> > Cc: Olof Johansson <[email protected]> > Cc: Andrew Morton <[email protected]> > Link: > https://lkml.kernel.org/r/[email protected] > > --- > Documentation/admin-guide/kernel-parameters.txt | 6 +- > kernel/printk/printk.c | 130 > +++++++++++++++++++++++- > lib/Kconfig.debug | 48 ++++++++- > 3 files changed, 176 insertions(+), 8 deletions(-) > > diff --git a/Documentation/admin-guide/kernel-parameters.txt > b/Documentation/admin-guide/kernel-parameters.txt > index 0549662..9a84483 100644 > --- a/Documentation/admin-guide/kernel-parameters.txt > +++ b/Documentation/admin-guide/kernel-parameters.txt > @@ -3211,8 +3211,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 > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 512f7c2..5e0bf2e 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_get_first_ts(void); > +static u64 (*printk_get_ts)(void) = printk_get_first_ts; > + > /* 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; > > @@ -1201,14 +1204,130 @@ 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); > +/** > + * enum timestamp_sources - Timestamp sources for printk() messages. > + * @PRINTK_TIME_DISABLED: 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. > + */ > +enum timestamp_sources { > + PRINTK_TIME_DISABLED = 0, > + PRINTK_TIME_LOCAL = 1, > + PRINTK_TIME_BOOT = 2, > + PRINTK_TIME_MONO = 3, > + PRINTK_TIME_REAL = 4, > +}; > + > +static const char * const timestamp_sources_str[5] = { > + "disabled", > + "local", > + "boottime", > + "monotonic", > + "realtime", > +}; > + > +static int printk_time = CONFIG_PRINTK_TIME_TYPE; > + > +static int printk_set_ts_source(enum timestamp_sources ts_source) > +{ > + int err = 0; > + > + switch (ts_source) { > + case PRINTK_TIME_LOCAL: > + 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 = ktime_get_real_fast_ns; > + break; > + case PRINTK_TIME_DISABLED: > + /* > + * The timestamp is always stored into the log buffer. > + * Keep the current one. > + */ > + break; > + default: > + err = -EINVAL; > + break; > + } > + > + if (!err) > + printk_time = ts_source; > + return err; > +} > + > +static u64 printk_get_first_ts(void) > +{ > + printk_set_ts_source(printk_time); > + > + /* Fallback for invalid or disabled timestamp source */ > + if (printk_get_ts == printk_get_first_ts) > + printk_get_ts = local_clock; > + > + return printk_get_ts(); > +} > + > +static int param_set_time(const char *val, const struct kernel_param *kp) > +{ > + char *param = strstrip((char *)val); > + int time_source = -1; > + int ts; > + int err; > + > + if (strlen(param) == 1) { > + /* Preserve legacy boolean settings */ > + if ((param[0] == '0') || (param[0] == 'n') || > + (param[0] == 'N')) > + time_source = PRINTK_TIME_DISABLED; > + if ((param[0] == '1') || (param[0] == 'y') || > + (param[0] == 'Y')) > + time_source = PRINTK_TIME_LOCAL; > + } > + if (time_source == -1) { > + for (ts = 0; ts < ARRAY_SIZE(timestamp_sources_str); ts++) { > + if (!strncmp(timestamp_sources_str[ts], param, > + strlen(param))) { > + time_source = ts; > + break; > + } > + } > + } > + > + err = printk_set_ts_source(time_source); > + if (err) { > + pr_warn("printk: invalid timestamp option %s\n", param); > + return err; > + } > + > + pr_info("printk: timestamp set to %s\n", > + timestamp_sources_str[printk_time]); > + return 0; > +} > + > +static int param_get_time(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 = param_set_time, > + .get = param_get_time, > +}; > +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_DISABLED) > return 0; > > rem_nsec = do_div(ts, 1000000000); > @@ -1631,7 +1750,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; > } > > @@ -1861,6 +1980,7 @@ 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; > #endif /* CONFIG_PRINTK */ > > #ifdef CONFIG_EARLY_PRINTK > diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug > index 2689b7c..c6401d3 100644 > --- a/lib/Kconfig.debug > +++ b/lib/Kconfig.debug > @@ -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 "Boot Time Clock" > + help > + Selecting this option causes the time stamps of printk() to be > + stamped with the adjusted boottime clock. > + > +config PRINTK_TIME_MONO > + bool "Monotonic Clock" > + help > + Selecting this option causes the time stamps of printk() to be > + stamped with the adjusted monotonic clock. > + > +config PRINTK_TIME_REAL > + bool "Real Time Clock" > + help > + Selecting this option causes the time stamps of printk() to be > + stamped with the adjusted realtime clock (UTC). > +endchoice > + > +config PRINTK_TIME_TYPE > + int > + depends on PRINTK > + range 0 4 > + default 0 if !PRINTK_TIME > + default 1 if PRINTK_TIME_LOCAL > + default 2 if PRINTK_TIME_BOOT > + default 3 if PRINTK_TIME_MONO > + default 4 if PRINTK_TIME_REAL > + > > config CONSOLE_LOGLEVEL_DEFAULT > int "Default console loglevel (1-15)" >
