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 QueryPerformanc eCounter:

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 SetThreadAffini tyMask 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

iD8DBQFE7yhsrgn 0plK5qqURAp1sAJ 9mOO0UbZUhjZQsj ew3roLGQHUabACg vwCJ
I8wDMKiuL2xF/dY7d2b1ccA=
=hRd5
-----END PGP SIGNATURE-----

[Terry Reedy]

"Giovanni Bajo" <no***@sorry.co mwrote in message
news:vk******** ************@tw ister2.libero.i t...

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.co mwrote in message
news:vk******** ************@tw ister2.libero.i t...

>>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
(randomicall y) 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 QueryPerformanc eCounter 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
QueryPerformanc eCounter 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
applicatio n at a customer's site, and the problem turned out to be that
time.clock () was going "backwards" , that is it was sometimes
(randomicall y)
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
Claudioeventual ly 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********@gma il.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
hyperthreade d) 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 QueryPerformanc eCounter 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, QueryPerformanc eCounter 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 QueryPerformanc eCounter non-monotonic.
--
- Tim Roberts, ti**@probo.com
Providenza & Boekelheide, Inc.

[Claudio Grondi]

Tim Roberts wrote:

"Tim Peters" <ti********@gma il.comwrote:

>>[Giovanni Bajo[

>>>>I experimented something very strange, a few days ago. I was debugging an
applicati on at a customer's site, and the problem turned out to be that
time.clock( ) was going "backwards" , that is it was sometimes
(randomical ly) 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 QueryPerformanc eCounter 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, QueryPerformanc eCounter 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 QueryPerformanc eCounter 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