time.clock() going backwards??

[Giovanni Bajo]

Hello,

I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes (randomically)
returning a floating point value which was "less than" the value returned by
the previous invokation. The computer was a pretty fast one (P4 3Ghz I think,
running Windows XP), and this happened only between very close invokations of
time.clock().

I have triple-verified this, including printing the repr() of the floating
point number and verifying it was really minor than the previous value by a few
microseconds. In other words, I'm absolutely positive that it's not a mistake
on my side, but that time.clock() was really apparently "jumping backward".
This was confusing the hell out of my application, of course, and I just hacked
it so to ignore these bogus reads, and just reading off again. Since the error
was just of a few microseconds, reading time.clock() again produces a number
which was higher than what I had before, and thus OK for my application.

I was wondering if someone had experimented this behaviour before. I tried
googling but to no effect. Is it possible this to be a bug in Python itself
(maybe, shooting at the moon, in the conversion between the 64bit performance
counter and the floating point representation returned by time.clock()), or
could it be a bug in Windows itself or the mother board drivers (buf if so,
wouldn't other application start going mad)?
--
Giovanni Bajo

[Michiel Sikma]

Op 25-aug-2006, om 16:13 heeft Giovanni Bajo het volgende geschreven:

Hello,

Is it possible this to be a bug in Python itself
(maybe, shooting at the moon, in the conversion between the 64bit
performance
counter and the floating point representation returned by time.clock
()), or
could it be a bug in Windows itself or the mother board drivers
(buf if so,
wouldn't other application start going mad)?
--
Giovanni Bajo

Very interesting! While I couldn't possibly know the answer to this,
I do wonder which version of Python you were using. Is it the
bleeding edge 2.5 release candidate?

Michiel

[K.S.Sreeram]

Giovanni Bajo wrote:

Hello,

I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes (randomically)
returning a floating point value which was "less than" the value returned by
the previous invokation. The computer was a pretty fast one (P4 3Ghz I think,
running Windows XP), and this happened only between very close invokations of
time.clock().

I have triple-verified this, including printing the repr() of the floating
point number and verifying it was really minor than the previous value by a few
microseconds. In other words, I'm absolutely positive that it's not a mistake
on my side, but that time.clock() was really apparently "jumping backward".
This was confusing the hell out of my application, of course, and I just hacked
it so to ignore these bogus reads, and just reading off again. Since the error
was just of a few microseconds, reading time.clock() again produces a number
which was higher than what I had before, and thus OK for my application.

I was wondering if someone had experimented this behaviour before. I tried
googling but to no effect. Is it possible this to be a bug in Python itself
(maybe, shooting at the moon, in the conversion between the 64bit performance
counter and the floating point representation returned by time.clock()), or
could it be a bug in Windows itself or the mother board drivers (buf ifso,
wouldn't other application start going mad)?

From the MSDN docs for QueryPerformanceCounter:

Remarks:
On a multiprocessor computer, it should not matter which processor is
called. However, you can get different results on different processors
due to bugs in the basic input/output system (BIOS) or the hardware
abstraction layer (HAL). To specify processor affinity for a thread, use
the SetThreadAffinityMask function.

Are you running on a multi-core or a multi-processor machine?

The best way to handle this is probably to make your application
'tolerant' to such cases.

[sreeram;]
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.2.2 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFE7yhsrgn0plK5qqURAp1sAJ9mOO0UbZUhjZQsjew3ro LGQHUabACgvwCJ
I8wDMKiuL2xF/dY7d2b1ccA=
=hRd5
-----END PGP SIGNATURE-----

[Terry Reedy]

"Giovanni Bajo" <no***@sorry.comwrote in message
news:vk********************@twister2.libero.it...

Hello,

I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically)
returning a floating point value which was "less than" the value returned
by
the previous invokation. The computer was a pretty fast one (P4 3Ghz I
think,
running Windows XP), and this happened only between very close
invokations of
time.clock().

I seem to remember this being mentioned before on the list, perhaps by Tim
Peters. Perhaps he will chime in.

tjr

[Claudio Grondi]

Terry Reedy wrote:

"Giovanni Bajo" <no***@sorry.comwrote in message
news:vk********************@twister2.libero.it...

>>Hello,

I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically)
returning a floating point value which was "less than" the value returned
by
the previous invokation. The computer was a pretty fast one (P4 3Ghz I
think,
running Windows XP), and this happened only between very close
invokations of
time.clock().

I seem to remember this being mentioned before on the list, perhaps by Tim
Peters. Perhaps he will chime in.

tjr

If I remember it right, the cause of such a problem is updating the
clock by accessing a time server over a network. Just any such access
results in adjusting the time a bit and leads eventually to such problems.

Claudio Grondi

[Tim Peters]

[Giovanni Bajo[

>I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically) returning a floating point value which was "less than" the
value returned by the previous invokation. The computer was a pretty fast
one (P4 3Ghz I think, running Windows XP), and this happened only between
very close invokations of time.clock().

[Terry Reed]

I seem to remember this being mentioned before on the list, perhaps by Tim
Peters. Perhaps he will chime in.

No real need ;-) BIOS or HAL bug on a multiprocessor (or maybe even
hyperthreaded) box is by far the most likely cause (and the only cause
ever identified for sure by people who followed up). Python's C code
slinging QueryPerformanceCounter is exceedingly simple, and isn't a
suspect because of that. It's on the edge of vague possibility that
Microsoft's compiler generates non-monotonic code for converting
64-bit integer to double: i.e., Python's C code obviously relies on
that if i and j are _int64 satisfying i >= j, then (double)i >=
(double)j. If that type-conversion code /is/ monotonic (which is
almost certainly so), then the only ways the C code can fail are if
the HW counter overflows (in which case time.clock() would "jump" a
huge amount), or if the sequence of values returned by
QueryPerformanceCounter is itself non-monotonic at times (which is
consistent with known BIOS/HAL bugs).

[Sander Steffann]

Hi,

>>>I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically)
returning a floating point value which was "less than" the value returned
by the previous invokation.

If I remember it right, the cause of such a problem is updating the
clock by accessing a time server over a network. Just any such access
results in adjusting the time a bit and leads eventually to such problems.

Usualy time is synchronized by making the clock run a little faster or a
little slower until it is in sync with the timeserver. It shouldn't go
backwards... A bad time-sync-program might ofcourse do this, but with a
decent NTP client this shouldn't happen.

- Sander

[skip]

>I seem to remember this being mentioned before on the list, perhaps by Tim

>Peters. Perhaps he will chime in.

ClaudioIf I remember it right, the cause of such a problem is updating
Claudiothe clock by accessing a time server over a network. Just any
Claudiosuch access results in adjusting the time a bit and leads
Claudioeventually to such problems.

Wouldn't that affect time.time (time since the start of the Epoch), not
time.clock (cpu time used by the current process)?

Skip

[Tim Roberts]

"Tim Peters" <ti********@gmail.comwrote:

>[Giovanni Bajo[

>>I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically) returning a floating point value which was "less than" the
value returned by the previous invokation. The computer was a pretty fast
one (P4 3Ghz I think, running Windows XP), and this happened only between
very close invokations of time.clock().

[Terry Reed]

>I seem to remember this being mentioned before on the list, perhaps by Tim
Peters. Perhaps he will chime in.

No real need ;-) BIOS or HAL bug on a multiprocessor (or maybe even
hyperthreaded) box is by far the most likely cause (and the only cause
ever identified for sure by people who followed up). Python's C code
slinging QueryPerformanceCounter is exceedingly simple, and isn't a
suspect because of that. It's on the edge of vague possibility that
Microsoft's compiler generates non-monotonic code for converting
64-bit integer to double:

It is much simpler than that. With a multiprocessor HAL, including on a
dual-core or hyperthreaded system, QueryPerformanceCounter returns the raw
cycle counter (RDTSC). However, on Windows XP, the operating system does
not synchronize the cycle counters on multiple processors, and they can be
actually be millions of cycles apart.

This was a change from previous systems. On NT4 and Win2000, the operating
actually rewrote the cycle counters on the second (and beyond) processors
to align them to the first processor, so the delta was usually only a dozen
or two cycles. XP does not appear to do that. I think that is a huge
mistake, since it renders QueryPerformanceCounter non-monotonic.
--
- Tim Roberts, ti**@probo.com
Providenza & Boekelheide, Inc.

[Claudio Grondi]

Tim Roberts wrote:

"Tim Peters" <ti********@gmail.comwrote:

>>[Giovanni Bajo[

>>>>I experimented something very strange, a few days ago. I was debugging an
application at a customer's site, and the problem turned out to be that
time.clock() was going "backwards", that is it was sometimes
(randomically) returning a floating point value which was "less than" the
value returned by the previous invokation. The computer was a pretty fast
one (P4 3Ghz I think, running Windows XP), and this happened only between
very close invokations of time.clock().

[Terry Reed]

>>>I seem to remember this being mentioned before on the list, perhaps by Tim
Peters. Perhaps he will chime in.

No real need ;-) BIOS or HAL bug on a multiprocessor (or maybe even
hyperthreaded) box is by far the most likely cause (and the only cause
ever identified for sure by people who followed up). Python's C code
slinging QueryPerformanceCounter is exceedingly simple, and isn't a
suspect because of that. It's on the edge of vague possibility that
Microsoft's compiler generates non-monotonic code for converting
64-bit integer to double:

It is much simpler than that. With a multiprocessor HAL, including on a
dual-core or hyperthreaded system, QueryPerformanceCounter returns the raw
cycle counter (RDTSC). However, on Windows XP, the operating system does
not synchronize the cycle counters on multiple processors, and they can be
actually be millions of cycles apart.

This was a change from previous systems. On NT4 and Win2000, the operating
actually rewrote the cycle counters on the second (and beyond) processors
to align them to the first processor, so the delta was usually only a dozen
or two cycles. XP does not appear to do that. I think that is a huge
mistake, since it renders QueryPerformanceCounter non-monotonic.

How does it come, that processors on same mainboard run at different
speeds? Do they have separate clock-pulse generators?

I can remember, that (at least on very old motherboards) the clock-pulse
generator was a separate element and the processor just used it, so I
would expect, that even in case of multiple processors, if there were
only one clock-pulse generator for all of them, they were not be able to
run at different speeds.

Claudio Grondi

[Rob Williscroft]

Claudio Grondi wrote in news:ec**********@newsreader2.netcologne.de in
gmane.comp.python.general:

Tim Roberts wrote:

>"Tim Peters" <ti********@gmail.comwrote:

>>
It is much simpler than that. With a multiprocessor HAL, including
on a dual-core or hyperthreaded system, QueryPerformanceCounter
returns the raw cycle counter (RDTSC). However, on Windows XP, the
operating system does not synchronize the cycle counters on multiple
processors, and they can be actually be millions of cycles apart.

This was a change from previous systems. On NT4 and Win2000, the
operating actually rewrote the cycle counters on the second (and
beyond) processors to align them to the first processor, so the delta
was usually only a dozen or two cycles. XP does not appear to do
that. I think that is a huge mistake, since it renders
QueryPerformanceCounter non-monotonic.

How does it come, that processors on same mainboard run at different
speeds? Do they have separate clock-pulse generators?

I don't see any claim above that they run at different speeds, only
that the counters are several million cycles apart, IOW running at the
same speed but with different initial values, or more likely starting
at different times.

For processors that run at (say) 2GHz, several million (say 10 million)
represents a difference of 10e6/2e9 = 0.005 seconds between when the
processors were sufficiently powered up to start counting cycles.

Rob.
--
http://www.victim-prime.dsl.pipex.com/

[Claudio Grondi]

Rob Williscroft wrote:

Claudio Grondi wrote in news:ec**********@newsreader2.netcologne.de in
gmane.comp.python.general:

>>Tim Roberts wrote:

>>>"Tim Peters" <ti********@gmail.comwrote:

>>>It is much simpler than that. With a multiprocessor HAL, including
on a dual-core or hyperthreaded system, QueryPerformanceCounter
returns the raw cycle counter (RDTSC). However, on Windows XP, the
operating system does not synchronize the cycle counters on multiple
processors, and they can be actually be millions of cycles apart.

This was a change from previous systems. On NT4 and Win2000, the
operating actually rewrote the cycle counters on the second (and
beyond) processors to align them to the first processor, so the delta
was usually only a dozen or two cycles. XP does not appear to do
that. I think that is a huge mistake, since it renders
QueryPerformanceCounter non-monotonic.

How does it come, that processors on same mainboard run at different
speeds? Do they have separate clock-pulse generators?

I don't see any claim above that they run at different speeds, only
that the counters are several million cycles apart, IOW running at the
same speed but with different initial values, or more likely starting
at different times.

For processors that run at (say) 2GHz, several million (say 10 million)
represents a difference of 10e6/2e9 = 0.005 seconds between when the
processors were sufficiently powered up to start counting cycles.

Rob.

If it were so, than why can't the delta of time between the processors
be set to exact zero?
I assume, that it is known how many cycles adjusting the value will
take, so it could be done exactly ... hmmm ...

Claudio Grondi

[Grant Edwards]

On 2006-08-28, Claudio Grondi <cl************@freenet.dewrote:

>I don't see any claim above that they run at different speeds, only
that the counters are several million cycles apart, IOW running at the
same speed but with different initial values, or more likely starting
at different times.

For processors that run at (say) 2GHz, several million (say 10 million)
represents a difference of 10e6/2e9 = 0.005 seconds between when the
processors were sufficiently powered up to start counting cycles.

If it were so, than why can't the delta of time between the processors
be set to exact zero?

This is

I assume, that it is known how many cycles adjusting the value will
take, so it could be done exactly ... hmmm ...

Claudio Grondi

--
Grant Edwards grante Yow! LIFE is a
at never-ending INFORMERCIAL!
visi.com

[Fredrik Lundh]

Claudio Grondi wrote:

If it were so, than why can't the delta of time between the processors
be set to exact zero?

someone just wrote:

>>>This was a change from previous systems. On NT4 and Win2000, the
operating actually rewrote the cycle counters on the second (and
beyond) processors to align them to the first processor, so the delta
was usually only a dozen or two cycles. XP does not appear to do
that. I think that is a huge mistake, since it renders
QueryPerformanceCounter non-monotonic.

so if you really want to know, you may have to ask microsoft.

</F>

[Fredrik Lundh]

so if you really want to know, you may have to ask microsoft.

footnote: judging from

http://support.microsoft.com/?id=896256

this might be related to advanced power management features in XP. that
note also mentions a hotfix for this.

</F>

[Grant Edwards]

On 2006-08-28, Grant Edwards <gr****@visi.comwrote:

>>For processors that run at (say) 2GHz, several million (say 10
million) represents a difference of 10e6/2e9 = 0.005 seconds
between when the processors were sufficiently powered up to
start counting cycles.

>If it were so, than why can't the delta of time between the
processors be set to exact zero?

This is

Oops. Hit the wrong key. I meant to say:

This is a _Microsoft_Product_. There doesn't have to be a
reason for something to be done in a half-assed manner.

>I assume, that it is known how many cycles adjusting the value
will take, so it could be done exactly

Yup.

--
Grant Edwards grante Yow! People humiliating
at a salami!
visi.com

[Hendrik van Rooyen]

"Grant Edwards" <gr****@visi.comWrote:

| On 2006-08-28, Grant Edwards <gr****@visi.comwrote:
|
| >>For processors that run at (say) 2GHz, several million (say 10
| >>million) represents a difference of 10e6/2e9 = 0.005 seconds
| >>between when the processors were sufficiently powered up to
| >>start counting cycles.
| >
| >If it were so, than why can't the delta of time between the
| >processors be set to exact zero?
| >
| This is
|
| Oops. Hit the wrong key. I meant to say:

Thank god! - I know you are not an idiot - and for some minutes you had me
guessing - I was beginning to think that my brain had finally been destroyed by
drink - trying to figure out this enigmatic post... :-)

- Hendrik

8<-----------------

[Ralf Muschall]

Grant Edwards wrote:

This is a _Microsoft_Product_. There doesn't have to be a
reason for something to be done in a half-assed manner.

No, it is a quantum effect. If the energy of a clock has a
lower bound, there must be a nonzero probability for it to
run backwards.

See <93**********@news.state.mn.us>

SCNR, Ralf

[Grant Edwards]

On 2006-08-29, Ralf Muschall <rm*******@tecont.dewrote:

Grant Edwards wrote:

>This is a _Microsoft_Product_. There doesn't have to be a
reason for something to be done in a half-assed manner.

No, it is a quantum effect. If the energy of a clock has a
lower bound, there must be a nonzero probability for it to
run backwards.

See <93**********@news.state.mn.us>

Brain... hurts...

--
Grant Edwards grante Yow! JAPAN is a WONDERFUL
at planet -- I wonder if we'll
visi.com ever reach their level of
COMPARATIVE SHOPPING...