timestamp problems

[satya komaragiri]

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