classification
Title: test_time.test_thread_time() failed on AMD64 Debian root 3.x
Type: Stage: resolved
Components: Tests Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: miss-islington, pitrou, vstinner
Priority: normal Keywords: patch, patch

Created on 2018-05-31 21:45 by vstinner, last changed 2018-11-28 20:32 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 8265 closed vstinner, 2018-07-12 10:43
PR 8265 closed vstinner, 2018-07-12 10:43
PR 8267 merged vstinner, 2018-07-12 12:26
PR 8268 merged miss-islington, 2018-07-12 13:26
PR 8358 merged vstinner, 2018-07-21 00:27
PR 8362 merged miss-islington, 2018-07-21 01:32
PR 10723 closed vstinner, 2018-11-26 16:31
PR 10724 merged vstinner, 2018-11-26 16:40
PR 10726 merged miss-islington, 2018-11-26 20:19
PR 10773 merged vstinner, 2018-11-28 17:01
PR 10776 merged miss-islington, 2018-11-28 17:30
Messages (17)
msg318344 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-31 21:45
AMD64 Debian root 3.x:

http://buildbot.python.org/all/#/builders/27/builds/1067

======================================================================
FAIL: test_thread_time (test.test_time.TimeTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/root/buildarea/3.x.angelico-debian-amd64/build/Lib/test/test_time.py", line 536, in test_thread_time
    self.assertGreaterEqual(stop - start, 0.020)  # machine busy?
AssertionError: 0.019943113999999984 not greater than or equal to 0.02
msg321537 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-12 10:44
The following test failed:

        # thread_time() should include CPU time spent in current thread...
        start = time.thread_time()
        busy_wait(0.100)
        stop = time.thread_time()
        self.assertGreaterEqual(stop - start, 0.020)  # machine busy?

def busy_wait(duration):
    deadline = time.monotonic() + duration
    while time.monotonic() < deadline:
        pass

Do we really have to have functional tests on Python block functions? These tests seem very fragile...

I proposed the PR 8265 to remove these fragile tests.

I chose to keep time.process_time() functional test. We can remove it later if it starts failing on a buildbot.
msg321548 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-12 13:25
New changeset d6345def68d3a0227253da26213dadb247f786db by Victor Stinner in branch 'master':
bpo-33723: Fix test_time.test_thread_time() (GH-8267)
https://github.com/python/cpython/commit/d6345def68d3a0227253da26213dadb247f786db
msg321555 - (view) Author: miss-islington (miss-islington) Date: 2018-07-12 14:05
New changeset 4ada0cff5315627eae8208adf0209b479f497b8d by Miss Islington (bot) in branch '3.7':
bpo-33723: Fix test_time.test_thread_time() (GH-8267)
https://github.com/python/cpython/commit/4ada0cff5315627eae8208adf0209b479f497b8d
msg322046 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-21 00:28
I reopen the issue since I got a very similar failure of test_time.test_process_time() on my laptop: the busy loop took 15.9 ms
whereas the test expects at least 20 ms. I wrote PR 8358 to only require 15 ms instead.
msg322056 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-21 01:31
New changeset e78dace8dcb23c371df19c9add65895adf436995 by Victor Stinner in branch 'master':
bpo-33723: Fix test_time.test_process_time() (GH-8358)
https://github.com/python/cpython/commit/e78dace8dcb23c371df19c9add65895adf436995
msg322058 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-21 01:52
New changeset a7a6eac966dd52db1762c8f455c1e208df36feb4 by Victor Stinner (Miss Islington (bot)) in branch '3.7':
bpo-33723: Fix test_time.test_process_time() (GH-8358) (GH-8362)
https://github.com/python/cpython/commit/a7a6eac966dd52db1762c8f455c1e208df36feb4
msg322059 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-07-21 01:53
I changed the minimum time from 20 ms to 15 ms in test_time.test_process_time(), in Python 3.7 and master branches.
msg330448 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-26 16:39
New failure on AppVeyor:

FAIL: test_thread_time (test.test_time.TimeTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_time.py", line 553, in test_thread_time
    self.assertLess(stop - start, min_time)
AssertionError: 0.015625 not less than 0.015
msg330449 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-26 16:41
Oh. In my previous attempt, I changed the minimum time from 20 ms to 15 ms. But I didn't notice that one check uses assertLess() rather than assertGreaterEqual(). So I wrote PR 10724 to change the maximum from 15 ms to 30 ms in test_thread_time().
msg330459 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-26 20:19
New changeset 65c216e74f7957006ef7653b7e2afe83007c45ce by Victor Stinner in branch 'master':
bpo-33723: Fix test_time.test_thread_time() (GH-10724)
https://github.com/python/cpython/commit/65c216e74f7957006ef7653b7e2afe83007c45ce
msg330461 - (view) Author: miss-islington (miss-islington) Date: 2018-11-26 20:36
New changeset 5350dd1b50e60882a2da6d53ed27e02d2b698f2e by Miss Islington (bot) in branch '3.7':
bpo-33723: Fix test_time.test_thread_time() (GH-10724)
https://github.com/python/cpython/commit/5350dd1b50e60882a2da6d53ed27e02d2b698f2e
msg330462 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-26 20:50
I close again the bug.
msg330612 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-28 17:03
A test failed again on AppVeyor! In the 3.7 branch, on this test:

def busy_wait(duration):
    deadline = time.monotonic() + duration
    while time.monotonic() < deadline:
        pass
(...)
    def test_thread_time(self):
        (...)
        # bpo-33723: A busy loop of 100 ms should increase thread_time()
        # by at least 15 ms, but less than 30 ms in other threads.
        # Tolerate 15 and 30 ms because of the bad resolution
        # of the clock on Windows (around 15.6 ms).
        min_time = 0.015
        max_time = 0.030
        busy_time = 0.100

        # thread_time() should include CPU time spent in current thread...
        start = time.thread_time()
        busy_wait(busy_time)
        stop = time.thread_time()
        self.assertGreaterEqual(stop - start, min_time)   # <===== HERE =====
        (...)

FAIL: test_thread_time (test.test_time.TimeTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\projects\cpython\lib\test\test_time.py", line 550, in test_thread_time
    self.assertGreaterEqual(stop - start, min_time)
AssertionError: 0.0 not greater than or equal to 0.015

IMHO the root issue is that time.thread_time() and time.monotonic() clocks are just... unrelated... on Windows.

This time, I give up and wrote a PR to remove the "busy loop" tests, sorry! PR 10773.
msg330620 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-28 17:30
New changeset 48498dd57f79ab1d061c754ad6a2ebe1a7172b0e by Victor Stinner in branch 'master':
bpo-33723: Remove busy loop from test_time (GH-10773)
https://github.com/python/cpython/commit/48498dd57f79ab1d061c754ad6a2ebe1a7172b0e
msg330625 - (view) Author: miss-islington (miss-islington) Date: 2018-11-28 17:58
New changeset d46d753d152a5d01f9c454d18b1ae660509d9b16 by Miss Islington (bot) in branch '3.7':
bpo-33723: Remove busy loop from test_time (GH-10773)
https://github.com/python/cpython/commit/d46d753d152a5d01f9c454d18b1ae660509d9b16
msg330629 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-11-28 20:32
I removed the "busy loop" tests from 3.7 and master.
History
Date User Action Args
2018-11-28 20:32:42vstinnersetstatus: open -> closed
messages: + msg330629

keywords: patch, patch
resolution: fixed
stage: patch review -> resolved
2018-11-28 17:58:34miss-islingtonsetmessages: + msg330625
2018-11-28 17:30:21miss-islingtonsetstage: resolved -> patch review
pull_requests: + pull_request10020
2018-11-28 17:30:12vstinnersetmessages: + msg330620
2018-11-28 17:03:59vstinnersetkeywords: patch, patch
status: closed -> open
resolution: fixed -> (no value)
messages: + msg330612
2018-11-28 17:01:55vstinnersetpull_requests: + pull_request10017
2018-11-26 20:50:20vstinnersetstatus: open -> closed
messages: + msg330462

keywords: patch, patch
resolution: fixed
stage: patch review -> resolved
2018-11-26 20:36:58miss-islingtonsetmessages: + msg330461
2018-11-26 20:19:55miss-islingtonsetpull_requests: + pull_request9974
2018-11-26 20:19:34vstinnersetmessages: + msg330459
2018-11-26 16:41:59vstinnersetkeywords: patch, patch

messages: + msg330449
2018-11-26 16:40:51vstinnersetstage: resolved -> patch review
pull_requests: + pull_request9971
2018-11-26 16:39:44vstinnersetkeywords: patch, patch
status: closed -> open
resolution: fixed -> (no value)
2018-11-26 16:39:38vstinnersetkeywords: patch, patch

messages: + msg330448
2018-11-26 16:31:16vstinnersetpull_requests: + pull_request9970
2018-07-21 01:53:33vstinnersetstatus: open -> closed
messages: + msg322059

keywords: patch, patch
resolution: fixed
stage: patch review -> resolved
2018-07-21 01:52:46vstinnersetmessages: + msg322058
2018-07-21 01:32:07miss-islingtonsetstage: resolved -> patch review
pull_requests: + pull_request7897
2018-07-21 01:31:53vstinnersetmessages: + msg322056
2018-07-21 00:28:53vstinnersetkeywords: patch, patch
status: closed -> open
resolution: fixed -> (no value)
messages: + msg322046
2018-07-21 00:27:52vstinnersetpull_requests: + pull_request7894
2018-07-12 14:23:24vstinnersetkeywords: patch, patch
status: open -> closed
stage: patch review -> resolved
resolution: fixed
versions: + Python 3.7
2018-07-12 14:05:48miss-islingtonsetnosy: + miss-islington
messages: + msg321555
2018-07-12 13:26:43miss-islingtonsetpull_requests: + pull_request7803
2018-07-12 13:25:33vstinnersetmessages: + msg321548
2018-07-12 12:26:11vstinnersetpull_requests: + pull_request7802
2018-07-12 10:44:02vstinnersetkeywords: patch, patch

messages: + msg321537
2018-07-12 10:43:51vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request7798
2018-07-12 10:43:51vstinnersetkeywords: + patch
stage: (no value)
pull_requests: + pull_request7799
2018-05-31 21:45:16vstinnercreate