This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: timestamp problems
- From: "satya komaragiri" <satya dot komaragiri at gmail dot com>
- To: "Frank Ch. Eigler" <fche at redhat dot com>
- Cc: systemtap at sourceware dot org
- Date: Mon, 13 Oct 2008 15:58:01 +0530
- Subject: Re: timestamp problems
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=domainkey-signature:received:received:message-id:date:from:to :subject:cc:in-reply-to:mime-version:content-type :content-transfer-encoding:content-disposition:references; bh=9ucLvzbrvSluqrbN2yuy/b/RK6j/iSekK/NO8TH249M=; b=xW/qfiCdFzOR6/b4CDRItWiOk4PVfT+mGTBLfxELSPSeHnfgGPyT0LTwGIoffzV054 QSt39JdeSNusCrx7fRsKqW3iwBPxRZOHwxWbO+RpddseU/vO14mb/o7AFecdD4QfdK2P NKqsIoq1iW8teKn5v4JgftcbhKUZsw06353uo=
- Domainkey-signature: a=rsa-sha1; c=nofws; d=gmail.com; s=gamma; h=message-id:date:from:to:subject:cc:in-reply-to:mime-version :content-type:content-transfer-encoding:content-disposition :references; b=PMvJa8hW8oKTqNwHI6DDUv8mrbcHK6LC9Kw77wjiSBgHcqFflvxSH+SY5R7wX+mb5Q 4xkoKLO2Fx43SgHLr2SBmW+iKt3F67KRy7XpZ6C8i9GLqh9Zh8FADG5DnTfdJH3BhbDo Ltvl35SYXgANhP6JtOf9+Zed9of5RcJoYRLvo=
- References: <146c63b10810121336s4e38dec7hbb0c6c168a836988@mail.gmail.com> <y0mbpxppeg7.fsf@ton.toronto.redhat.com>
Hi
On Mon, Oct 13, 2008 at 5:13 AM, Frank Ch. Eigler <fche@redhat.com> wrote:
>
> That is "only" 0.229 days (20 million units if we're talking about
> milliseconds), but of course still unacceptable. (I'm assuming the
> main system clock does not jump similarly.)
>
Sorry for that.
> Can you try something like this:
>
> probe timer.s(10) { now=gettimeofday_ns()
> printf("systemtap %s %6d\n",ctime(now/1000000000),now%1000000000)
> system("date -u +\"system %a %b %d %H:%M:%S %Y %N\"")
> system("grep -i mhz /proc/cpuinfo") }'
>
> and watch for a divergence over time. The timer.s(NN) parameter could
> be changed to narrow in on a suspected trigger time.
I ran the script several times for different intervals and the
timestamps are working fine at normal time
just that the logging is weird at times.( not in the order that out
probe tells it to print)
snips from the outputs ( mainly showing the messed up logging at times.. )
cpu MHz : 3065.653
system Mon Oct 13 04:24:45 2008 408697424
systemtap Mon Oct 13 04:24:45 2008 389369690
systemtap Mon Oct 13 04:24:55 2008 389369783
system Mon Oct 13 04:24:55 2008 395816927
cpu MHz : 3065.653
systemtap Mon Oct 13 04:25:05 2008 389369404
system Mon Oct 13 04:25:05 2008 395788064
cpu MHz : 3065.653
systemtap Mon Oct 13 04:25:15 2008 389369407
system Mon Oct 13 04:25:15 2008 395763673
cpu MHz : 3065.653
.......
==============================
system Mon Oct 13 04:30:23 2008 725795912
cpu MHz : 3065.653
systemtap Mon Oct 13 04:30:23 2008 713991064
system Mon Oct 13 04:30:33 2008 717822396
cpu MHz : 3065.653
systemtap Mon Oct 13 04:30:33 2008 713992080
system Mon Oct 13 04:30:43 2008 725775669
.......
systemtap Mon Oct 13 04:32:13 2008 713990711
systemtap Mon Oct 13 04:32:23 2008 713993789
system Mon Oct 13 04:32:23 2008 729103889
cpu MHz : 3065.653
systemtap Mon Oct 13 04:32:33 2008 713992105
system Mon Oct 13 04:32:33 2008 725866561
cpu MHz : 3065.65
But when I run it at boot time (with some modifications)
i get
systemtap Mon Oct 13 14:42:16 2008 159315516
systemtap Mon Oct 13 14:42:17 2008 159315673
systemtap Mon Oct 13 14:42:18 2008 159315837
systemtap Mon Oct 13 14:42:19 2008 159316258
//(then jumps)
systemtap Mon Oct 13 09:12:20 2008 645426712
systemtap Mon Oct 13 09:12:21 2008 645426460
systemtap Mon Oct 13 09:12:22 2008 645426486
systemtap Mon Oct 13 09:12:23 2008 645426933
systemtap Mon Oct 13 09:12:24 2008 645426848
systemtap Mon Oct 13 09:12:25 2008 645426421
system Mon Oct 13 14:42:16 2008 195582695
system Mon Oct 13 14:42:17 2008 164907660
system Mon Oct 13 14:42:18 2008 162838435
system Mon Oct 13 14:42:19 2008 162789467
//(similar jump in system time too )
system Mon Oct 13 09:12:20 2008 649037391
system Mon Oct 13 09:12:21 2008 653586541
system Mon Oct 13 09:12:22 2008 653056695
system Mon Oct 13 09:12:23 2008 657430857
system Mon Oct 13 09:12:24 2008 656989129
system Mon Oct 13 09:12:25 2008 650496853
The time after the jump was the correct UTC time ( i had checked immediately)
I don't know if that's normal or is my clock messed up.
What I did:
Stp script:
probe timer.s(1)
{
now=gettimeofday_ns()
printf("systemtap %s %6d\n",ctime(now/1000000000),now%1000000000)
system("date -u +\"system %a %b %d %H:%M:%S %Y %N\" >> /debugout/sys.txt")
system("grep -i mhz /proc/cpuinfo")
}
===========================
mkdir /debugko
mkdir /debugout
chmod 777 /debugko
chmod 777 /debugout
(we'll only run it once for trial.. so no harm)
stap -k -g -p4 -m debug ./debug.stp
cp debug.ko /debugko/debug.ko
=============================
have a script in sbin
say /sbin/trial
contents of /sbin/trial
#!/bin/sh
# Use tmpfs to collect data, since root is still readonly
mount -n -t tmpfs -o size=5M none /debugout
# run as long until exit condition satisfied
# Start systemtap scriot & probe
/usr/bin/staprun /debugko/debug.ko -c 'sleep 10' -o /debugout/trial.txt &
# Give daemon time to start collecting...
sleep 3
# Hand off to real init
exec /sbin/init
===========================================
change the grub to include( copy pasting from my menu.lst)
title trial
root (hd0,2)
kernel /vmlinuz-2.6.25-14.fc9.i686 ro
root=UUID=be43b64a-bfa8-43fa-8c8d-cd9a036a3301 rhgb quiet
init=/sbin/trial
initrd /initrd-2.6.25-14.fc9.i686.img
=============================================
reboot into 'trial' open terminal to do a sleep 10 and the check in /debugout
Regards
Satya