FAQ Search Today's Posts Mark Forums Read
» Video Reviews

» Linux Archive

Linux-archive is a website aiming to archive linux email lists and to make them easily accessible for linux users/developers.


» Sponsor

» Partners

» Sponsor

Go Back   Linux Archive > Debian > Debian Kernel

 
 
LinkBack Thread Tools
 
Old 02-26-2009, 01:53 AM
Ben Hutchings
 
Default dmesg timestamps vs uptime

On Wed, 2009-02-25 at 20:47 -0500, Yaroslav Halchenko wrote:
> 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.
 
Old 02-26-2009, 03:06 AM
Yaroslav Halchenko
 
Default dmesg timestamps vs uptime

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

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


--
To UNSUBSCRIBE, email to debian-kernel-REQUEST@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
 
Old 02-27-2009, 12:43 AM
Ben Hutchings
 
Default dmesg timestamps vs uptime

On Wed, 2009-02-25 at 23:06 -0500, Yaroslav Halchenko wrote:
> 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.
 

Thread Tools




All times are GMT. The time now is 10:48 PM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.
Copyright 2007 - 2008, www.linux-archive.org