Message-ID: <6b265b2b-130a-c19b-1f68-b12895e1c17e@android.com>
Date:   Thu, 17 Aug 2017 08:30:05 -0700
From:   Mark Salyzyn <salyzyn@...roid.com>
To:     Prarit Bhargava <prarit@...hat.com>, linux-kernel@...r.kernel.org
Cc:     Jonathan Corbet <corbet@....net>, Petr Mladek <pmladek@...e.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        John Stultz <john.stultz@...aro.org>,
        Thomas Gleixner <tglx@...utronix.de>,
        Stephen Boyd <sboyd@...eaurora.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
        Christoffer Dall <cdall@...aro.org>,
        Deepa Dinamani <deepa.kernel@...il.com>,
        Ingo Molnar <mingo@...nel.org>,
        Joel Fernandes <joelaf@...gle.com>,
        Kees Cook <keescook@...omium.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Geert Uytterhoeven <geert+renesas@...der.be>,
        "Luis R. Rodriguez" <mcgrof@...nel.org>,
        Nicholas Piggin <npiggin@...il.com>,
        "Jason A. Donenfeld" <Jason@...c4.com>,
        Olof Johansson <olof@...om.net>,
        Josh Poimboeuf <jpoimboe@...hat.com>, linux-doc@...r.kernel.org
Subject: Re: [PATCH 2/2 v7] printk: Add monotonic, boottime, and realtime
 timestamps

On 08/17/2017 06:15 AM, Prarit Bhargava wrote:
> 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.
Congrats, greatly eases merges into older kernels, and has eliminated 
the churn this could place on all the configured systems out there.

Sadly, one of my suggestions did not quite go the way I expected ;-} 
easy to correct, and fix (I missed a spot in my original suggestion, as 
code changed underfoot over the set ;-/). (see bottom)

<discussion type="maybe out of the scope for this patch">

I am not convinced that user space is entirely at a disadvantage with 
this 'feature' enabled. Before interpreting it can read 
/sys/module/printk/parameters/time, then sniff for the flowing content 
for time breaks (watch for printk: timestamp set to <string>). Of 
course, the value in 'time' is current, so it would be _wrong_ during 
flow of previous content until the first time break shows up if it 
really was being switched that often.

(echo local ; echo disabled ; echo boottime ; echo monotonic ; echo 
realtime ; echo local ) > /sys/module/printk/parameters/time

[  473.589169] printk: timestamp set to local
printk: timestamp set to disabled
[  473.545384] printk: timestamp set to boottime
[  473.549924] printk: timestamp set to monotonic
[1502957708.055265] printk: timestamp set to realtime
[  473.612024] printk: timestamp set to local

A 'fix' would be to add a letter after the timestamp if not local. For 
example:

[  473.589169] printk: timestamp set to local
printk: timestamp set to disabled
[  473.545384b] printk: timestamp set to boottime
[  473.549924m] printk: timestamp set to monotonic
[1502957708.055265U] printk: timestamp set to realtime
[  473.612024] printk: timestamp set to local

(I used U instead of r, because it is actually UTC, and did not add 'l' 
because it is a long standing default)

But there would be concern over a change in time format API, so maybe it 
should be relegated to a CONFIG_PRINTK_TIME_DEBUG 'feature' only to add 
the timebase letters?

</discussion>

. . .

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 8817ed5ee6a3..2e3321f6604b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1273,7 +1273,7 @@ static int printk_time_set(const char *val, const 
struct kernel_param *kp)

         if (printk_time_source == PRINTK_TIME_UNDEFINED)
                 printk_time_source = _printk_time;
-#ifndef PRINTK_TIME_DEBUG
+#ifndef CONFIG_PRINTK_TIME_DEBUG
         else if ((printk_time_source != _printk_time) &&
                  (_printk_time != PRINTK_TIME_DISABLE)) {
                 /*

@@ -1288,7 +1288,9 @@ static int printk_time_set(const char *val, const 
struct kernel_param *kp)
  #endif

         printk_time = _printk_time;
+#ifndef CONFIG_PRINTK_TIME_DEBUG
         if (printk_time_source > PRINTK_TIME_DISABLE)
+#endif
                 printk_set_timestamp();

         pr_info("printk: timestamp set to %s\n",

> +
> +config PRINTK_TIME_TYPE
> +	int
> +	depends on PRINTK
> +	range 1 5
> +	default 1 if !PRINTK_TIME
> +	default 2 if PRINTK_TIME_LOCAL
> +	default 3 if PRINTK_TIME_BOOT
> +	default 4 if PRINTK_TIME_MONO
> +	default 5 if PRINTK_TIME_REAL
> +
>   
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 1fb23d851ca2..2517ed69d7f8 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -60,6 +60,22 @@ config PRINTK_TIME_TYPE
      default 4 if PRINTK_TIME_MONO
      default 5 if PRINTK_TIME_REAL

+config PRINTK_TIME_DEBUG
+    bool "Allow runtime reselection of any timebase on printks"
+    depends on PRINTK
+    help
+      Selecting this option causes time stamps of the printk()
+      messages to be changed freely at runtime on the output of
+      the syslog() system call and at the console. Without this
+      option, one can only enable or disable the configuration
+      selected timebase.
+
+      Runtime adjustment can be set via
+      /sys/module/printk/paramters/time as follows with a string:
+      0/N/n/disable, 1/Y/y/local, b/boot, m/monotonic, r/realtime.
+      eg: echo local >/sys/module/printk/parameters/time
+          echo realtime >/sys/module/printk/parameters/time
+
  config MESSAGE_LOGLEVEL_DEFAULT
      int "Default message log level (1-15)"
      range 1 15

The last bit should probably be adjusted to eliminate details, maybe 
keep the example as it will stand the test of time, and merely reference 
the Documentation tree w.r.t. printk.time=

Powered by blists - more mailing lists