From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753201AbdHISYk (ORCPT ); Wed, 9 Aug 2017 14:24:40 -0400 Received: from mx2.suse.de ([195.135.220.15]:58535 "EHLO mx1.suse.de" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1752142AbdHISYh (ORCPT ); Wed, 9 Aug 2017 14:24:37 -0400 Date: Wed, 9 Aug 2017 20:24:33 +0200 From: "Luis R. Rodriguez" To: Prarit Bhargava Cc: "Luis R. Rodriguez" , linux-kernel@vger.kernel.org, Mark Salyzyn , Jonathan Corbet , Petr Mladek , Sergey Senozhatsky , Steven Rostedt , John Stultz , Thomas Gleixner , Stephen Boyd , Andrew Morton , Greg Kroah-Hartman , "Paul E. McKenney" , Christoffer Dall , Deepa Dinamani , Ingo Molnar , Joel Fernandes , Kees Cook , Peter Zijlstra , Geert Uytterhoeven , Nicholas Piggin , "Jason A. Donenfeld" , Olof Johansson , Josh Poimboeuf , linux-doc@vger.kernel.org Subject: Re: [PATCH v3] printk: Add boottime and real timestamps Message-ID: <20170809182433.GE27873@wotan.suse.de> References: <1501809524-496-1-git-send-email-prarit@redhat.com> <20170807171412.GK27873@wotan.suse.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.6.0 (2016-04-01) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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