kernel printk timestamps not aligned to syslog time

Solution Unverified - Updated -

Environment

  • Red Hat Enterprise Linux 6.2 x86_64
  • Red Hat Enterprise Linux 5.8 x86_64

Issue

A simple test shows that the kernel printk timestamps are not in line with the system reported time.


[hostname ~]# echo "hey1" > /dev/kmsg;date;/sadmin/local/bin/dmesg_time.pl | tail -1
Mon May  7 23:36:03 CDT 2012
[2012-05-07 23:25:47]  hey1
[hostname ~]# cat /etc/issue
Red Hat Enterprise Linux Server release 6.2 (Santiago)
Kernel \r on an \m

As seen above we are off by 10 seconds.

Resolution

If high resolution time stamping is required in custom modules, attempt to use the internal do_gettimeofday call instead of reading the TSC. The TSC is not accurate in all conditions, and can cause unexpected behavior in situations where a process could be migrated between CPUs.

It may be be possible to work around this problem by setting "tsc_disable" (not a boot parameter) by systemtap or kernel module.

Enable dmesg timestamps

Root Cause

The timestamp in the kernel printk is generated by looking at the CPU TSC (time stamp counters) on the CPU that is being run. The TSC is notoriously unreliable in CPU's with powersaving/overclock modes, although somewhat more reliable on newer Intel systems.

The TSC used to be consistent and reliable but its not what it used to be. The only thing that the TSC is guaranteed to do is increase monotonically, but not consistently (And there is a TSC per CPU! so if you run two commands across two different cpus, the counter could appear to go backwards)

If the driver needs the "correct" time, the do_gettimeofday function is what they should be using. This function doesn't tell the current day of the week or anything like that; rather, it fills a struct timeval pointer -- the same as used in the gettimeofday system call -- with the usual seconds and microseconds values. The prototype for do_gettimeofday is:

#include <linux/time.h>
void do_gettimeofday(struct timeval *tv);

Using this method instead of the TSC value is probably more in-line with what the requirements are, however this may not be in-line with their use case.

Messages are generated for dmesg via the printk kernel function, the printk fills a buffer which is read by dmesg.

# asmlinkage int printk(const char *fmt, ...)

This calls vprintk.

vprintk contains:


                        if (printk_time) {
                                /* Follow the token with the time */
                                char tbuf[50], *tp;
                                unsigned tlen;
                                unsigned long long t;
                                unsigned long nanosec_rem;

                                t = cpu_clock(printk_cpu);
                                nanosec_rem = do_div(t, 1000000000);
                                tlen = sprintf(tbuf, "[%5lu.%06lu] ",
                                                (unsigned long) t,
                                                nanosec_rem / 1000);

                                for (tp = tbuf; tp < tbuf + tlen; tp++)
                                        emit_log_char(*tp);
                                printed_len += tlen;
                        }

We can see that this is dependent on the printk_cpu, which is the current CPU that is doing the printk. This may not be the same CPU that is generating other time values, for other messages, including other printk's. This may be why things seem so "wild".

References:

Wikipedia - Time Stamp Counter

Warning: The above link is to a source that are not authored by Red Hat directly. As such, Red Hat support cannot verify its accuracy and content.

Diagnostic Steps

Enable kernel timestamps following the kcs article below.

Test will perl script provided below

[hostname ~]# echo "hey1" > /dev/kmsg;date;/sadmin/local/bin/dmesg_time.pl | tail -1
Mon May  7 23:36:03 CDT 2012
[2012-05-07 23:25:47]  hey1

[shadowman@pearl ~]$ cat dmesg_time.pl 
#!/usr/bin/perl

$uptime = `cat /proc/uptime | awk '{print $1}';`;
$boot = time() - $uptime;
chomp $boot;
while (<STDIN>) {
        if ($_ =~ /^\[([\s\d\.]+)\]/) {
                $time_offset = $1;
        }
        $real_time = sprintf scalar localtime($boot + $time_offset);
        $_ =~ s/\[[\s\d\.]+\]/\[$real_time\]/;
        print $_;
}

or using a bash script

[root@localhost ~]# echo "hey7777" > /dev/kmsg;date "+%Y%m%d %H:%M:%S";sh timestamp_dmesg.sh | tail -1
20120508 21:48:33
20120508 21:48:41  hey7777
[root@localhost ~]# uname -a
Linux localhost.localdomain 2.6.18-238.19.1.el5 #1 SMP Sun Jul 10 08:43:41 EDT 2011 x86_64 x86_64 x86_64 GNU/Linux

#!/bin/bash 

current_epoch=$(date +%s)
uptime=$(cat /proc/uptime | awk '{print $1}')

boot_start_epoch=$(echo "$current_epoch - $uptime" | bc)
boot_start_timestamp=$(date -d "1970-01-01 ${boot_start_epoch} sec GMT" "+%Y%m%d %H:%M:%S")

#echo $boot_start_timestamp

dmesg > /tmp/dmesg
while read line
do
  time_line="$(echo $line | awk '/^\[/ { print $0 }')"
  if [ -z "$time_line" ]
  then
     echo $line
  else
     #hack here
     #echo "hey7777" > /dev/kmsg;date "+%Y%m%d %H:%M:%S";sh timestamp_dmesg.sh | tail -1
     if [[ "$time_line" == *"hey7777"* ]]
     then
       boot_epoch=$(echo $time_line | awk -F'[' '{print $2}' | awk -F']' '{ print $1 }')
     else
       boot_epoch=$(echo $time_line | awk -F']' '{print $1}' | awk '{ print $2 }')
     fi
     post_boot_epoch=$(echo "$boot_start_epoch + $boot_epoch" | bc)
     post_boot_timestamp=$(date -d "1970-01-01 ${post_boot_epoch} sec GMT" "+%Y%m%d %H:%M:%S")
     verbage=$(echo $time_line | awk -F']' '{print $2}')

     echo "$post_boot_timestamp $verbage"
  fi
done < /tmp/dmesg

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments