Issue19999
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.
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) * | 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) | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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) * | 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:55 | admin | set | github: 64198 |
2013-12-24 14:18:26 | vstinner | set | messages: + msg206891 |
2013-12-24 14:08:08 | vstinner | set | messages: + msg206890 |
2013-12-24 03:26:39 | tim.peters | set | messages: + msg206886 |
2013-12-24 03:10:07 | tim.peters | set | messages: + msg206885 |
2013-12-23 21:32:43 | vstinner | set | messages: + msg206874 |
2013-12-23 18:17:48 | tim.peters | set | messages: + msg206870 |
2013-12-23 15:51:06 | zach.ware | set | messages: + msg206865 |
2013-12-23 05:33:49 | tim.peters | set | nosy:
+ tim.peters messages: + msg206841 |
2013-12-22 21:55:19 | zach.ware | set | nosy:
+ zach.ware messages: + msg206833 |
2013-12-16 22:22:21 | vstinner | set | messages: + msg206380 |
2013-12-16 21:39:24 | python-dev | set | status: open -> closed nosy: + python-dev messages: + msg206372 resolution: fixed stage: test needed -> resolved |
2013-12-16 18:46:57 | christian.heimes | create |