Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

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 <prarit@redhat.com>
> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
> Committer:  Thomas Gleixner <tglx@linutronix.de>
> 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 <prarit@redhat.com>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> Cc: Joel Fernandes <joelaf@google.com>
> Cc: Geert Uytterhoeven <geert+renesas@glider.be>
> Cc: linux-doc@vger.kernel.org
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Deepa Dinamani <deepa.kernel@gmail.com>
> Cc: Christoffer Dall <cdall@linaro.org>
> Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
> Cc: Jonathan Corbet <corbet@lwn.net>
> Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
> Cc: Petr Mladek <pmladek@suse.com>
> Cc: Kees Cook <keescook@chromium.org>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Nicholas Piggin <npiggin@gmail.com>
> Cc: Josh Poimboeuf <jpoimboe@redhat.com>
> Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> Cc: Stephen Boyd <sboyd@codeaurora.org>
> Cc: Mark Salyzyn <salyzyn@android.com>
> Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
> Cc: Olof Johansson <olof@lixom.net>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Link: https://lkml.kernel.org/r/1505757060-2004-4-git-send-email-prarit@redhat.com
> 
> ---
>  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)"
> 

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Thomas Gleixner]

On Tue, 26 Sep 2017, Prarit Bhargava wrote:

> 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 <prarit@redhat.com>
> > AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
> > Committer:  Thomas Gleixner <tglx@linutronix.de>
> > 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.

Errm. I applied v12. where the heck is v13?

And in the applied patch printk_time is used.....

Thanks,

	tglx

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 09/26/2017 11:26 AM, Thomas Gleixner wrote:
> On Tue, 26 Sep 2017, Prarit Bhargava wrote:
> 
>> 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 <prarit@redhat.com>
>>> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
>>> Committer:  Thomas Gleixner <tglx@linutronix.de>
>>> 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.
> 
> Errm. I applied v12. where the heck is v13?
> 
> And in the applied patch printk_time is used.....

Sorry, my mistake I meant v13.

This morning pmladek posted about a warning when when CONFIG_PRINTK is not defined:

https://marc.info/?l=linux-doc&m=150642667403344&w=2

I'm fixing it now for v13.

P.
> 
> Thanks,
> 
> 	tglx
> 
> 

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Thomas Gleixner]

On Tue, 26 Sep 2017, Prarit Bhargava wrote:
> On 09/26/2017 11:26 AM, Thomas Gleixner wrote:
> > On Tue, 26 Sep 2017, Prarit Bhargava wrote:
> > 
> >> 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 <prarit@redhat.com>
> >>> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
> >>> Committer:  Thomas Gleixner <tglx@linutronix.de>
> >>> 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.
> > 
> > Errm. I applied v12. where the heck is v13?
> > 
> > And in the applied patch printk_time is used.....
> 
> Sorry, my mistake I meant v13.
> 
> This morning pmladek posted about a warning when when CONFIG_PRINTK is not defined:
> 
> https://marc.info/?l=linux-doc&m=150642667403344&w=2
> 
> I'm fixing it now for v13.

Please send a delta patch.

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Prarit Bhargava]

On 09/26/2017 11:33 AM, Thomas Gleixner wrote:
> On Tue, 26 Sep 2017, Prarit Bhargava wrote:
>> On 09/26/2017 11:26 AM, Thomas Gleixner wrote:
>>> On Tue, 26 Sep 2017, Prarit Bhargava wrote:
>>>
>>>> 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 <prarit@redhat.com>
>>>>> AuthorDate: Mon, 18 Sep 2017 13:51:00 -0400
>>>>> Committer:  Thomas Gleixner <tglx@linutronix.de>
>>>>> 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.
>>>
>>> Errm. I applied v12. where the heck is v13?
>>>
>>> And in the applied patch printk_time is used.....
>>
>> Sorry, my mistake I meant v13.
>>
>> This morning pmladek posted about a warning when when CONFIG_PRINTK is not defined:
>>
>> https://marc.info/?l=linux-doc&m=150642667403344&w=2
>>
>> I'm fixing it now for v13.
> 
> Please send a delta patch.
> 

Will do.

P.

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Thomas Gleixner]

On Tue, 26 Sep 2017, Sergey Senozhatsky wrote:

> On (09/25/17 12:19), tip-bot for Prarit Bhargava wrote:
> > Commit-ID:  a4c1a0002f4518363da9d9ecd7b805af152dcdf1
> > Gitweb:     http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1
> > Author:     Prarit Bhargava <prarit@redhat.com>
> > AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400
> > Committer:  Thomas Gleixner <tglx@linutronix.de>
> > CommitDate: Mon, 25 Sep 2017 21:12:06 +0200
> > 
> > printk: Add monotonic, boottime, and realtime timestamps
> 
> this doesn't seem to be the latest version of the patch set.
> v12 can be found here: lkml.kernel.org/r/1505757060-2004-1-git-send-email-prarit@redhat.com

Thanks for pointing it out. I somehow got lost in the revisions zoo. Fixed
now.

       tglx

Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[Sergey Senozhatsky]

On (09/25/17 12:19), tip-bot for Prarit Bhargava wrote:
> Commit-ID:  a4c1a0002f4518363da9d9ecd7b805af152dcdf1
> Gitweb:     http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1
> Author:     Prarit Bhargava <prarit@redhat.com>
> AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400
> Committer:  Thomas Gleixner <tglx@linutronix.de>
> CommitDate: Mon, 25 Sep 2017 21:12:06 +0200
> 
> printk: Add monotonic, boottime, and realtime timestamps

this doesn't seem to be the latest version of the patch set.
v12 can be found here: lkml.kernel.org/r/1505757060-2004-1-git-send-email-prarit@redhat.com

	-ss

[tip:core/printk] printk: Add monotonic, boottime, and realtime timestamps

[tip-bot for Prarit Bhargava]

Commit-ID:  a4c1a0002f4518363da9d9ecd7b805af152dcdf1
Gitweb:     http://git.kernel.org/tip/a4c1a0002f4518363da9d9ecd7b805af152dcdf1
Author:     Prarit Bhargava <prarit@redhat.com>
AuthorDate: Mon, 28 Aug 2017 08:21:54 -0400
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Mon, 25 Sep 2017 21:12:06 +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, the monotonic clock, the boottime clock, and the
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.

[ jstultz: Reworked Kconfig settings to avoid defconfig noise ]

Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Cc: John Stultz <john.stultz@linaro.org>
Cc: Joel Fernandes <joelaf@google.com>
Cc: Geert Uytterhoeven <geert+renesas@glider.be>
Cc: linux-doc@vger.kernel.org
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Deepa Dinamani <deepa.kernel@gmail.com>
Cc: Christoffer Dall <cdall@linaro.org>
Cc: "Jason A. Donenfeld" <Jason@zx2c4.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Cc: Petr Mladek <pmladek@suse.com>
Cc: Kees Cook <keescook@chromium.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Nicholas Piggin <npiggin@gmail.com>
Cc: Josh Poimboeuf <jpoimboe@redhat.com>
Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Cc: Stephen Boyd <sboyd@codeaurora.org>
Cc: Mark Salyzyn <salyzyn@android.com>
Cc: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Cc: "Luis R. Rodriguez" <mcgrof@kernel.org>
Cc: Olof Johansson <olof@lixom.net>
Cc: Andrew Morton <akpm@linux-foundation.org>
Link: http://lkml.kernel.org/r/1503922914-10660-3-git-send-email-prarit@redhat.com

---
 Documentation/admin-guide/kernel-parameters.txt |   6 +-
 kernel/printk/printk.c                          | 116 +++++++++++++++++++++++-
 lib/Kconfig.debug                               |  48 +++++++++-
 3 files changed, 162 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..4b824dd 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,116 @@ 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.  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.
+ */
+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 void printk_set_ts_func(void)
+{
+	switch (printk_time) {
+	case PRINTK_TIME_LOCAL:
+	case PRINTK_TIME_DISABLED:
+	default:
+		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;
+	}
+}
+
+static u64 printk_get_first_ts(void)
+{
+	printk_set_ts_func();
+	return printk_get_ts();
+}
+
+static int param_set_time(const char *val, const struct kernel_param *kp)
+{
+	char *param = strstrip((char *)val);
+	int _printk_time = -1;
+	int ts;
+
+	if (strlen(param) == 1) {
+		/* Preserve legacy boolean settings */
+		if ((param[0] == '0') || (param[0] == 'n') ||
+		    (param[0] == 'N'))
+			_printk_time = PRINTK_TIME_DISABLED;
+		if ((param[0] == '1') || (param[0] == 'y') ||
+		    (param[0] == 'Y'))
+			_printk_time = PRINTK_TIME_LOCAL;
+	}
+	if (_printk_time == -1) {
+		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 == -1) {
+		pr_warn("printk: invalid timestamp option %s\n", param);
+		return -EINVAL;
+	}
+
+	printk_time = _printk_time;
+	if (printk_time > PRINTK_TIME_DISABLED)
+		printk_set_ts_func();
+
+	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 +1736,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 +1966,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..b1602fb 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 "CLOCK_BOOTTIME"
+	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"
+	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"
+	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)"