This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Determine correct behavior for time functions on Windows
Type: behavior Stage:
Components: Extension Modules, Windows Versions: Python 3.3, Python 3.4
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: BreamoreBoy, jkloth, loewis, python-dev, tim.peters, vstinner, zach.ware
Priority: normal Keywords:

Created on 2013-12-31 21:42 by zach.ware, last changed 2022-04-11 14:57 by admin. This issue is now closed.

Messages (10)
msg207125 - (view) Author: Zachary Ware (zach.ware) * (Python committer) Date: 2013-12-31 21:42
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)]
msg207141 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2014-01-02 02:03
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
msg207162 - (view) Author: Martin v. Löwis (loewis) * (Python committer) Date: 2014-01-02 13:20
As a further datapoint, it would be good to find out whether any of you has NTP enabled, and if so, against what time server. To find out, open the clock settings ("Datums- und Uhrzeiteinstellungen ändern"), and go to NTP tab ("Internetzeit").
msg207165 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-01-02 14:01
time.get_clock_info("time") and time.get_clock_info("monotonic") is currently using GetSystemTimeAdjustment(). In msg206886 it was said that "GetSystemTimeAdjustment is not the function to look at."

Should we modify this function to use NtQueryTimerResolution() instead?

TimeAdjustmentDisabled argument of GetSystemTimeAdjustment() is current ignored. Is it a bug?
msg207167 - (view) Author: Zachary Ware (zach.ware) * (Python committer) Date: 2014-01-02 14:54
Martin v. Löwis wrote:
> As a further datapoint, it would be good to find out whether any of you has NTP enabled, and if so, against what time server. To find out, open the clock settings ("Datums- und Uhrzeiteinstellungen ändern"), and go to NTP tab ("Internetzeit").

My 32-bit box is on a domain, and thus I can't access that tab.
However, according to
HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\DateTime\Servers
(see [1]) it looks to me like NTP is enabled, with 5 servers listed:
time.windows.com followed by 4 different time*.nist.gov servers.

I expect the 64-bit box to be checking time.windows.com; if I find
anything different when I get a chance to look at it, I'll report my
findings.

[1] http://superuser.com/questions/161759/where-do-i-find-the-internet-time-ntp-settings-in-windows-7
msg207168 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2014-01-02 15:43
New changeset 82df66a091da by Zachary Ware in branch '3.3':
Issue #20101: Allow test_monotonic to pass on Windows machines on which
http://hg.python.org/cpython/rev/82df66a091da

New changeset e2a1400b7db9 by Zachary Ware in branch 'default':
Issue #20101: Merge with 3.3
http://hg.python.org/cpython/rev/e2a1400b7db9
msg207186 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2014-01-02 20:30
1. I'm sync'ing with north-america.pool.ntp.org.  But the docs on my box say "Your clock is typically updated once a week", and I believe it.

2. I just ran Zach's program again, with the same Python, and _this_ time 'time' passed 25 times (as did 'monotonic').  'time' failed 25 times in the output I pasted here before.  'clock' failed 25 times again.  Here are the passing values for this run of 'time':

[(0.5001208782196045, 4), (0.5001211166381836, 6),
 (0.5001218318939209, 5), (0.5001220703125, 10)]
msg207193 - (view) Author: Zachary Ware (zach.ware) * (Python committer) Date: 2014-01-02 22:19
I ran the same test on all of the Windows buildbots, with the following results:

x86 XP-4:
http://buildbot.python.org/all/builders/x86%20XP-4%20custom/builds/33/steps/test/logs/stdio
monotonic: good
time: good
clock/perf_counter: 10 failures

x86 Windows7
http://buildbot.python.org/all/builders/x86%20Windows7%20custom/builds/37/steps/test/logs/stdio
monotonic: good
time: 24 failures
clock/perf_counter: 11 failures

AMD64 Windows7 SP1
http://buildbot.python.org/all/builders/AMD64%20Windows7%20SP1%20custom/builds/41/steps/test/logs/stdio
All good

x86 Windows Server 2003
http://buildbot.python.org/all/builders/x86%20Windows%20Server%202003%20%5BSB%5D%20custom/builds/33/steps/test/logs/stdio
monotonic: good
time: good
clock/perf_counter: all failures

AMD64 Windows Server 2008R2
http://buildbot.python.org/all/builders/AMD64%20Windows%20Server%202008%20%5BSB%5D%20custom/builds/17/steps/test/logs/stdio
All good

x86 Windows Server 2008R2
http://buildbot.python.org/all/builders/x86%20Windows%20Server%202008%20%5BSB%5D%20custom/builds/0/steps/test/logs/stdio
All good


Also, I noticed three different resolutions for monotonic: mine, Tim's, and 0.0100144 on the XP-4 bot.
msg225160 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2014-08-10 19:38
Is there anything else that can be done or needs doing here?
msg225161 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2014-08-10 20:01
time.sleep() and time.monotonic() don't use the same clock. Python cannot fix Windows clocks, it's not a bug.
History
Date User Action Args
2022-04-11 14:57:56adminsetgithub: 64300
2014-08-10 20:01:25vstinnersetstatus: open -> closed
resolution: not a bug
messages: + msg225161
2014-08-10 19:38:22BreamoreBoysetnosy: + BreamoreBoy
messages: + msg225160
2014-01-02 22:19:04zach.waresetmessages: + msg207193
2014-01-02 20:30:09tim.peterssetmessages: + msg207186
2014-01-02 15:43:31python-devsetnosy: + python-dev
messages: + msg207168
2014-01-02 14:54:41zach.waresetmessages: + msg207167
2014-01-02 14:01:59vstinnersetmessages: + msg207165
2014-01-02 13:20:07loewissetnosy: + loewis
messages: + msg207162
2014-01-02 02:03:08tim.peterssetmessages: + msg207141
2014-01-01 11:42:32jklothsetnosy: + jkloth
2013-12-31 21:42:32zach.warecreate