/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.
sort
, have year, timezone, etc. +1 for the python script.Freezing user space processes
which is clearly done before sleep.[12345.6789]..
) emitted by the kernel, so it's doing things correctly, subject to the issues addressed by my last comment. I'm not sure what the kernel should really be doing here; it depends on what those startup-relative timestamps are meant to indicate. Running time (as opposed to time since boot) may be meaningful in some contexts. I guess ideally there would be a reliable record of both of those values.