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

Groups > linux.kernel > #1705722 > unrolled thread

Re: [PATCH v3] printk: Add boottime and real 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: [PATCH v3] printk: Add boottime and real timestamps "Luis R. Rodriguez" <mcgrof@kernel.org> - 2017-08-07 19:20 +0200
    Re: [PATCH v3] printk: Add boottime and real timestamps Prarit Bhargava <prarit@redhat.com> - 2017-08-07 20:20 +0200
      Re: [PATCH v3] printk: Add boottime and real timestamps "Luis R. Rodriguez" <mcgrof@kernel.org> - 2017-08-09 20:30 +0200
        Re: [PATCH v3] printk: Add boottime and real timestamps Prarit Bhargava <prarit@redhat.com> - 2017-08-10 00:50 +0200

#1705722 — Re: [PATCH v3] printk: Add boottime and real timestamps

On Thu, Aug 03, 2017 at 09:18:44PM -0400, Prarit Bhargava wrote:
> index fc47863f629c..8f093dd0a733 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1202,8 +1204,119 @@ 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);
> +static int printk_time = CONFIG_PRINTK_TIME;
> +static int printk_time_setting;
> +
> +/**
> + * enum printk_time_type - Timestamp types for printk() messages.
> + * @PRINTK_TIME_DISABLE: 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 in the call to ktime_get_log_ts()
> + * in printk_get_ts() below.

You can expand on this or the actual routines that use this in kdoc form.

> + */
> +enum printk_time_type {
> +	PRINTK_TIME_DISABLE = 0,
> +	PRINTK_TIME_LOCAL = 1,
> +	PRINTK_TIME_BOOT = 2,
> +	PRINTK_TIME_MONO = 3,
> +	PRINTK_TIME_REAL = 4,
> +};
> +
> +static const char * const printk_time_str[5] = {
> +	"disabled",
> +	"local hardware",
> +	"boottime",
> +	"monotonic",
> +	"realtime",
> +};
> +
> +static int printk_time_set(const char *val, const struct kernel_param *kp)
> +{
> +	char *param = strstrip((char *)val);
> +	int _printk_time;
> +
> +	if (strlen(param) != 1)
> +		return -EINVAL;
> +
> +	switch (param[0]) {
> +	case '0':
> +	case 'n':
> +	case 'N':
> +		_printk_time = PRINTK_TIME_DISABLE;
> +		break;
> +	case '1':
> +	case 'y':
> +	case 'Y':
> +		_printk_time = PRINTK_TIME_LOCAL;
> +		break;
> +	case '2':
> +		_printk_time = PRINTK_TIME_BOOT;
> +		break;
> +	case '3':
> +		_printk_time = PRINTK_TIME_MONO;
> +		break;
> +	case '4':
> +		_printk_time = PRINTK_TIME_REAL;
> +		break;
> +	default:
> +		pr_warn("printk: invalid timestamp value\n");
> +		return -EINVAL;
> +	}
> +
> +	/*
> +	 * Only allow enabling and disabling of the current printk_time
> +	 * setting.  Changing it from one setting to another confuses
> +	 * userspace.
> +	 */
> +	if (printk_time_setting == PRINTK_TIME_DISABLE) {
> +		printk_time_setting = _printk_time;
> +	} else if ((printk_time_setting != _printk_time) &&
> +		   (_printk_time != 0)) {
> +		pr_warn("printk: timestamp can only be set to 0(disabled) or %d(%s) ",
> +			printk_time_setting,
> +			printk_time_str[printk_time_setting]);
> +		return -EINVAL;
> +	}
> +
> +	printk_time = _printk_time;
> +	pr_info("printk: timestamp set to %d(%s).",
> +		printk_time, printk_time_str[printk_time]);
> +	return 0;
> +}
> +
> +static int printk_time_get(char *buffer, const struct kernel_param *kp)
> +{
> +	return scnprintf(buffer, PAGE_SIZE, "%d", printk_time);
> +}
> +
> +static struct kernel_param_ops printk_time_ops = {
> +	.set = printk_time_set,
> +	.get = printk_time_get,
> +};
> +module_param_cb(time, &printk_time_ops, NULL, 0644);
> +
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time <= PRINTK_TIME_LOCAL)
> +		return local_clock();
> +
> +	if (printk_time == PRINTK_TIME_BOOT)
> +		return ktime_get_boot_log_ts();
> +
> +	mono = ktime_get_real_log_ts(&offset_real);
> +
> +	if (printk_time == PRINTK_TIME_MONO)
> +		return mono;
> +
> +	return mono + offset_real;
> +}
>  
>  static size_t print_time(u64 ts, char *buf)
>  {
> @@ -1643,7 +1756,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;
>  	}
>  
> @@ -1873,6 +1986,8 @@ 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;
> +static int printk_time_setting;
>  #endif /* CONFIG_PRINTK */
>  
>  #ifdef CONFIG_EARLY_PRINTK
>
> @@ -2659,6 +2774,10 @@ static int __init printk_late_init(void)
>  	struct console *con;
>  	int ret;
>  
> +	/* initialize printk_time settings */
> +	if (printk_time_setting == 0)
> +		printk_time_setting = printk_time;
> +

Note printk_late_init() is a late_initcall(). This means if the
printk_time_setting was disabled it will take a while to enable it. Enabling it
is done at the device_initcall(), so if printk setting is disabled but a user
enables it with a toggle of the module param there is a period of time during
which time resolution would be different. Perhaps for some this is not useful
information but for others I think this would be very valuable.

There is also something to say about the time in between initializing access
to ktime_get_mono_fast_ns(), how early is this reliable?

All these things could be mentioned on the documentation.

  Luis

[toc] | [next] | [standalone]

#1705771

On 08/07/2017 01:14 PM, Luis R. Rodriguez wrote:

> 
> Note printk_late_init() is a late_initcall(). This means if the
> printk_time_setting was disabled it will take a while to enable it. Enabling it
> is done at the device_initcall(), so if printk setting is disabled but a user
> enables it with a toggle of the module param there is a period of time during
> which time resolution would be different. 

I'm not sure I follow your comment.  Could you elaborate with an example of
what you think is going wrong or might be confusing?

P.

> Perhaps for some this is not useful
> information but for others I think this would be very valuable.
> 
> There is also something to say about the time in between initializing access
> to ktime_get_mono_fast_ns(), how early is this reliable?
> 
> All these things could be mentioned on the documentation.
> 
>   Luis
> 

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

#1707714

On Mon, Aug 07, 2017 at 02:17:33PM -0400, Prarit Bhargava wrote:
> 
> 
> On 08/07/2017 01:14 PM, Luis R. Rodriguez wrote:
> 
> > 
> > Note printk_late_init() is a late_initcall(). This means if the
> > printk_time_setting was disabled it will take a while to enable it. Enabling it
> > is done at the device_initcall(), so if printk setting is disabled but a user
> > enables it with a toggle of the module param there is a period of time during
> > which time resolution would be different. 
> 
> I'm not sure I follow your comment.  Could you elaborate with an example of
> what you think is going wrong or might be confusing?

Sure let's consider this:

+static u64 printk_get_ts(void)
+{
+	u64 mono, offset_real;
+
+	if (printk_time <= PRINTK_TIME_LOCAL)
+		return local_clock();
+
+	if (printk_time == PRINTK_TIME_BOOT)
+		return ktime_get_boot_log_ts();
+
+	mono = ktime_get_real_log_ts(&offset_real);
+
+	if (printk_time == PRINTK_TIME_MONO)
+		return mono;
+
+	return mono + offset_real;
+}

So even if printk_time was flipped in the end the backend routines used will be
local_clock(), ,ktime_get_boot_log_ts() or ktime_get_real_log_ts().

This is used here;
 
@@ -1643,7 +1756,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;
 	}


But lets inspect these new calls:
 
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
@@ -477,6 +479,24 @@ u64 notrace ktime_get_boot_fast_ns(void)
 }
 EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
 
+u64 ktime_get_real_log_ts(u64 *offset_real)
+{
+	*offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
+
+	if (timekeeping_active)
+		return ktime_get_mono_fast_ns();
+	else
+		return local_clock();
+}
+
+u64 ktime_get_boot_log_ts(void)
+{
+	if (timekeeping_active)
+		return ktime_get_boot_fast_ns();
+	else
+		return local_clock();
+}
+

So they are really only effectively calling something other than
what lock_clock() returns *iff* timekeeping_active is true. But
this is only set later at the respective device_initcall() in this
file:

@@ -1530,6 +1550,8 @@ void __init timekeeping_init(void)
 
 	write_seqcount_end(&tk_core.seq);
 	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
+
+	timekeeping_active = 1;
 }
 

So when the boot param is processed and prints out that it has
changed someone inspecting any time setting after that print
may assume its using after that ktime_get_mono_fast_ns() or
time_get_boot_fast_ns() but this is not accurate, it will use
local_clock() until *after* device_initcall().

So in between boot and this particular device_initcall() time
resolution can only be local_time(). Seems worth documenting
that.

  Luis

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

#1708040

On 08/09/2017 02:24 PM, Luis R. Rodriguez wrote:
> On Mon, Aug 07, 2017 at 02:17:33PM -0400, Prarit Bhargava wrote:
>>
>>
>> On 08/07/2017 01:14 PM, Luis R. Rodriguez wrote:
>>
>>>
>>> Note printk_late_init() is a late_initcall(). This means if the
>>> printk_time_setting was disabled it will take a while to enable it. Enabling it
>>> is done at the device_initcall(), so if printk setting is disabled but a user
>>> enables it with a toggle of the module param there is a period of time during
>>> which time resolution would be different. 
>>
>> I'm not sure I follow your comment.  Could you elaborate with an example of
>> what you think is going wrong or might be confusing?
> 
> Sure let's consider this:
> 
> +static u64 printk_get_ts(void)
> +{
> +	u64 mono, offset_real;
> +
> +	if (printk_time <= PRINTK_TIME_LOCAL)
> +		return local_clock();
> +
> +	if (printk_time == PRINTK_TIME_BOOT)
> +		return ktime_get_boot_log_ts();
> +
> +	mono = ktime_get_real_log_ts(&offset_real);
> +
> +	if (printk_time == PRINTK_TIME_MONO)
> +		return mono;
> +
> +	return mono + offset_real;
> +}
> 
> So even if printk_time was flipped in the end the backend routines used will be
> local_clock(), ,ktime_get_boot_log_ts() or ktime_get_real_log_ts().
> 
> This is used here;
>  
> @@ -1643,7 +1756,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;
>  	}
> 
> 
> But lets inspect these new calls:
>  
> diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
> @@ -477,6 +479,24 @@ u64 notrace ktime_get_boot_fast_ns(void)
>  }
>  EXPORT_SYMBOL_GPL(ktime_get_boot_fast_ns);
>  
> +u64 ktime_get_real_log_ts(u64 *offset_real)
> +{
> +	*offset_real = ktime_to_ns(tk_core.timekeeper.offs_real);
> +
> +	if (timekeeping_active)
> +		return ktime_get_mono_fast_ns();
> +	else
> +		return local_clock();
> +}
> +
> +u64 ktime_get_boot_log_ts(void)
> +{
> +	if (timekeeping_active)
> +		return ktime_get_boot_fast_ns();
> +	else
> +		return local_clock();
> +}
> +
> 
> So they are really only effectively calling something other than
> what lock_clock() returns *iff* timekeeping_active is true. But
> this is only set later at the respective device_initcall() in this
> file:
> 
> @@ -1530,6 +1550,8 @@ void __init timekeeping_init(void)
>  
>  	write_seqcount_end(&tk_core.seq);
>  	raw_spin_unlock_irqrestore(&timekeeper_lock, flags);
> +
> +	timekeeping_active = 1;
>  }
>  
> 
> So when the boot param is processed and prints out that it has
> changed someone inspecting any time setting after that print
> may assume its using after that ktime_get_mono_fast_ns() or
> time_get_boot_fast_ns() but this is not accurate, it will use
> local_clock() until *after* device_initcall().
> 
> So in between boot and this particular device_initcall() time
> resolution can only be local_time(). Seems worth documenting
> that.

I've moved to a different model of using a fn ptr for print_get_ts() and using
peterz's suggestion of returning 0 until the timekeeping is initialized, so this
won't be a problem any more.

P.

> 
>   Luis
> 

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web