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: test_monotonic fails on x86 OpenIndiana
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vstinner Nosy List: christian.heimes, python-dev, tim.peters, vstinner, zach.ware
Priority: low Keywords: buildbot

Created on 2013-12-16 18:46 by christian.heimes, last changed 2022-04-11 14:57 by admin. This issue is now closed.

Messages (12)
msg206344 - (view) Author: Christian Heimes (christian.heimes) * (Python committer) Date: 2013-12-16 18:46
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

----------------------------------------------------------------------
msg206372 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2013-12-16 21:39
New changeset 4864c0b914ae by Victor Stinner in branch '3.3':
Close #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 #19999: tolerate coarse time when testing time.monotonic() on
http://hg.python.org/cpython/rev/a34582c53911
msg206380 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2013-12-16 22:22
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
msg206833 - (view) Author: Zachary Ware (zach.ware) * (Python committer) Date: 2013-12-22 21:55
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.
msg206841 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-12-23 05:33
@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 ;-)
msg206865 - (view) Author: Zachary Ware (zach.ware) * (Python committer) Date: 2013-12-23 15:51
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? :)
msg206870 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-12-23 18:17
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 ;-)
msg206874 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2013-12-23 21:32
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.
msg206885 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-12-24 03:10
@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.
msg206886 - (view) Author: Tim Peters (tim.peters) * (Python committer) Date: 2013-12-24 03:26
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 ;-)
msg206890 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2013-12-24 14:08
> 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)
msg206891 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2013-12-24 14:18
> "GetSystemTimeAdjustment is not the function to look at."

This sentence comes from http://stackoverflow.com/questions/7685762/windows-7-timing-functions-how-to-use-getsystemtimeadjustment-correctly which describes the wall clock (GetSystemTimeAsFileTime), not the monotonic clock (GetTickCount[64]).

GetTickCount[64] resolution cannot be better than 1 ms because its C structure has a resolution of 1 ms...

But I don't know any other *monotonic* clock with a better resolution.

Python 3.3 provides time.perf_counter(): "clock with the highest available resolution to measure a short duration". I added this function because of Windows, to give access to QueryPerformanceCounter().

@Tim: This issue is closed. If you believe that Python time functions are buggy on windows, which is quite possible, please open a *new* issue. (This issue was specific to OpenIndiana buildbot which looks to be ill.)

The C function pygettimeofday() which is used by time.time() and time.get_clock_info() uses GetSystemTimeAsFileTime() and GetSystemTimeAdjustment(). According to the article, there is a bug.
History
Date User Action Args
2022-04-11 14:57:55adminsetgithub: 64198
2013-12-24 14:18:26vstinnersetmessages: + msg206891
2013-12-24 14:08:08vstinnersetmessages: + msg206890
2013-12-24 03:26:39tim.peterssetmessages: + msg206886
2013-12-24 03:10:07tim.peterssetmessages: + msg206885
2013-12-23 21:32:43vstinnersetmessages: + msg206874
2013-12-23 18:17:48tim.peterssetmessages: + msg206870
2013-12-23 15:51:06zach.waresetmessages: + msg206865
2013-12-23 05:33:49tim.peterssetnosy: + tim.peters
messages: + msg206841
2013-12-22 21:55:19zach.waresetnosy: + zach.ware
messages: + msg206833
2013-12-16 22:22:21vstinnersetmessages: + msg206380
2013-12-16 21:39:24python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg206372

resolution: fixed
stage: test needed -> resolved
2013-12-16 18:46:57christian.heimescreate