Linux – Correlating /var/log/* timestamps

/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.