Re: [PATCH] printk, allow different timestamps for printk.time [v2]

[Petr Mladek <pmladek@suse.com>]

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