Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1739970 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime  timestamps Prarit Bhargava <prarit@redhat.com> - 2017-09-26 17:20 +0200
    Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime  timestamps Thomas Gleixner <tglx@linutronix.de> - 2017-09-26 17:30 +0200
      Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime  timestamps Prarit Bhargava <prarit@redhat.com> - 2017-09-26 17:40 +0200
        Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime  timestamps Thomas Gleixner <tglx@linutronix.de> - 2017-09-26 17:40 +0200
          Re: [tip:core/printk] printk: Add monotonic, boottime, and realtime  timestamps Prarit Bhargava <prarit@redhat.com> - 2017-09-26 17:50 +0200

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

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)"
> 

[toc] | [next] | [standalone]

#1739983

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

[toc] | [prev] | [next] | [standalone]

#1739986

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
> 
> 

[toc] | [prev] | [next] | [standalone]

#1739990

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.

[toc] | [prev] | [next] | [standalone]

#1739993

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.

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web