From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752572AbdHIWm2 (ORCPT ); Wed, 9 Aug 2017 18:42:28 -0400 Received: from mx1.redhat.com ([209.132.183.28]:49642 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752403AbdHIWmZ (ORCPT ); Wed, 9 Aug 2017 18:42:25 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com CFB5E2B5ADD Authentication-Results: ext-mx09.extmail.prod.ext.phx2.redhat.com; dmarc=none (p=none dis=none) header.from=redhat.com Authentication-Results: ext-mx09.extmail.prod.ext.phx2.redhat.com; spf=fail smtp.mailfrom=prarit@redhat.com Subject: Re: [PATCH v3] printk: Add boottime and real timestamps To: "Luis R. Rodriguez" References: <1501809524-496-1-git-send-email-prarit@redhat.com> <20170807171412.GK27873@wotan.suse.de> <20170809182433.GE27873@wotan.suse.de> Cc: 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 From: Prarit Bhargava Message-ID: Date: Wed, 9 Aug 2017 18:42:21 -0400 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.7.0 MIME-Version: 1.0 In-Reply-To: <20170809182433.GE27873@wotan.suse.de> Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: 7bit X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.38]); Wed, 09 Aug 2017 22:42:25 +0000 (UTC) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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 >