dmesg timestamps vs uptime
Yaroslav Halchenko
doesn't gimme rest. One of the problem of analysis of traces is that
some times are recorded since epoch, some are the kernel's "uptime".
what puzzles me is:
* Difference between dmesg timestamp and /proc/uptime
$> tcpdump -i bond0 -tt -vvv -n "(dst host raider or src host raider)" -s 192 | head -3; dmesg | tail -1; echo "/proc/uptime"; cat /proc/uptime
...
[250851.259481] device eth1 left promiscuous mode
/proc/uptime
241764.70 224706.33
so I have timestamp in kernel messages bigger than uptime
I wonder why is that? different clock source? any other drift?
or may be 'kernel time' in dmesg is some kind of tick, not time per se?
* Is there an easy way to convert (reliably ;)) timestamp in dmesg to
time since epoch (with mksec precision of cause), so I could easily compare
with output in strace and alike.
Thanks in advance!!!!
--
Yaroslav Halchenko
Research Assistant, Psychology Department, Rutgers-Newark
Student Ph.D. @ CS Dept. NJIT
Office: (973) 353-1412 | FWD: 82823 | Fax: (973) 353-1171
101 Warren Str, Smith Hall, Rm 4-105, Newark NJ 07102
WWW: http://www.linkedin.com/in/yarik
Yaroslav Halchenko
even answered why I saw some timestamps jumping backwards while I was
monitoring debug msgs of RPC + NFS , I guess they came from different
CPUs
now I wonder if there is a tool which would "work" along some other
process and monitor those 'semi stable' clocks so later on provide more
or less reliable and consistent conversion into time since epoch.
On Wed, 25 Feb 2009, Yaroslav Halchenko wrote:
> * Difference between dmesg timestamp and /proc/uptime
> * Is there an easy way to convert (reliably ;)) timestamp in dmesg to
> time since epoch (with mksec precision of cause), so I could easily compare
> with output in strace and alike.
> Thanks in advance!!!!
--
Yaroslav Halchenko
Ph.D. Student CS Dept. NJIT
--
To UNSUBSCRIBE, email to debian-ker...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Ben Hutchings
> My today reported (and reassigned to linux2.6) bug #517122
> doesn't gimme rest. One of the problem of analysis of traces is that
> some times are recorded since epoch, some are the kernel's "uptime".
> what puzzles me is:
>
> * Difference between dmesg timestamp and /proc/uptime
>
> $> tcpdump -i bond0 -tt -vvv -n "(dst host raider or src host raider)" -s 192 | head -3; dmesg | tail -1; echo "/proc/uptime"; cat /proc/uptime
> ...
> [250851.259481] device eth1 left promiscuous mode
> /proc/uptime
> 241764.70 224706.33
>
> so I have timestamp in kernel messages bigger than uptime
>
> I wonder why is that? different clock source? any other drift?
Different clock source.
> or may be 'kernel time' in dmesg is some kind of tick, not time per se?
It's a scheduler timestamp, which is an approximation to real time but
due to internal requirements of the scheduler may run slightly fast.
Timestamps in the kernel log help to show how close together events
occurred, but nothing more.
> * Is there an easy way to convert (reliably ;)) timestamp in dmesg to
> time since epoch (with mksec precision of cause), so I could easily compare
> with output in strace and alike.
Not really, but you can get a scheduler timestamp from
/proc/sched_debug which may help in correlating them.
Ben.
Yaroslav Halchenko
Thanks -- that is a nice pointer (i.e. /proc/sched_debug), but I still
can't match everything up in my mind... could you gimme a little hint?
I guess the .clock (in sched_debug) is the interesting one, but it
doesn't match up to the "time" reported by the kernel...
$> sudo tcpdump -i bond0 -tt -vvv -n "(dst host raider or src host raider)" -s 192 | head -3; dmesg | tail -1; grep -e 'now' -e '\.clock' /proc/sched_debug ; echo -n "date :"; date +'%s.%N'; echo -n "uptime:"; cat /proc/uptime
1235620965.207560 IP (tos 0x0, .....
...
[259941.257724] device eth1 left promiscuous mode
now at 250362660.852703 msecs
.clock : 250362660.973307
.clock : 250362661.008877
....
date :1235620965.387909070
uptime:250362.67 232514.99
so indeed /proc/uptime is close (or is) what is in .clock in sched_debug,
but how could I get those 259941.257724? I am sorry if that is
something obvious and RTFM
--
Yaroslav Halchenko
Research Assistant, Psychology Department, Rutgers-Newark
Student Ph.D. @ CS Dept. NJIT
Office: (973) 353-1412 | FWD: 82823 | Fax: (973) 353-1171
101 Warren Str, Smith Hall, Rm 4-105, Newark NJ 07102
WWW: http://www.linkedin.com/in/yarik
Ben Hutchings
> Hi Ben,
>
> Thanks -- that is a nice pointer (i.e. /proc/sched_debug), but I still
> can't match everything up in my mind... could you gimme a little hint?
>
> I guess the .clock (in sched_debug) is the interesting one, but it
> doesn't match up to the "time" reported by the kernel...
>
> $> sudo tcpdump -i bond0 -tt -vvv -n "(dst host raider or src host raider)" -s 192 | head -3; dmesg | tail -1; grep -e 'now' -e '\.clock' /proc/sched_debug ; echo -n "date :"; date +'%s.%N'; echo -n "uptime:"; cat /proc/uptime
> 1235620965.207560 IP (tos 0x0, .....
> ...
> [259941.257724] device eth1 left promiscuous mode
> now at 250362660.852703 msecs
> .clock : 250362660.973307
> .clock : 250362661.008877
> ....
> date :1235620965.387909070
> uptime:250362.67 232514.99
>
> so indeed /proc/uptime is close (or is) what is in .clock in sched_debug,
> but how could I get those 259941.257724? I am sorry if that is
> something obvious and RTFM
Sorry, I thought the clocks shown in sched_debug matched the log
timestamps, but I was wrong. I think the divergence is a result of
cross-processor interactions, and my machine only has a single
processor.
Grepping the kernel source suggests that there is currently no way to
read the current value of the clock used by printk from user-space. If
you are prepared to write a kernel module then you can get the value in
nanoseconds for a particular CPU using cpu_clock(cpu_id).
Ben.