From: "Rob Donovan" <rob@proivrc.com>
To: <systemtap@sourceware.org>
Subject: RE: gettimeofday_ns accuracy
Date: Fri, 01 Oct 2010 12:44:00 -0000 [thread overview]
Message-ID: <002c01cb6166$78d981b0$6a8c8510$@proivrc.com> (raw)
Hi,
I've tested this on the latest snapshot (systemtap-20100925), and it's still
a problem.
Is anyone particularly looking into this or do you need any more info or
anything from me?
Has anyone been able to reproduce it, or is it just me?
Thanks,
Rob.
> -----Original Message-----
> From: Rob Donovan [mailto:rob@proivrc.com]
> Sent: 05 September 2010 17:47
> To: 'Steve Fink'
> Cc: 'Frank Ch. Eigler'; 'systemtap@sourceware.org'
> Subject: RE: gettimeofday_ns accuracy
>
> Hi,
>
> Well, I've done some more testing...
>
> I turned off Power management (by putting "apm=off acpi=off" in
> /etc/grub.conf and rebooting).
>
> GHz still showed 1400, and now gettimeofday_s() always returns '0'.
>
> I don't think that has anything to do with the bug mind you, because the
> other machine I try it on at work doesn't show the GHz incorrectly, and I
still
> get the problem on that computer also, but as I said, only on RHEL6 not
> RHEL5.
>
> One thing I didn't say, is that this problem seems to get worse when lots
of
> processes are running or starting, so once the script has started if you
also
> run 2 commands to create processes, something like..... watch -n 0 "ps
aux |
> grep stap"
>
> Once the stap script is running, I get some of the messages that the time
has
> gone backwards by 1 second, but then as I said after a while it then
starts
> reporting that the difference is many hours.
>
> One thing I've noticed, is that when it does jump to the difference that
is hrs,
> the time that it reports instead of the correct time, is the time that the
script
> started! And then it just gets higher.
>
> Also, when it was reporting 1 second diff, the 'last time' was always on
CPU 3
> mostly, sometimes on 1, and the 'now' time was always on CPU 0 or 2.
Exactly
> when it starts showing a diff of 1hr or more, it switches to the 'last
time' on
> CPU 2 or 0, and the 'now' time on CPU 3 or 1.... not sure if that is
relevant or
> not...
>
> Below is new output, with the CPU field for the 2 times...
>
> Started at Sun Sep 5 14:55:28 2010
> proc_exec: Oh dear, last time was Sun Sep 5 14:55:54 2010 (CPU=3) but now
> its Sun Sep 5 14:55:53 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:55:56 2010 (CPU=3) but now
> its Sun Sep 5 14:55:55 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:03 2010 (CPU=3) but now
> its Sun Sep 5 14:56:02 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:07 2010 (CPU=3) but now
> its Sun Sep 5 14:56:06 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:09 2010 (CPU=3) but now
> its Sun Sep 5 14:56:08 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:52 2010 (CPU=3) but now
> its Sun Sep 5 14:56:51 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:53 2010 (CPU=3) but now
> its Sun Sep 5 14:56:52 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:56:55 2010 (CPU=3) but now
> its Sun Sep 5 14:56:54 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:00 2010 (CPU=3) but now
> its Sun Sep 5 14:56:59 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:02 2010 (CPU=3) but now
> its Sun Sep 5 14:57:01 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:04 2010 (CPU=3) but now
> its Sun Sep 5 14:57:03 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:08 2010 (CPU=1) but now
> its Sun Sep 5 14:57:07 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:18 2010 (CPU=3) but now
> its Sun Sep 5 14:57:17 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 14:57:23 2010 (CPU=3) but now
> its Sun Sep 5 14:57:22 2010 (CPU=0) ....
> ....
> ....
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=3) but now
> its Sun Sep 5 16:17:48 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=3) but now
> its Sun Sep 5 16:17:48 2010 (CPU=2)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=3) but now
> its Sun Sep 5 16:17:48 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=3) but now
> its Sun Sep 5 16:17:48 2010 (CPU=0)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=1) but now
> its Sun Sep 5 14:55:28 2010 (CPU=3) <- this is where it starts back to
the time
> the scripts starts!
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:48 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:48 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=0) but now
> its Sun Sep 5 14:55:28 2010 (CPU=3)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:28 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:29 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:49 2010 (CPU=2) but now
> its Sun Sep 5 14:55:29 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:29 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:29 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:29 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:50 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=0) but now
> its Sun Sep 5 14:55:30 2010 (CPU=3)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=0) but now
> its Sun Sep 5 14:55:30 2010 (CPU=3)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:30 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:31 2010 (CPU=3)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:31 2010 (CPU=3)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:31 2010 (CPU=1)
> proc_exec: Oh dear, last time was Sun Sep 5 16:17:51 2010 (CPU=2) but now
> its Sun Sep 5 14:55:31 2010 (CPU=1)
>
> -----Original Message-----
> From: systemtap-owner@sourceware.org [mailto:systemtap-
> owner@sourceware.org] On Behalf Of Steve Fink
> Sent: 03 September 2010 17:58
> To: Rob Donovan
> Cc: Frank Ch. Eigler; systemtap@sourceware.org
> Subject: Re: gettimeofday_ns accuracy
>
> On Fri, Sep 3, 2010 at 1:56 AM, Rob Donovan <rob@proivrc.com> wrote:
> > 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.
>
> Just speculating - does it still happen if you turn off power management?
>
> Your output says the CPU is a 3.73GHz machine running at 1.4GHz, which I
> think means you have frequency scaling happening. I'm wondering if the
> larger differences are from CPUs getting completely shut down for a while
or
> something.
>
> Can you print out the CPU ids in the output as well?
next reply other threads:[~2010-10-01 12:44 UTC|newest]
Thread overview: 6+ messages / expand[flat|nested] mbox.gz Atom feed top
2010-10-01 12:44 Rob Donovan [this message]
-- strict thread matches above, loose matches on Subject: below --
2010-08-07 17:02 Rob Donovan
2010-08-07 21:53 ` Frank Ch. Eigler
2010-09-03 8:56 ` Rob Donovan
2010-09-03 16:58 ` Steve Fink
2010-09-05 16:46 ` Rob Donovan
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to='002c01cb6166$78d981b0$6a8c8510$@proivrc.com' \
--to=rob@proivrc.com \
--cc=systemtap@sourceware.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).