/var/log/syslog, and some other log files use a timestamp which contains an absolute time, like
Jan 13 14:13:10.
/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?
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.
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.
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
rel_time is the kernel timestamp.
rel_offset is the difference between
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.
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.