Issue 20101: Determine correct behavior for time functions on Windows (original) (raw)

For previous discussion, see .

To summarize, time on Windows is far from straight-forward, and currently for

""" t1 = time.monotonic() time.sleep(0.5) t2 = time.monotonic() dt = t2-t1 """

dt may end up as very slightly smaller than 0.5 (0.4990000003017485 or so), 0.5, or somewhat larger than 0.5 (0.5150000001303852 or so); or 0.5 almost all of the time, depending on the machine in question. So far, two very different Win7 machines of mine both produced the first result, and Tim Peters' Vista machine produced the second. Both of mine report the resolution as 0.015600099999999999, Tim's reports 0.015625.

Due to the issue, test_monotonic regularly fails for me. A simple workaround is to relax the lower bound of 0.5 <= dt <= 1.0 to 0.45; I intend to commit that workaround soon, but it won't close this issue.

In preparation for creating this issue I also checked the other time functions (time, clock, and perf_counter) for the same issue, and on my test machine all of them have it (although it is apparently intermittent for time (earlier I got straight failures, now it won't fail), and clock and perf_counter are implemented by the same underlying function).

Here is some output from my machine, formatted slightly for nicer presentation:

3.4.0b1 (default:fd846837492d+, Dec 30 2013, 11:01:01) [MSC v.1600 32 bit (Intel)] Windows-7-6.1.7601-SP1 Running: """ import time import sys import platform print(sys.version) print(platform.platform())

with open(file) as file: print('Running:\n"""') print(file.read()) print('"""')

clock_info = {}

for time_func in (time.monotonic, time.time, time.clock, time.perf_counter): name = time_func.name info = str(time.get_clock_info(name)) print(name, info) if info in clock_info: print('Same clock as time.{}'.format(clock_info[info])) continue else: clock_info[info] = name good = 0 values = {} count = 0 try: while count < 25: # basic test copied from test_monotonic, extras bolted on t1 = time_func() time.sleep(0.5) t2 = time_func() dt = t2 - t1 if values.get(dt): values[dt] += 1 else: values[dt] = 1 assert t2 > t1 passed = 0.5 <= dt <= 1.0 print('.' if passed else 'F', end='', flush=True) if passed: good += 1 count += 1 except KeyboardInterrupt: pass

print()
print('total:', count,
      'good:', good,
      'bad:', count - good)
print(sorted(values.items()))
print()

""" monotonic namespace(adjustable=False, implementation='GetTickCount64()', monotonic=True, resolution=0.015600099999999999) FF.FFFF.FFF.FF.FFF.FFFF.F total: 25 good: 6 bad: 19 [(0.4989999998360872, 13), (0.4990000003017485, 6), (0.5, 5), (0.5150000001303852, 1)]

time namespace(adjustable=True, implementation='GetSystemTimeAsFileTime()', monotonic=False, resolution=0.015600099999999999) ......................... total: 25 good: 25 bad: 0 [(0.5, 25)]

clock namespace(adjustable=False, implementation='QueryPerformanceCounter()', monotonic=True, resolution=2.851518034140655e-07) .FFFFFFFFFFFFFFFFFF.FFFFF total: 25 good: 2 bad: 23 [(0.49929681565278194, 1), (0.49941258728496685, 1), (0.4995377689266647, 1), (0.4995543077312634, 1), (0.49955459288306736, 1), (0.4995597256155282, 1), (0.4995602959191352, 1), (0.4995659989552035, 1), (0.4995679950178271, 1), (0.49956970592864813, 1), (0.4995748386611094, 1), (0.499581967456195, 1), (0.4995956547427589, 1), (0.49961304900276726, 1), (0.49961761143162153, 1), (0.49961846688703204, 1), (0.49962445507490294, 1), (0.499629017503759, 1), (0.4996355759952369, 1), (0.4996401384240914, 1), (0.49964042357589467, 1), (0.4996486929781927, 1), (0.4996555366214759, 1), (0.5000139724383673, 1), (0.5036356854935278, 1)]

perf_counter namespace(adjustable=False, implementation='QueryPerformanceCounter()', monotonic=True, resolution=2.851518034140655e-07) Same clock as time.clock

And here's results from time.time earlier today (produced by an earlier version of the above script, same machine and interpreter):

time FFFFFFFFFFFFFFFFFFFFFF.FF total: 25 good: 1 bad: 24 [(0.49969983100891113, 7), (0.49970006942749023, 17), (0.5006990432739258, 1)]

I'm not sanguine about fixing any of this :-( The Microsoft docs are awful, and the more web searches I do the more I realize that absolutely everyone is confused, just taking their best guesses.

FYI, here are results from your new program on my 32-bit Vista box:

3.4.0b1 (default:9d1fb265b88a, Dec 10 2013, 18:48:53) [MSC v.1600 32 bit (Intel)] Windows-Vista-6.0.6002-SP2 Running: ... monotonic namespace(adjustable=False, implementation='GetTickCount64()', monotonic=True, resolution=0.015625) ......................... total: 25 good: 25 bad: 0 [(0.5, 25)]

time namespace(adjustable=True, implementation='GetSystemTimeAsFileTime()', monotonic=False, resolution=0.015625) FFFFFFFFFFFFFFFFFFFFFFFFF total: 25 good: 0 bad: 25 [(0.4999678134918213, 5), (0.4999680519104004, 20)]

clock namespace(adjustable=False, implementation='QueryPerformanceCounter()', monotonic=True, resolution=2.793651148400146e-07) FFFFFFFFFFFFFFFFFFFF.FFFF total: 25 good: 1 bad: 24 [(0.49919109830998076, 1), (0.4996682539261279, 1), (0.4997051301212867, 1), (0.4997221713932909, 1), (0.49972636187001385, 1), (0.499727479330474, 1), (0.49973139044208104, 1), (0.49973390472811463, 1), (0.4997383745699526, 1), (0.49974479996759325, 1), (0.4997501079047755, 1), (0.4997501079047756, 1), (0.49975318092104004, 1), (0.499756533302417, 1), (0.4997598856837939, 1), (0.49976239996982863, 1), (0.49976714917678144, 1), (0.49977078092327387, 1), (0.49977189838373315, 1), (0.4997724571139628, 1), (0.499777765051145, 1), (0.49979173330688553, 1), (0.4997973206091828, 1), (0.4998065396579734, 1), (0.500726488981142, 1)]

perf_counter namespace(adjustable=False, implementation='QueryPerformanceCounter()', monotonic=True, resolution=2.793651148400146e-07) Same clock as time.clock