[New-bugs-announce] [issue20101] Determine correct behavior for time functions on Windows

[Zachary Ware]

New submission from Zachary Ware:

For previous discussion, see issue19999.

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.

See also http://stackoverflow.com/questions/7685762/windows-7-timing-functions-how-to-use-getsystemtimeadjustment-correctly and http://www.windowstimestamp.com/description for more related reading.

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)]

----------
components: Extension Modules, Windows
messages: 207125
nosy: haypo, tim.peters, zach.ware
priority: normal
severity: normal
status: open
title: Determine correct behavior for time functions on Windows
type: behavior
versions: Python 3.3, Python 3.4

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue20101>
_______________________________________