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
>
