time.clock() or Windows bug?

[Theo v. Werkhoven]

hi,

In this code I read out an instrument during a user determined period,
and save the relative time of the sample (since the start of the test)
and the readback value in a csv file.

#v+
from datetime import *
from time import *
from visa import *
from random import *
[..]
for Reading in range(Readings):
RelTimeOfSample = "%.1f" % clock()
#PwrMtr.write("READ?")
#Sample = "%.3f" % float(PwrMtr.read())
Sample = "%.3f" % (uniform(8.9,9.3)) # Simulation of reading.
print "Sample %s, at %s seconds from start; Output power is: %s dBm"
% (Reading+1, RelTimeOfSample, Sample)
writer.writerow([RelTimeOfSample, Sample])
ResultFile.flush()
sleep(6.6)
#v-

Output:
Sample 1, at 0.0 seconds from start; Output power is: 8.967 dBm
Sample 2, at 6.6 seconds from start; Output power is: 9.280 dBm
Sample 3, at 13.2 seconds from start; Output power is: 9.096 dBm
Sample 4, at 19.8 seconds from start; Output power is: 9.166 dBm
Sample 5, at 26.4 seconds from start; Output power is: 8.918 dBm
Sample 6, at 33.0 seconds from start; Output power is: 9.183 dBm
Sample 7, at 39.7 seconds from start; Output power is: 8.903 dBm
Sample 8, at 46.3 seconds from start; Output power is: 9.138 dBm
Sample 9, at 52.9 seconds from start; Output power is: 9.163 dBm
Sample 10, at 59.5 seconds from start; Output power is: 9.075 dBm
Sample 11, at 66.1 seconds from start; Output power is: 9.230 dBm
Sample 12, at 72.7 seconds from start; Output power is: 9.225 dBm
Sample 13, at 79.3 seconds from start; Output power is: 9.053 dBm
Sample 14, at 85.9 seconds from start; Output power is: 9.066 dBm
Sample 15, at 92.5 seconds from start; Output power is: 9.109 dBm
Sample 16, at 99.1 seconds from start; Output power is: 9.286 dBm
Sample 17, at 105.7 seconds from start; Output power is: 9.147 dBm
Sample 18, at 112.4 seconds from start; Output power is: 9.284 dBm
Sample 19, at 119.0 seconds from start; Output power is: 9.013 dBm
Sample 20, at 125.6 seconds from start; Output power is: 8.952 dBm
Sample 21, at 91852.8 seconds from start; Output power is: 9.102 dBm
Sample 22, at 91862.7 seconds from start; Output power is: 9.289 dBm
Sample 23, at 145.4 seconds from start; Output power is: 9.245 dBm
Sample 24, at 152.0 seconds from start; Output power is: 8.936 dBm
Sample 25, at 158.8 seconds from start; Output power is: 9.139 dBm
Sample 26, at 165.4 seconds from start; Output power is: 9.241 dBm
Sample 27, at 172.1 seconds from start; Output power is: 8.938 dBm
Sample 28, at 178.7 seconds from start; Output power is: 8.947 dBm
Sample 29, at 185.3 seconds from start; Output power is: 9.252 dBm
Sample 30, at 191.9 seconds from start; Output power is: 9.082 dBm
Sample 31, at 198.5 seconds from start; Output power is: 9.224 dBm
Sample 32, at 205.1 seconds from start; Output power is: 8.902 dBm
Sample 33, at 211.7 seconds from start; Output power is: 9.182 dBm
Sample 34, at 218.3 seconds from start; Output power is: 8.974 dBm
Sample 35, at 224.9 seconds from start; Output power is: 9.129 dBm
Sample 36, at 231.5 seconds from start; Output power is: 9.214 dBm
Sample 37, at 238.1 seconds from start; Output power is: 9.188 dBm
Sample 38, at 244.8 seconds from start; Output power is: 8.909 dBm
Sample 39, at 251.4 seconds from start; Output power is: 9.197 dBm
Sample 40, at 258.0 seconds from start; Output power is: 8.946 dBm
Sample 41, at 264.6 seconds from start; Output power is: 9.228 dBm
Sample 42, at 271.2 seconds from start; Output power is: 8.938 dBm
Sample 43, at 92071.3 seconds from start; Output power is: 8.964 dBm
Sample 44, at 284.4 seconds from start; Output power is: 9.276 dBm
Sample 45, at 291.0 seconds from start; Output power is: 8.932 dBm
Sample 46, at 297.6 seconds from start; Output power is: 9.158 dBm

But look at the timestamps of samples 21, 22 and 43.
What is causing this?
I've replaced the time.clock() with time.time(), and that seems to
solve the problem, but I would like to know if it's something I
misunderstand or if it's a problem with the platform (Windows Server
2003) or the time.clock() function.

T:\Theo\Python>ver
Microsoft Windows [Version 5.2.3790]
T:\Theo\Python>c:\Python25\python.exe --version
Python 2.5.1

Thanks,
Theo

 

[Theo v. Werkhoven]

The carbonbased lifeform Nick Craig-Wood inspired comp.lang.python with:

Output:
Sample 1, at 0.0 seconds from start; Output power is: 8.967 dBm [snip]
Sample 17, at 105.7 seconds from start; Output power is: 9.147 dBm
Sample 18, at 112.4 seconds from start; Output power is: 9.284 dBm
Sample 19, at 119.0 seconds from start; Output power is: 9.013 dBm
Sample 20, at 125.6 seconds from start; Output power is: 8.952 dBm
Sample 21, at 91852.8 seconds from start; Output power is: 9.102 dBm
Sample 22, at 91862.7 seconds from start; Output power is: 9.289 dBm
Sample 23, at 145.4 seconds from start; Output power is: 9.245 dBm
Sample 24, at 152.0 seconds from start; Output power is: 8.936 dBm [snip]
But look at the timestamps of samples 21, 22 and 43.
What is causing this?
I've replaced the time.clock() with time.time(), and that seems to
solve the problem, but I would like to know if it's something I
misunderstand or if it's a problem with the platform (Windows Server
2003) or the time.clock() function.

time.clock() uses QueryPerformanceCounter under windows. There are
some known problems with that (eg with Dual core AMD processors).

See http://msdn.microsoft.com/en-us/library/ms644904.aspx

And in particular

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.

Alright, that explains that then.

I would have said time.time is what you want to use anyway though
because under unix time.clock() returns the elapsed CPU time which is
not what you want at all!

You're right, using fuctions that do not work cross platform isn't
smart.
Cheers for the explanation Nick

Theo

 

[Tim Roberts]

time.clock() uses QueryPerformanceCounter under windows. There are
some known problems with that (eg with Dual core AMD processors).

See http://msdn.microsoft.com/en-us/library/ms644904.aspx

And in particular

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.

That's an extremely arrogant statement on their part, because the fault
here is entirely within Windows.

Through Windows 2000, the operating system actually synchronized the cycle
counters on the additional processors as they came out of reset at boot
time. (The cycle counter is, after all, a writable register.) As a
result, the cycle counters were rarely off by more than about 20 cycles.

Beginning with XP, they stopped doing that. As a result, the cycle
counters on multiprocessor machines can vary by millions or even tens of
millions of cycles.

 

[Tim Roberts]

Hmmm, 10,000,000 cycles (40 ms @2.5GHz) is nowhere near the ~90,000
second jump in time.clock() output reported by the OP. I wonder if
there could be a different cause?

Just wild theorizing, but it's possible that they are actually getting a
negative delta, and some kind of signed/unsigned manipulation produces the
90,000 number.

 

[mgenti]

Don't forget that timeit module uses time.clock on windows as well:
if sys.platform == "win32":
# On Windows, the best timer is time.clock()
default_timer = time.clock
else:
# On most other platforms the best timer is time.time()
default_timer = time.time
http://svn.python.org/view/python/trunk/Lib/timeit.py

--Mark

 The carbonbased lifeform Nick Craig-Wood inspired comp.lang.python with:

 Output:
 Sample 1, at 0.0 seconds from start; Output power is: 8.967 dBm
[snip]
 Sample 17, at 105.7 seconds from start; Output power is: 9.147 dBm
 Sample 18, at 112.4 seconds from start; Output power is: 9.284 dBm
 Sample 19, at 119.0 seconds from start; Output power is: 9.013 dBm
 Sample 20, at 125.6 seconds from start; Output power is: 8.952 dBm
 Sample 21, at 91852.8 seconds from start; Output power is: 9.102 dBm
 Sample 22, at 91862.7 seconds from start; Output power is: 9.289 dBm
 Sample 23, at 145.4 seconds from start; Output power is: 9.245 dBm
 Sample 24, at 152.0 seconds from start; Output power is: 8.936 dBm
[snip]
 But look at the timestamps of samples 21, 22 and 43.
 What is causing this?
 I've replaced the time.clock() with time.time(), and that seems to
 solve the problem, but I would like to know if it's something I
 misunderstand or if it's a problem with the platform (Windows Server
 2003) or the time.clock() function.
time.clock() uses QueryPerformanceCounter under windows.  There are
some known problems with that (eg with Dual core AMD processors).
Seehttp://msdn.microsoft.com/en-us/library/ms644904.aspx
And in particular
    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.

 Alright, that explains that then.

 You're right, using fuctions that do not work cross platform isn't
 smart.

Actually there is one good reason for using time.clock() under Windows
- because it is much higher precision than time.time().  Under Windows
time.time() is only accurate at best 1ms, and in fact it is a lot
worse than that.

Under Win95/98 it has a 55ms granularity and under Vista time().time()
changes in 15ms or 16ms steps.

Under unix, time.clock() is pretty much useless because it measures
CPU time (with a variable precision, maybe 10ms, maybe 1ms), and
time.time() has a precision of about 1us (exact precision depending on
lots of things!).

"""
Test timing granularity

Under Vista this produces

C:\>time_test.py
  15000us -  40 times
  16000us -  60 times

Under linux 2.6 this produces

$ python time_test.py
      1us - 100 times

"""

from time import time

granularities = {}

for i in range(100):
    x = time()
    j = 0
    while 1:
        y = time()
        if x != y:
            dt = int(1000000*(y - x)+0.5)
            granularities[dt] = granularities.get(dt, 0) + 1
            break
        j += 1

dts = granularities.keys()
dts.sort()
for dt in dts:
    print "%7dus - %3d times" % (dt, granularities[dt])

 

[Theo v. Werkhoven]

The carbonbased lifeform Tim Roberts inspired comp.lang.python with:

Just wild theorizing, but it's possible that they are actually getting a
negative delta, and some kind of signed/unsigned manipulation produces the
90,000 number.

Actually, in previous runs I /did/ see negative timestamps using
time.clock().
Bizar.

Theo