J <dreadpiratej...@gmail.com> wrote:
> Hi...
>
> I have a bit of code that does the following:
>
> uses the syslog module to inject a LOG_INFO message into the syslog on
> my linux machine
> runs a suspend/resume cycle
> uses the syslog module to inkect a LOG_INFO message marking the end of test.
>
> Then I parse everything between the start and stop markers for certain
> items that the Linux kernel logs during a suspend and resume cycle.
>
> But my "resume complete" timing is not as accurate as it could be.
> The problem with doing it this way is that while I can find definite
> kernel messages that mark various points in the suspend/resume cycle,
> the final message when the kernel is done resuming is NOT the point I
> actually want to mark.
>
> Instead, the end point I want is the time of the ending marker itself,
> as this happens after certain other things are done such as resumption
> of networking services.
>
> Here's the problem. I can't just use syslog timestamps. The reason
> is that the syslog timestamps are only indicative of when messages are
> written to syslog via syslogd. The kernel timestamps are different.
> For example, the following bits of log are taken from the time the
> test starts until the end of the "going to sleep" kernel messages.
> First, note that there's a 5 second difference between the START
> marker and the first kernel message. Next, look at the kernel
> timestamps. The total real time to suspend starts at 421320.380947
> and ends at 421322.386355, around 2 seconds later, where the log
> messages themselves all state that the events occurred at the same
> time.
>
> Oct 15 10:24:19 klaatu sleep_test: ---SLEEP TEST START 1350296656---
> Oct 15 10:25:24 klaatu kernel: [421320.380947] PM: Syncing filesystems ...
> done.
> Oct 15 10:25:24 klaatu kernel: [421320.391282] PM: Preparing system
> for mem sleep
> [SNIP]
> Oct 15 10:25:24 klaatu kernel: [421322.282943] Broke affinity for irq 23
> Oct 15 10:25:24 klaatu kernel: [421322.386355] CPU 7 is now offline
>
> So, what I REALLY want is to inject my start/stop markers into klogd
> rather than syslogd. This will, I hope, give my markers kernel
> timestamps rather than syslog timestamps which are not as accurate.
>
> So does anyone know of a way to do this? Unfortunately, I've tried
> some searching but google doesn't like the term klog, and most of the
> hits involved injecting code or other things that are not related at
> all.
>
> Or, if there's a better way to get accurate timestamps, what would that be?
Take a look at /dev/kmsg, I *believe* it's the way various boot
logging programs inject application type messages into the kernel boot
up message stream.
Jerry
--
http://mail.python.org/mailman/listinfo/python-list
