Date:   Thu, 20 Jul 2017 11:24:22 -0700
From:   Mark Salyzyn <salyzyn@...roid.com>
To:     linux-kernel@...r.kernel.org
Cc:     pavel@....cz, andriy.shevchenko@...ux.intel.com, joe@...ches.com,
        prarit@...hat.com, rjw@...ysocki.net, tglx@...utronix.de,
        Mark Salyzyn <salyzyn@...roid.com>,
        Petr Mladek <pmladek@...e.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Steven Rostedt <rostedt@...dmis.org>,
        Kees Cook <keescook@...omium.org>,
        Anton Vorontsov <anton@...msg.org>,
        Colin Cross <ccross@...roid.com>,
        Tony Luck <tony.luck@...el.com>,
        Andrew Morton <akpm@...ux-foundation.org>,
        "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
        Ingo Molnar <mingo@...nel.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Geert Uytterhoeven <geert@...ux-m68k.org>,
        Mark Salyzyn <salyzyn@...gle.com>,
        "Luis R. Rodriguez" <mcgrof@...nel.org>,
        Nicholas Piggin <npiggin@...il.com>,
        Olof Johansson <olof@...om.net>,
        "Jason A. Donenfeld" <Jason@...c4.com>,
        Josh Poimboeuf <jpoimboe@...hat.com>
Subject: [PATCH v5] printk: Add pr_info_show_time

Primary purpose of pr_info_show_time() is to provide a marker used for
post-mortem Battery and Power analysis.  These markers are to be
placed at major discontinuities of time and power level.  An optional
timestamp is added to aid the post-mortem or delayed analysis.  This
function is to be called at a level where the associated timekeeping
is active and available.  pr_info_show_time() is functionally the same
as pr_info(), except for the ability to add an alternate time prefix
to the message.

For example, the persistent clock that is used to report
"Suspended for" message, although very useful, is not present on all
platforms.  It is currently standardized for millisecond precision.
Thus pr_info_show_time would be used at a higher level to aid power
analysis.

An added value to the time report is the ability in post-mortem
triage analysis to synchronize kernel logging activities in MONOTONIC
time with user space logging activities in REALTIME or BOOTTIME.

Feature activated by CONFIG_PR_INFO_SHOW_TIME_<TYPE>, where <TYPE> is:

MONOTONIC - default, disabled time prefix because dmesg logs already
            are reported in monotonic.
REALTIME - Add a [<epoch>.<nanoseconds>U] prefix to the message to
           report getnstimeofday64() collected timestamp.
BOOTTIME - Add a [<seconds>.<nanoseconds>B] prefix to the message to
           report getboottime64() collected timestamp.

Since this is for post mortem field analysis, there is no debugfs or
trace facility that can generally be leveraged.  For example
analyze_suspend.py requires a debug configured kernel, on the other
hand these pr_info_show_time prints can remain in a field product.
The purpose for pr_info_show_time is not necessarily for development
debugging.

Data collected may be recorded by klogd with a longer logspan than the
built-in dmesg buffer, or land in pstore console driver to be collected
after a reboot.

Signed-off-by: Mark Salyzyn <salyzyn@...roid.com>

v2:
- move implementation to kernel timekeeping from rtc_lib files
- use rtc_time64_to_tm() instead of rtc_time_to_tm()
- use inline in include/linux/rtc.h for !CONFIG_RTC_SHOW_TIME
v3:
- _correctly_ use rtc_time64_to_tm
v4:
- introduce CONFIG_RTC_SHOW_TIME_<TYPE> and split off rtc time
  format printing to a separate patch.
v5:
- change function to pr_info_show_time
- remove dependent patches from the series to ease discussion.

---
 include/linux/printk.h | 30 +++++++++++++++++++++++++++++
 lib/Kconfig.debug      | 52 ++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 82 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..c1283a893cc1 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -306,6 +306,36 @@ extern asmlinkage void dump_stack(void) __cold;
 	printk(KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_info(fmt, ...) \
 	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+
+/*
+ * pr_info_show_time() prefixes an alternate time prefix as selected by
+ * CONFIG_PR_INFO_SHOW_TIME_<TYPE>.  The time is prefixed on the message
+ * as "[<seconds>.<nseconds><typchar>] ". <TYPE> in the config selection
+ * can be one of the following:
+ *
+ * MONOTONIC - (default) print no alternate time, monotonic is part of dmesg.
+ * BOOTTIME - Adds a message prefix with getboottime64() values.
+ * REALTIME - Adds a message prefix with getnstimeofday64() values.
+ */
+#if defined(CONFIG_PR_INFO_SHOW_TIME_BOOTTIME)
+#define pr_info_show_time(fmt, ...) ({	\
+	struct timespec64 ts;		\
+					\
+	getboottime64(&ts);		\
+	pr_info("[%5lu.%09luB] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
+#include <linux/time64.h>
+#elif defined(CONFIG_PR_INFO_SHOW_TIME_REALTIME)
+#define pr_info_show_time(fmt, ...) ({	\
+	struct timespec64 ts;		\
+					\
+	getnstimeofday64(&ts);		\
+	pr_info("[%lu.%09luU] " fmt, ts.tv_sec, ts.tv_nsec, ##__VA_ARGS__); })
+#include <linux/time64.h>
+#else
+#define pr_info_show_time(fmt, ...) \
+	pr_info(fmt, ##__VA_ARGS__)
+#endif
+
 /*
  * Like KERN_CONT, pr_cont() should only be used when continuing
  * a line with no newline ('\n') enclosed. Otherwise it defaults
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 98fe715522e8..0d63c3fb4e24 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -30,6 +30,58 @@ config CONSOLE_LOGLEVEL_DEFAULT
 	  usage in the kernel. That is controlled by the MESSAGE_LOGLEVEL_DEFAULT
 	  option.
 
+# set if time is being printed in pr_info_show_time()
+config PR_INFO_SHOW_TIME
+	bool
+
+choice
+	prompt "pr_info_show_time() alternate time message prefix"
+	help
+	  Activate alternate time prefix in pr_info_show_time
+
+	  The primary use of the instrumentation is to aid field
+	  analysis of Battery and Power usage.  The instrumentation
+	  may also help triage and synchronize kernel logs and user
+	  space activity logs at key displacements.
+	config PR_INFO_SHOW_TIME_MONOTONIC
+		bool "monotonic"
+		help
+		  Deactivate alternate time prefix in pr_info_show_time.
+		  Doing so because monotonic time is part of the normal
+		  printk time logging.
+
+		  Print only the supplied message in pr_info_show_time,
+		  indistinguishable from pr_info.
+	config PR_INFO_SHOW_TIME_REALTIME
+		bool "realtime"
+		select PR_INFO_SHOW_TIME
+		help
+		  Activate alternate time prefix in pr_info_show_time
+
+		  The primary use of the instrumentation is to aid field
+		  analysis of Battery and Power usage.  The instrumentation
+		  may also help triage and synchronize kernel logs and user
+		  space activity logs at key displacements.  For instance
+		  CLOCK_MONOTONIC stops while suspended, while CLOCK_REALTIME
+		  continues, and the timestamps help re-orient post-analysis.
+
+		  Prefix realtime [<epoch>.<ns>U] timestamp in pr_info_show_time
+	config PR_INFO_SHOW_TIME_BOOTTIME
+		bool "boottime"
+		select PR_INFO_SHOW_TIME
+		help
+		  Activate alternate time prefix in pr_info_show_time
+
+		  The primary use of the instrumentation is to aid field
+		  analysis of Battery and Power usage.  The instrumentation
+		  may also help triage and synchronize kernel logs and user
+		  space activity logs at key displacements.  For instance
+		  CLOCK_MONOTONIC stops while suspended, while CLOCK_BOOTTIME
+		  continues, and the timestamps help re-orient post-analysis.
+
+		  Prefix boottime [<epoch>.<ns>B] timestamp in pr_info_show_time
+endchoice
+
 config MESSAGE_LOGLEVEL_DEFAULT
 	int "Default message log level (1-7)"
 	range 1 7
-- 
2.14.0.rc0.284.gd933b75aa4-goog

Powered by blists - more mailing lists