RE: gettimeofday_ns accuracy

["Rob Donovan" <rob at proivrc dot com>]

Hi,

Sorry for the delay...

I think I've got a worse problem now with gettimeofday now.

If you run a script for a long time, it seems that the gettimeofday_s()
sometimes goes backwards by 1 second. And if you leave it running for 30
minutes (or up to 2 hrs sometimes) then some probes are returning with the
time 2-3 hrs ago.

I have the following script below, and if you start it, it will start off
with just a few errors of 1 second, but if you leave it running, it will get
worse and worse.

I've also included some of the output.

Now, this doesn't seem to happen on a RHEL5 kernel, but it does on RHEL6
Beta and also on Fedora (2.6.33.6-147.2.4.fc13.i686)

All the machines I've tried it on are multi CPU machines.

Sometimes its specific probes, like 'kprocess.exec' and sometimes it happens
with the 'timer.ms' one all the time. It seems random.

The RHEL5 & RHEL6 systems are on the same hardware, but dual boot.

Versions & machine info:

Fedora Machine:

[robdon@BlackSun ~ 09:50:27]$ stap -V
SystemTap translator/driver (version 1.3/0.148 non-git sources)
Copyright (C) 2005-2010 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR
TR1_UNORDERED_MAP

uname: Linux BlackSun 2.6.33.6-147.2.4.fc13.i686 #1 SMP Fri Jul 23 17:27:40
UTC 2010 i686 i686 i386 GNU/Linux

I have 4 CPUs, all like this:

[robdon@BlackSun ~ 09:47:36]$ cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 15
model           : 6
model name      : Intel(R) Pentium(R) D CPU 3.73GHz
stepping        : 4
cpu MHz         : 1400.000
cache size      : 2048 KB
physical id     : 0
siblings        : 4
core id         : 0
cpu cores       : 2
apicid          : 0
initial apicid  : 0
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 6
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov
pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe lm constant_tsc
pebs bts pni dtes64 monitor ds_cpl vmx cid cx16 xtpr pdcm lahf_lm tpr_shadow
bogomips        : 7465.81
clflush size    : 64
cache_alignment : 128
address sizes   : 36 bits physical, 48 bits virtual
power management:

RHEL6 Machine:

[cscrodo@xxxxxx rob]$ /usr/local/systap-releases/systemtap-1.3/bin/stap -V
SystemTap translator/driver (version 1.3/0.147 non-git sources)
Copyright (C) 2005-2010 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: TR1_UNORDERED_MAP

uname: Linux xxxxxxxxx 2.6.32-37.el6.x86_64 #1 SMP Sun Jun 20 19:29:35 EDT
2010 x86_64 x86_64 x86_64 GNU/Linux

This machine has 7 CPUS:

processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 16
model           : 4
model name      : Quad-Core AMD Opteron(tm) Processor 2384
stepping        : 2
cpu MHz         : 2671.732
cache size      : 512 KB
physical id     : 0
siblings        : 4
core id         : 0
cpu cores       : 4
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 5
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov
pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb
rdtscp lm 3dnowext 3dnow constant_tsc rep_good nonstop_tsc extd_apicid pni
monitor cx16 popcnt lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a
misalignsse 3dnowprefetch osvw ibs skinit wdt npt lbrv svm_lock nrip_save
bogomips        : 5399.90
TLB size        : 1024 4K pages
clflush size    : 64
cache_alignment : 64
address sizes   : 48 bits physical, 48 bits virtual
power management: ts ttp tm stc 100mhzsteps hwpstate



Script:

global last_time

probe begin
{
  mytime = gettimeofday_s()
  printf("Started at %s\n",ctime(mytime))
}

probe kprocess.exec
{
  mytime = gettimeofday_s()

  if (mytime < last_time)
  {
    printf("proc_exec: Oh dear, last time was %s but now its %s\n",
ctime(last_time), ctime(mytime))
  }

  last_time = mytime
}

probe timer.ms(10000)
{
  mytime = gettimeofday_s()

  if (mytime < last_time)
  {
    printf("timer: Oh dear, last time was %s but now its %s\n",
ctime(last_time), ctime(mytime))
  }

  last_time = mytime
}

Output:

Started at Thu Sep  2 20:08:44 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:00:02 2010 but now its Thu
Sep  2 21:00:01 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:01:02 2010 but now its Thu
Sep  2 21:01:01 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:10:02 2010 but now its Thu
Sep  2 21:10:01 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:20:02 2010 but now its Thu
Sep  2 21:20:01 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:30:02 2010 but now its Thu
Sep  2 21:30:01 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:40:01 2010 but now its Thu
Sep  2 20:17:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:45:04 2010 but now its Thu
Sep  2 20:22:52 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:49:48 2010 but now its Thu
Sep  2 20:27:28 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:49:56 2010 but now its Thu
Sep  2 20:27:36 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:49:56 2010 but now its Thu
Sep  2 20:27:36 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:49:57 2010 but now its Thu
Sep  2 20:27:37 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:49:57 2010 but now its Thu
Sep  2 20:27:37 2010
proc_exec: Oh dear, last time was Thu Sep  2 21:50:01 2010 but now its Thu
Sep  2 20:27:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:00:01 2010 but now its Thu
Sep  2 20:37:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:01:01 2010 but now its Thu
Sep  2 20:38:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:01:01 2010 but now its Thu
Sep  2 20:38:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:06:44 2010 but now its Thu
Sep  2 20:44:28 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:10:01 2010 but now its Thu
Sep  2 20:47:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:17:24 2010 but now its Thu
Sep  2 20:55:06 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:20:01 2010 but now its Thu
Sep  2 20:57:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:30:01 2010 but now its Thu
Sep  2 21:07:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:40:01 2010 but now its Thu
Sep  2 21:17:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:50:01 2010 but now its Thu
Sep  2 21:27:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 22:53:01 2010 but now its Thu
Sep  2 21:30:41 2010
proc_exec: Oh dear, last time was Thu Sep  2 23:00:01 2010 but now its Thu
Sep  2 20:15:20 2010
....
....

Thanks for any help,

Rob.

-----Original Message-----
From: systemtap-owner@sourceware.org [mailto:systemtap-owner@sourceware.org]
On Behalf Of Frank Ch. Eigler
Sent: 07 August 2010 22:54
To: Rob Donovan
Cc: systemtap@sourceware.org
Subject: Re: gettimeofday_ns accuracy

"Rob Donovan" <rob@proivrc.com> writes:

> Is there any other kind of time measure other than gettimeofday_ns()?

There is also get_cycles() after the epolymous kernel function.

> Since gettimeofday_ns is not that accurate, and has the possibility
> (and does) sometimes go backwards in time.

Can you describe your system (CPU models, kernel versions) a little
more?  We may be able to use/expose other time sources too, or help
you write the bit of code that would do so.

- FChE