From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754404AbcBHPvt (ORCPT ); Mon, 8 Feb 2016 10:51:49 -0500 Received: from mx2.suse.de ([195.135.220.15]:49605 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753973AbcBHPvr (ORCPT ); Mon, 8 Feb 2016 10:51:47 -0500 Date: Mon, 8 Feb 2016 16:51:44 +0100 From: Petr Mladek To: Prarit Bhargava Cc: linux-kernel@vger.kernel.org, John Stultz , Xunlei Pang , Thomas Gleixner , Baolin Wang , Andrew Morton , Greg Kroah-Hartman , Tejun Heo , Peter Hurley , Vasily Averin , Joe Perches Subject: Re: [PATCH] printk, allow different timestamps for printk.time [v2] Message-ID: <20160208155144.GG30328@pathway.suse.cz> References: <1453985029-25912-1-git-send-email-prarit@redhat.com> <20160204164824.GB3305@pathway.suse.cz> <56B3845F.8050203@redhat.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <56B3845F.8050203@redhat.com> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu 2016-02-04 12:03:27, Prarit Bhargava wrote: > > > On 02/04/2016 11:48 AM, Petr Mladek wrote: > > On Thu 2016-01-28 07:43:49, Prarit Bhargava wrote: > >> +static u64 printk_get_ts(void) > >> +{ > >> + u64 mono, offset_real; > >> + > >> + if (printk_time == 0) > >> + return 0; > >> + > >> + if (printk_time == 1) > >> + return local_clock(); > >> + > >> + mono = ktime_get_log_ts(&offset_real); > >> + > >> + if (printk_time == 2) > >> + return mono; > >> + > >> + return mono + offset_real; > > > > At least dmesg is not capable to read the absolute size of the > > real time. It expects offset against the start of the timekeeping > > stuff or so. I get this: > > > > $> dmesg | tail -n 5 > > [ 7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready > > [ 0.000000] printk: timestamp set to 0. > > ^^^ Hmm ... I'll have to think about that. > > > [ 179.983704] printk: timestamp set to 1. > > [ 181.895655] printk: timestamp set to 2. > > [1454602412.026424] printk: timestamp set to 3. > > > > $dmesg -T -S | tail -n 5 > > [Thu Feb 4 17:10:34 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready > > [Thu Feb 4 17:10:27 2016] printk: timestamp set to 0. > > [Thu Feb 4 17:13:26 2016] printk: timestamp set to 1. > > [Thu Feb 4 17:13:28 2016] printk: timestamp set to 2. > > [Fri Mar 10 09:23:59 2062] printk: timestamp set to 3. > > Yes, this is a known issue that someone else previously brought to my attention > on LKML. It was me ;-) > I will have to modify dmesg once this code is stabilized. But how will dmesg detect when the time is a real time or an offset? There is still a bit available in struct printk_log in the flags variable but... Also note that there are more tools that might need to get updated. For example, "crash" and maybe "gdb" are able to print the messages from the crashdump. I still think that it might be easier to convert the real time to the offset before storing it. > > Please, note that the last entry points to the year 2062. > > > > > >> --- a/lib/Kconfig.debug > >> +++ b/lib/Kconfig.debug > >> @@ -13,7 +13,7 @@ config PRINTK_TIME > >> be included, not that the timestamp is recorded. > >> > >> The behavior is also controlled by the kernel command line > >> - parameter printk.time=1. See Documentation/kernel-parameters.txt > >> + parameter printk.time=[0-3]. See Documentation/kernel-parameters.txt > > > > Please, mention there the mention of the numbers. The cross reference > > is annoying if you look at the help when configuring kernel build. > > I can certainly make that change and provide better documentation. > > > > > Also there is a mismatch between the values and the type of > > CONFIG_PRINTK_TIME. You should change it to > > > > int "Show timing information on printks" > > range 0 3 > > I don't think that's what CONFIG_PRINTK_TIME does. All CONFIG_PRINTK_TIME does > is turn the timestamping on or off. > > IOW, > > CONFIG_PRINTK_TIME=n results in > > IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready > > and CONFIG_PRINTK_TIME=y results in > > [ 7.128924] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready > > I explicitly did NOT want to change the behavior of CONFIG_PRINTK_TIME. But why? IMHO, it would be much more practical and clear if both CONFIG_PRINTK_TIME and the command line parameter printk.time have exactly the same meaning. I am not aware of any other couple where the corresponding config and commandline options have different meaning. Best Regards, Petr