test_monotonic fails on x86 OpenIndiana

[tiran]

BPO	19999
Nosy	@tim-one, @vstinner, @tiran, @zware

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vstinner'
closed_at = <Date 2013-12-16.21:39:24.284>
created_at = <Date 2013-12-16.18:46:57.923>
labels = ['type-bug', 'tests']
title = 'test_monotonic fails on x86 OpenIndiana'
updated_at = <Date 2013-12-24.14:18:26.301>
user = 'https://github.com/tiran'

bugs.python.org fields:

activity = <Date 2013-12-24.14:18:26.301>
actor = 'vstinner'
assignee = 'vstinner'
closed = True
closed_date = <Date 2013-12-16.21:39:24.284>
closer = 'python-dev'
components = ['Tests']
creation = <Date 2013-12-16.18:46:57.923>
creator = 'christian.heimes'
dependencies = []
files = []
hgrepos = []
issue_num = 19999
keywords = ['buildbot']
message_count = 12.0
messages = ['206344', '206372', '206380', '206833', '206841', '206865', '206870', '206874', '206885', '206886', '206890', '206891']
nosy_count = 5.0
nosy_names = ['tim.peters', 'vstinner', 'christian.heimes', 'python-dev', 'zach.ware']
pr_nums = []
priority = 'low'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue19999'
versions = ['Python 3.4']

[tiran]

I have seen this failure multiple times.

http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.x/builds/7353/steps/test/logs/stdio

======================================================================
FAIL: test_monotonic (test.test_time.TimeTestCase)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_time.py", line 387, in test_monotonic
    self.assertAlmostEqual(dt, 0.5, delta=0.2)
AssertionError: 0.8012567944824696 != 0.5 within 0.2 delta

---

[python-dev]

New changeset 4864c0b914ae by Victor Stinner in branch '3.3':
Close bpo-19999: tolerate coarse time when testing time.monotonic() on very
http://hg.python.org/cpython/rev/4864c0b914ae

New changeset a34582c53911 by Victor Stinner in branch 'default':
(Merge 3.3) Close bpo-19999: tolerate coarse time when testing time.monotonic() on
http://hg.python.org/cpython/rev/a34582c53911

[vstinner]

Hum, there is something wrong with this buildbot!

http://buildbot.python.org/all/builders/x86%20OpenIndiana%203.3/builds/1266/steps/test/logs/stdio

======================================================================
FAIL: test_monotonic (test.test_time.TimeTestCase)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.3.cea-indiana-x86/build/Lib/test/test_time.py", line 379, in test_monotonic
    self.assertTrue(0.5 <= dt <= 1.0, dt)
AssertionError: False is not true : 2.2977897822856903

[zware]

I think the minimum bound for dt could stand to be relaxed very slightly, here's some results from my 64-bit Win7 box running 32-bit Python:

3.4.0b1 (default:eae6966d9734+, Dec 21 2013, 15:47:14) [MSC v.1600 32 bit (Intel)]
sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1')
Running:
import time
import sys
print(sys.version)
print(sys.getwindowsversion())

with open(__file__) as file:
    print('Running:')
    print(file.read())

for i in range(10):
    # copied from test_monotonic, with regular assert and added prints
    t1 = time.monotonic()
    time.sleep(0.5)
    t2 = time.monotonic()
    dt = t2 - t1
    assert t2 > t1
    print(i, t1, t2, dt, sep='\t')
    print('  assertion', 'passed' if 0.5 <= dt <= 1.0 else 'failed')

0 243323.54200000002 243324.041 0.4989999999816064
assertion failed
1 243324.041 243324.54 0.4990000000107102
assertion failed
2 243324.54 243325.03900000002 0.4990000000107102
assertion failed
3 243325.03900000002 243325.53900000002 0.5
assertion passed
4 243325.53900000002 243326.038 0.4989999999816064
assertion failed
5 243326.038 243326.537 0.4990000000107102
assertion failed
6 243326.537 243327.036 0.4989999999816064
assertion failed
7 243327.036 243327.535 0.4990000000107102
assertion failed
8 243327.535 243328.035 0.5
assertion passed
9 243328.035 243328.534 0.4990000000107102
assertion failed

I suspect there's some rounding going on somewhere, making dt usually about 0.499, not 0.5. Relaxing the condition to '0.498 < dt < 1.0' should be adequate, since I don't think a thousandth of a second only part of the time is enough to say there's a behavior issue.

I haven't seen this fail on any buildbots, but I suspect most of them are just loaded a bit heavier than my laptop is when I see this.

[tim-one]

@zach, "it would be nice" to know more about this. I tried your little program on a desktop box, 32-bit Windows Vista, Python 3.3.2, but I boosted the loop count to 10,000. So it ran well over an hour, with a wide variety of other loads (from 0 to 4 (of 4) cores busy). dt was never less than 0.5. It was exactly 0.5 9,997(!) times, and a little larger than 0.5 the remaining 3 times. Yes, I was surprised too ;-)

[zware]

That's weird. I ran the same test on the same computer with an installed 64-bit 3.3.2, and got the same results (70+% failure). I just ran the same test on a different computer (32-bit Windows 7), and also got the same results with both 3.4.0b1+ and 3.3.2 (installed).

FTR:
>>> time.get_clock_info('monotonic')
namespace(adjustable=False, implementation='GetTickCount64()', monotonic=True, resolution=0.015600099999999999)

I believe it's the same for all four Pythons tested.

Shall I open a new issue for this, or is it related enough to stay here? :)

[tim-one]

Hmm. One obvious difference on my box:

Python 3.3.2 (v3.3.2:d047928ae3f6, May 16 2013, 00:03:43) [MSC v.1600 32 bit (Intel)] on win32
>>> time.get_clock_info('monotonic')
namespace(adjustable=False, implementation='GetTickCount64()', monotonic=True, resolution=0.015625)

So the "resolution" here is exactly 1/64. If that's truly the resolution, then all the results I'll see are exactly representable as Python floats.

The "resolution" you see (0.015600099999999999) looks bizarre. Not because of the trailing nines, but because 0.0156001 doesn't appear to have any natural hardware or software meaning in decimal or binary.

That said, I see we get the resolution from GetSystemTimeAdjustment. I don't understand the Windows time functions, but also don't see anything in the MSDN docs to suggest that the results from GetSystemTimeAdjustment "should have" anything to do with the resolution of GetTickCount64. But maybe they do - LOL ;-)

One other point: we have lots of code of the form:

    info->resolution = timeIncrement * 1e-7;

That is, we multiply some integer type by a double _negative_ power of 10. All such code is needlessly inaccurate: no negative power of 10 is exactly representable as a double, so we suffer a rounding error in representing 1e-7, and then another rounding error from the multiplication. It's trivial to reduce the grand total to one rounding error instead, by rewriting as:

    info->resolution = timeIncrement / 1e7;

But these rounding errors are too tiny to account for the difference between, e.g., 0.4990000000107102 and 0.5.

I don't conclude that we don't know what we're doing, but I bet we don't really understand what Windows is doing ;-)

[vstinner]

For more info on time, you can refer to the PEP-418.

I may be interesting to add "sleep" to time.get_clock_info(). time.sleep()
uses WaitForSingleObject() on windows. It may use internally a different
clock with a different resolution than time.monoyonic (GetTickCount). The
PEP says "WaitForSingleObject(): use the same timer than GetTickCount()
with the same precision."

I don't think that it's very useful to investigate the rounding issue on
Windows. The resolution of Windows clocks is very coarse (15 ms, 10^-2)
compared to Unix clocks (usually a few nanoseconds, 10^-9)... I changed
recently the unit test to check if a sleep of 0.5 seconds gives a time
delta of at least 0.5 seconds. The minimum delta can be set to 0.45 sec
with a comment refering to this issue.

[tim-one]

@Haypo, I've read the PEP and it has great ideas. What I'm wondering is whether they've been implemented "correctly" in the relevant cases on Windows here. That Zach see a resolution of 0.0156001 on Windows isn't plausibly a question of rounding errors: that value appears to be insane. Yes, it's vaguely close to the 0.015625 I see, but the value I see _is_ sane (being exactly 1/64) - but 0.0156001 isn't close enough to 0.015625 for "rounding errors" to be at all a plausible explanation for why it's so strange.

[tim-one]

FYI, this person seems to have made a career ;-) of making sense of the Windows time functions:

http://stackoverflow.com/questions/7685762/windows-7-timing-functions-how-to-use-getsystemtimeadjustment-correctly

and their site:

http://www.windowstimestamp.com/description

Bottom line is that it's messy as everything else on Windows :-( They claim, among other things:

• "GetSystemTimeAdjustment is not the function to look at."

• The undocumented NtQueryTimerResolution() is the function to look at.

• "Time Adjustment: 0.0156001 clearly identifies windows VISTA or higher with HPET and/or constant/invariant TSC on your system."

Screw it - I'm gonna go shovel more snow ;-)

[vstinner]

but 0.0156001 isn't close enough to 0.015625 for "rounding errors" to be at all a plausible explanation for why it's so strange.

0.0156001 is close to 0.0156, and this number cannot be representated exactly in binary:

>>> (0.0156).hex()
'0x1.ff2e48e8a71dep-7'

C code used by Python:

GetSystemTimeAdjustment(&timeAdjustment, &timeIncrement,
&isTimeAdjustmentDisabled);
info->resolution = timeIncrement * 1e-7;

(And yes, 0.0156001 is surprising, I also expected 1/64, 0.015625)