Re: [PATCH 2/2] printk, Add printk.clock kernel parameter

[Petr Mladek <pmladek@suse.com>]

On Thu 2016-01-07 10:38:37, Prarit Bhargava wrote:
> 
> 
> On 01/07/2016 09:57 AM, Petr Mladek wrote:
> > On Wed 2016-01-06 08:00:34, Prarit Bhargava wrote:
> >> This patch introduces printk.clock=[local|boot|real|tai] allowing a
> >> user to specify an adjusted clock to use with printk timestamps.  The
> >> hardware clock, or the existing functionality, is preserved by default.
> >> +	pr_info("printk: timestamp set to %s clock.\n", printk_clock);
> >> +	return 0;
> >> +}
> >> +
> >> +static struct kernel_param_ops printk_clock_param_ops = {
> >> +	.set =		printk_clock_param_set,
> >> +	.get =		param_get_charp,
> >> +};
> >> +
> >> +module_param_cb(clock, &printk_clock_param_ops, &printk_clock, 0644);
> >> +MODULE_PARM_DESC(clock, "Clock used for printk timestamps.  Can be local (hardware/default), boot, real, or tai.\n");
> > 
> > I have problems to parse this. It seems that the most common style
> > used for possible values is to putthem into brackets. I wonder
> > if this is better readable.
> > 
> > MODULE_PARM_DESC(clock, "Clock used for printk timestamps (local = default, boot, real, tai).");
> > 
> 
> Ah, thanks! :)  I was wondering if there was a coding style preference there
> when I wrote this up.

Heh, I am not sure if there is any coding style for this. I just went
over the output from

      git grep MODULE_PARM_DESC

> > 
> >> +
> >>  /* insert record into the buffer, discard old ones, update heads */
> >>  static int log_store(int facility, int level,
> >>  		     enum log_flags flags, u64 ts_nsec,
> >> @@ -467,7 +544,7 @@ static int log_store(int facility, int level,
> >>  	if (ts_nsec > 0)
> >>  		msg->ts_nsec = ts_nsec;
> >>  	else
> >> -		msg->ts_nsec = local_clock();
> >> +		msg->ts_nsec = printk_get_timestamp();
> > 
> > Hmm, one problem is that each clock returns another type of time.
> > "local" and "boot" clocks returns the number of ns since the boot.
> > While "real" and "tai" clocks returns the number of ns since 1.1.1970
> > or so.
> > 
> > The tools reading the timestamps are confused by this. For example,
> > I get this:
> > 
> > $> echo boot >/sys/module/printk/parameters/clock
> > $> echo local >/sys/module/printk/parameters/clock
> > $> echo real >/sys/module/printk/parameters/clock
> > $> echo tai >/sys/module/printk/parameters/clock
> > $> dmesg | tail -6
> > [    6.976593] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
> > [    6.977168] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> > [   77.500483] printk: timestamp set to boot clock.
> > [   81.419957] printk: timestamp set to local clock.
> > [1452177961.544909] printk: timestamp set to real clock.
> > [1452177965.224824] printk: timestamp set to tai clock.
> > $> dmesg -T | tail -6
> > [Thu Jan  7 15:44:41 2016] e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX
> > [Thu Jan  7 15:44:41 2016] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> > [Thu Jan  7 15:45:52 2016] printk: timestamp set to boot clock.
> > [Thu Jan  7 15:45:56 2016] printk: timestamp set to local clock.
> > [Fri Jan 13 06:30:36 2062] printk: timestamp set to real clock.
> > [Fri Jan 13 06:30:40 2062] printk: timestamp set to tai clock.
> > 
> > Please, note that the last messages looks as they are printed in
> > a far far future ;-)
> 
> Heh :)  I didn't even think of testing that.  I'll have to think about that a
> bit more.  systemd logging must assume boot time/local time.  I'll ping those
> guys with a patch if/when the next version of this gets accepted.

I am not sure how many tools would be affected by this. An easier
solution would be to normalize all times and always save the relative
time since the boot as it is done now.

Best Regards,
Petr