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

[Prarit Bhargava <prarit@redhat.com>]

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.  I will have to modify dmesg once this code is stabilized.

> 
> 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.

P.