Messages in this thread | | | Date | Fri, 22 Apr 2016 12:47:30 -0700 | From | Andrew Morton <> | Subject | Re: [PATCH 2/2] printk, allow different timestamps for printk.time |
| |
On Fri, 22 Apr 2016 08:03:09 -0400 Prarit Bhargava <prarit@redhat.com> wrote:
> Over the past years I've seen many reports of bugs that include > time-stamped kernel logs (enabled when CONFIG_PRINTK_TIME=y or > print.time=1 is specified as a kernel parameter) that do not align > with either external time stamped logs or /var/log/messages. This > also makes determining the time of a failure difficult in cases where > /var/log/messages is unavailable. > > For example, > > [root@intel-wildcatpass-06 ~]# date; echo "Hello!" > /dev/kmsg ; date > Thu Dec 17 13:58:31 EST 2015 > Thu Dec 17 13:58:31 EST 2015 > > which displays > > [83973.768912] Hello! > > on the serial console. > > Running a script to convert this to the stamped time, > > [root@intel-wildcatpass-06 ~]# ./human.sh | tail -1 > [Thu Dec 17 13:59:57 2015] Hello! > > which is already off by 1 minute and 26 seconds off after ~24 hours of > uptime. > > This occurs because the time stamp is obtained from a call to > local_clock() which (on x86) is a direct call to the hardware. These > hardware clock reads are not modified by the standard ntp or ptp protocol, > while the other timestamps are, and that results in situations external > time sources are further and further offset from the kernel log > timestamps. > > This patch introduces printk.time=[0-3] allowing a user to specify an adjusted > clock to use with printk timestamps. The hardware clock, or the existing > functionality, is preserved by default. > > Real clock & 32-bit systems: Selecting the real clock printk timestamp may > lead to unlikely situations where a timestamp is wrong because the real time > offset is read without the protection of a sequence lock in the call to > ktime_get_log_ts() in printk_get_ts().
Looks OK to me. Timekeeping stuff makes my head spin nowadays but I trust you've sorted out the obvious deadlock/reentrancy/etc issues. I'll toss it in for some testing.
> @@ -1042,6 +1044,12 @@ static inline void boot_delay_msec(int level) > > static int printk_time = CONFIG_PRINTK_TIME; > > +/* > + * Real clock & 32-bit systems: Selecting the real clock printk timestamp may > + * lead to unlikely situations where a timestamp is wrong because the real time > + * offset is read without the protection of a sequence lock in the call to > + * ktime_get_log_ts() in printk_get_ts() below. > + */ > static int printk_time_param_set(const char *val, > const struct kernel_param *kp) > { > @@ -1063,6 +1071,14 @@ static int printk_time_param_set(const char *val, > case 'y': > printk_time = 1; > break; > + /* 2 = monotonic clock */ > + case '2': > + printk_time = 2; > + break; > + /* 3 = real clock */ > + case '3': > + printk_time = 3; > + break;
Maybe it's time to enumerate these values.
> default: > pr_warn("printk: invalid timestamp value\n"); > return -EINVAL; > @@ -1080,6 +1096,21 @@ static struct kernel_param_ops printk_time_param_ops = { > > module_param_cb(time, &printk_time_param_ops, &printk_time, S_IRUGO); > > +static u64 printk_get_ts(void) > +{ > + u64 mono, offset_real; > + > + if (printk_time <= 1) > + return local_clock(); > + > + mono = ktime_get_log_ts(&offset_real); > + > + if (printk_time == 2) > + return mono; > + > + return mono + offset_real; > +}
Because the magic constants set a bad example for any children in the audience.
| |