Correlating /var/log/* timestamps

Question

/var/log/messages, /var/log/syslog, and some other log files use a timestamp which contains an absolute time, like Jan 13 14:13:10.

/var/log/Xorg.0.log and /var/log/dmesg, as well as the output of $ dmesg, use a format that looks like

[50595.991610] malkovich: malkovich malkovich malkovich malkovich

I'm guessing/gathering that the numbers represent seconds and microseconds since startup.

However, my attempt to correlate these two sets of timestamps (using the output from uptime) gave a discrepancy of about 5000 seconds.

This is roughly the amount of time my computer was suspended for.

Is there a convenient way to map the numeric timestamps used by dmesg and Xorg into absolute timestamps?

update

As a preliminary step towards getting this figured out, and also to hopefully make my question a bit more clear, I've written a Python script to parse /var/log/syslog and output the time skew. On my machine, running ubuntu 10.10, that file contains numerous kernel-originated lines which are stamped both with the dmesg timestamp and the syslog timestamp. The script outputs a line for each line in that file which contains a kernel timestamp.

Usage:

python syslogdriver.py /var/log/syslog | column -nts $'\t'

Expurgated output (see below for column definitions):

abs              abs_since_boot  rel_time      rel_offset  message
Jan 13 07:49:15  32842.1276569   32842.301498  0           malkovich malkovich

... rel_offset is 0 for all intervening lines ...

Jan 13 09:55:14  40401.1276569   40401.306386  0           PM: Syncing filesystems ... done.
Jan 13 09:55:14  40401.1276569   40401.347469  0           PM: Preparing system for mem sleep
Jan 13 11:23:21  45688.1276569   40402.128198  -5280       Skipping EDID probe due to cached edid
Jan 13 11:23:21  45688.1276569   40402.729152  -5280       Freezing user space processes ... (elapsed 0.03 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.760110  -5280       Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
Jan 13 11:23:21  45688.1276569   40402.776102  -5280       PM: Entering mem sleep

... rel_offset is -5280 for all remaining lines ...

Jan 13 11:23:21  45688.1276569   40403.149074  -5280       ACPI: Preparing to enter system sleep state S3
Jan 13 11:23:21  45688.1276569   40403.149477  -5280       PM: Saving platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Disabling non-boot CPUs ...
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       Back to C!
Jan 13 11:23:21  45688.1276569   40403.149495  -5280       PM: Restoring platform NVS memory
Jan 13 11:23:21  45688.1276569   40403.151034  -5280       ACPI: Waking up from system sleep state S3

... The final lines are from a bit further down, still well above the end of the output. Some of them presumably got written to dmesg's circular buffer before the suspend happened, and were only propagated to syslog afterwards. This explains why all of them have the same syslog timestamp.

Column definitions:

abs is the time logged by syslog.

abs_since_boot is that same time in seconds since system startup, based on the contents of /proc/uptime and the value of time.time().

rel_time is the kernel timestamp.

rel_offset is the difference between abs_since_boot and rel_time. I'm rounding this to the tens of seconds so as to avoid one-off errors due to the absolute (i.e. syslog-generated) timestamps only having seconds precision. That's actually not the right way to do it, since it really (I think..) just results in a smaller chance of having an off-by-10 error. If somebody has a better idea, please let me know.

I also have some questions about syslog's date format; in particular, I'm wondering if a year ever shows up in it. I'm guessing no, and in any case could most likely help myself to that information in TFM, but if somebody happens to know it would be useful. ..Assuming, of course, that someone uses this script at some point in the future, instead of just busting out a couple of lines of Perl code.

Next:

So unless some welcome revelation is unto me given by one of You, my next step will be to add a function to get the time skew for a given kernel timestamp. I should be able to feed the script one or a set of syslogs, along with a kernel timestamp, to get an absolute timestamp. Then I can get back to debugging my Xorg issues, which escape me at the moment.

Answer 1

Interesting problem, Not sure I've ever tried to do this. But I have notice the timestamp you are talking about and I have always belived it to be seconds since bootup.

In my syslog I have on my server, I have:

Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpuset
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Initializing cgroup subsys cpu
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Linux version 2.6.32-21-server (buildd@yellow) (gcc version 4.4.3 (Ubuntu 4.4.3-4ubuntu5) ) #32-Ubuntu SMP Fri Apr 16     09:17:34 UTC 2010 (Ubuntu 2.6.32-21.32-server 2.6.32.11+drm33.2)
Jan 10 19:58:55 wdgitial kernel: [    0.000000] Command line:  root=/dev/xvda1 ro quiet splash

I would imagine this is fairly consistent among most Linux distro's as this is the kernel spitting out it's stuff.

And here I have the date along with the timestamp.

Answer 2

You can give this a try :

First, get the timestamp of the dmesg file (my assumption is this will be dmesg's time 0). You'll use

ls -l --time-style=+%s

/var/log$ ls -l --time-style=+%s dmesg
-rw-r----- 1 root adm 56181 1294941018 dmesg

You can convert the seconds into a human-readable date with

perl -e 'print scalar localtime(1294941018)' 

So to see a readable event time, add in the seconds from the event in dmesg. If the dmesg event was 55.290387 seconds in, add 55 or 55.290387 :

perl -e 'print scalar localtime(1294953978 + 55)'

Another way to transform epochal-rooted seconds into readable time is to use date -d as suggested. If you tell 'date' to represent a time supplied with -d , you can indicate that the time to be converted is in seconds-since-the-epoch by using @ .

date -d "@1294953978"

This gives you something like "Thu Jan 13 15:26:18 CST 2011" as output.

date +%s

will print the current time in the seconds-since-epoch format.

I can't remember how to do shell math, so I typically use the perl method as above. :)

Answer 3

The easiest way to map the number from dmesg to a date is using the date program.

date -d "-50595 seconds"

This command displays the date for the current time minus 50595 seconds.

From man date:

-d, --date=STRING
       display time described by STRING, not `now'

The number equals the powered-on time, not the time elapsed since boot time.

Answer 4

Since you noted the time skew changing during suspend/resume, I'll note this is documented in at least one place. The dmesg(1) man page says:

The time source used for the logs is not updated after system SUSPEND/RESUME.

I couldn't find a way to make the kernel keep these timestamps in sync with wall time.

Answer 5

Quick, dirty, works.

$ dmesg | grep 3w | perl /root/print_time_offset.pl

Contents of that script:

$ cat /root/print_time_offset.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 $_;
}

Sample output is as follows:

[Mon Feb 21 23:06:33 2011] 3ware 9000 Storage Controller device driver for Linux v2.26.02.012.
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[Mon Feb 21 23:06:33 2011] 3w-9xxx 0000:03:00.0: setting latency timer to 64
[Mon Feb 21 23:06:33 2011] scsi4 : 3ware 9000 Storage Controller
[Mon Feb 21 23:06:33 2011] 3w-9xxx: scsi4: Found a 3ware 9000 Storage Controller at 0xfbcde000, IRQ: 16.
[Mon Feb 21 23:06:34 2011] 3w-9xxx: scsi4: Firmware FE9X 4.08.00.006, BIOS BE9X 4.08.00.001, Ports: 4.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Mon Feb 21 23:06:35 2011] 3w-9xxx: scsi4: ERROR: (0x03:0x0101): Invalid command opcode:opcode=0x85.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Feb 26 02:01:01 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Feb 26 16:49:13 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Feb 26 17:07:19 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar  5 02:00:16 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.
[Sat Mar  5 18:48:57 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=1.
[Sat Mar  5 19:05:17 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x002B): Verify completed:unit=0, subunit=0.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=1.
[Sat Mar 12 02:00:30 2011] 3w-9xxx: scsi4: AEN: INFO (0x04:0x0029): Verify started:unit=0, subunit=0.