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

[Prarit Bhargava <prarit@redhat.com>]

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.
>>
>> If the timekeeper_lock (used to protect writes from reads) is under
>> contention, the last known good time is output again and "??" is used as
>> the last two digits of time.  This avoids contention issues with a CPU
>> panicking while another CPU is writing time data.
>>
>> ---
>>  include/linux/time64.h |    2 +
>>  kernel/printk/printk.c |  105 ++++++++++++++++++++++++++++++++++++++++++++----
>>  2 files changed, 99 insertions(+), 8 deletions(-)
>>
>> diff --git a/include/linux/time64.h b/include/linux/time64.h
>> index 367d5af..f4a35d9 100644
>> --- a/include/linux/time64.h
>> +++ b/include/linux/time64.h
>> @@ -39,6 +39,8 @@ struct itimerspec64 {
>>  #define TIME64_MAX			((s64)~((u64)1 << 63))
>>  #define KTIME_MAX			((s64)~((u64)1 << 63))
>>  #define KTIME_SEC_MAX			(KTIME_MAX / NSEC_PER_SEC)
>> +/* Maximum value returned by ktime_to_ns() */
>> +#define KTIME_MAX_NS 			((u64)((U64_MAX>>1)))
> 
> Please, use KTIME_NS_MAX to use the same naming scheme as
> KTIME_SEC_MAX.
> 
> Well, I would return 0 when the time is not known. See also below.
> 
>>  #if __BITS_PER_LONG == 64
>>  
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index 2ce8826..ffc05ee 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -419,6 +419,83 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len,
>>  	return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len);
>>  }
>>  
>> +static u64 printk_try_real_ns(void)
>> +{
>> +	return ktime_try_real_ns();
>> +}
>> +
>> +static u64 printk_try_boot_ns(void)
>> +{
>> +	return ktime_try_boot_ns();
>> +}
>> +
>> +static u64 printk_try_tai_ns(void)
>> +{
>> +	return ktime_try_tai_ns();
>> +}
> 
> Do we need these wrappers? Why not using ktime_try_xxx_ns() directly?
> You already use local_clock().

Unfortunately ktime_* are inlined functions, and I've mimicked the currently
coding style there.

In any case I'm doing a v2 with different functions.  I'll see if making this
stuff not-inlined is any better.

> 
> 
>> +static int printk_clock_param_set(const char *val,
>> +				  const struct kernel_param *kp)
>> +{
>> +	char *printk_clock_new = strstrip((char *)val);
>> +	int ret;
>> +
>> +	/* check if change is needed */
>> +	if (!strcmp(printk_clock_new, printk_clock))
>> +		return 0;
>> +
>> +	if (!strncmp("local", printk_clock_new, 5)) {
>> +		ret = param_set_charp(printk_clock_new, kp);
>> +		if (ret)
>> +			return ret;
>> +		printk_clock_fn = &local_clock;
>> +	} else if (!strncmp("real", printk_clock_new, 4)) {
>> +		ret = param_set_charp(printk_clock_new, kp);
>> +		if (ret)
>> +			return ret;
>> +		printk_clock_fn = &printk_try_real_ns;
>> +	} else if (!strncmp("boot", printk_clock_new, 4)) {
>> +		ret = param_set_charp(printk_clock_new, kp);
>> +		if (ret)
>> +			return ret;
>> +		printk_clock_fn = &printk_try_boot_ns;
>> +	} else if (!strncmp("tai", printk_clock_new, 3)) {
>> +		ret = param_set_charp(printk_clock_new, kp);
>> +		if (ret)
>> +			return ret;
>> +		printk_clock_fn = &printk_try_tai_ns;
>> +	}
>> +
>> +	/* Did the clock change ? */
>> +	if (strcmp(printk_clock_new, printk_clock))
>> +		return -EINVAL;
> 
> I wonder if we need this extra check. It might be enough to
> print the error message in the final "else" above.

I was trying to catch a local to local change or a real to real change.
But yeah ... I could sort of do that in the final else above.

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

> 
>> +
>>  /* 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.

Thanks for catching this.

> 
> 
>>  	memset(log_dict(msg) + dict_len, 0, pad_len);
>>  	msg->len = size;
>>  
>> @@ -1039,18 +1116,30 @@ module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>>  
>>  static size_t print_time(u64 ts, char *buf)
>>  {
>> -	unsigned long rem_nsec;
>> +	unsigned long rem;
>> +	size_t size;
>>  
>>  	if (!printk_time)
>>  		return 0;
>>  
>> -	rem_nsec = do_div(ts, 1000000000);
>> +	if (ts == KTIME_MAX_NS)
>> +		ts = last_time_stamp;
>>  
>> -	if (!buf)
>> -		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
>> +	if (buf) {
>> +		size = INT_MAX;
>> +		rem = do_div(ts, 1000000000) / 1000;
>> +	} else {
>> +		size = 0;
>> +		rem = 0;
>> +	}
>>  
>> -	return sprintf(buf, "[%5lu.%06lu] ",
>> -		       (unsigned long)ts, rem_nsec / 1000);
>> +	if (ts != KTIME_MAX_NS) {
>> +		return snprintf(buf, size, "[%5lu.%06lu] ",
>> +			       (unsigned long)ts, rem);
>> +	}
>> +	/* return last_time_stamp with ?? warning */
>> +	return snprintf(buf, size, "[%5lu.%04lu??] ",
>> +		       (unsigned long)ts, rem);
> 
> I am not sure if this is worth the effort. All other tools parsing the
> log will be confused by this. Also there are tools that read the ring
> buffer dirrectly, e.g. "crash" reading a crashdump. They will need to
> get updated to handle KTIME_MAX_NS correctly.

Yep -- the thread contains suggestions on how to avoid all of this by using the
NMI safe ktime_* calls (and implementing new ones).  I'm going to do that which
should nicely clean all of this up.

Thanks for the review Petr,

P.