Messages in this thread Patches in this message |  | | Date | Wed, 9 Aug 2017 20:24:33 +0200 | From | "Luis R. Rodriguez" <> | Subject | Re: [PATCH v3] printk: Add boottime and real timestamps |
| |
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
|  |