[PATCH 0/2] printk, Add printk.clock kernel parameter [v2]

[Prarit Bhargava]

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 patchset introduces additional NMI safe timekeeping functions and the
kernel parameter 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 <john.stultz@xxxxxxxxxx>
Cc: Xunlei Pang <pang.xunlei@xxxxxxxxxx>
Cc: Thomas Gleixner <tglx@xxxxxxxxxxxxx>
Cc: Baolin Wang <baolin.wang@xxxxxxxxxx>
Cc: Andrew Morton <akpm@xxxxxxxxxxxxxxxxxxxx>
Cc: Greg Kroah-Hartman <gregkh@xxxxxxxxxxxxxxxxxxx>
Cc: Petr Mladek <pmladek@xxxxxxx>
Cc: Tejun Heo <tj@xxxxxxxxxx>
Cc: Peter Hurley <peter@xxxxxxxxxxxxxxxxxx>
Cc: Vasily Averin <vvs@xxxxxxxxxxxxx>
Cc: Joe Perches <joe@xxxxxxxxxxx>
Signed-off-by: Prarit Bhargava <prarit@xxxxxxxxxx>


Prarit Bhargava (2):
  kernel, timekeeping, add ktime_get_[boot|real|tai]_fast_ns functions
  printk, Add printk.clock kernel parameter

 include/linux/timekeeping.h |    3 +++
 kernel/printk/printk.c      |   54 +++++++++++++++++++++++++++++++++++++++++--
 kernel/time/timekeeping.c   |   52 +++++++++++++++++++++++++++++++++--------
 3 files changed, 97 insertions(+), 12 deletions(-)

-- 
1.7.9.3