From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1759811AbcAMMe4 (ORCPT ); Wed, 13 Jan 2016 07:34:56 -0500 Received: from mx1.redhat.com ([209.132.183.28]:37237 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1759625AbcAMMec (ORCPT ); Wed, 13 Jan 2016 07:34:32 -0500 From: Prarit Bhargava To: linux-kernel@vger.kernel.org Cc: Prarit Bhargava , John Stultz , Xunlei Pang , Thomas Gleixner , Baolin Wang , Andrew Morton , Greg Kroah-Hartman , Petr Mladek , Tejun Heo , Peter Hurley , Vasily Averin , Joe Perches Subject: [PATCH 2/2] printk, Add printk.clock kernel parameter Date: Wed, 13 Jan 2016 07:34:26 -0500 Message-Id: <1452688466-14877-3-git-send-email-prarit@redhat.com> In-Reply-To: <1452688466-14877-1-git-send-email-prarit@redhat.com> References: <1452688466-14877-1-git-send-email-prarit@redhat.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org The script used in the analysis below: dmesg_with_human_timestamps () { $(type -P dmesg) "$@" | perl -w -e 'use strict; my ($uptime) = do { local @ARGV="/proc/uptime";<>}; ($uptime) = ($uptime =~ /^(\d+)\./); foreach my $line (<>) { printf( ($line=~/^\[\s*(\d+)\.\d+\](.+)/) ? ( "[%s]%s\n", scalar localtime(time - $uptime + $1), $2 ) : $line ) }' } dmesg_with_human_timestamps ----8<---- 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. 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 "boot 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.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. [v2]: use NMI safe timekeeping access functions Cc: John Stultz Cc: Xunlei Pang Cc: Thomas Gleixner Cc: Baolin Wang Cc: Andrew Morton Cc: Greg Kroah-Hartman Cc: Petr Mladek Cc: Tejun Heo Cc: Peter Hurley Cc: Vasily Averin Cc: Joe Perches Signed-off-by: Prarit Bhargava --- kernel/printk/printk.c | 54 ++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 52 insertions(+), 2 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 2ce8826..671f0ec 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -419,6 +419,56 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len, return msg_used_size(*text_len + *trunc_msg_len, 0, pad_len); } +/* Default timestamp is local clock */ +static char *printk_clock = "local"; +static u64 (*printk_clock_fn)(void) = &local_clock; + +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 = &ktime_get_real_fast_ns; + } else if (!strncmp("boot", printk_clock_new, 4)) { + ret = param_set_charp(printk_clock_new, kp); + if (ret) + return ret; + printk_clock_fn = &ktime_get_boot_fast_ns; + } else if (!strncmp("tai", printk_clock_new, 3)) { + ret = param_set_charp(printk_clock_new, kp); + if (ret) + return ret; + printk_clock_fn = &ktime_get_tai_fast_ns; + } else { + return -EINVAL; + } + + 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"); + /* 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 +517,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_clock_fn(); memset(log_dict(msg) + dict_len, 0, pad_len); msg->len = size; @@ -1613,7 +1663,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len) cont.facility = facility; cont.level = level; cont.owner = current; - cont.ts_nsec = local_clock(); + cont.ts_nsec = printk_clock_fn(); cont.flags = 0; cont.cons = 0; cont.flushed = false; -- 1.7.9.3