Re: Re: 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. signature.asc Description: This is a digitally signed message part
Re: dmesg timestamps vs uptime
I guess kernel/sched_clock.c gave me the answer to the 1st question... 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-kernel-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
Re: 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. signature.asc Description: This is a digitally signed message part
Re: Re: 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-requ...@lists.debian.org with a subject of unsubscribe. Trouble? Contact listmas...@lists.debian.org
