classification
Title: Executor.map and as_completed timeouts are able to deviate
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: miss-islington, orlnub123, pitrou, vstinner, xtreak
Priority: normal Keywords: patch

Created on 2018-09-27 09:51 by orlnub123, last changed 2018-09-27 11:47 by pitrou. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 9599 merged orlnub123, 2018-09-27 09:58
PR 9600 merged miss-islington, 2018-09-27 11:18
PR 9601 merged miss-islington, 2018-09-27 11:18
Messages (8)
msg326535 - (view) Author: (orlnub123) * Date: 2018-09-27 09:51
The map and as_completed functions can randomly timeout earlier or later due to NTP stepping the clock or something changing the time and/or date.

Here's some code to reproduce the issue for map:

import concurrent.futures
import time

with concurrent.futures.ThreadPoolExecutor() as executor:
    list(executor.map(time.sleep, [29, 30], timeout=3000))

And similar code to reproduce it for as_completed:

import concurrent.futures
import time

with concurrent.futures.ThreadPoolExecutor() as executor:
    future1 = executor.submit(time.sleep, 29)
    future2 = executor.submit(time.sleep, 30)
    list(concurrent.futures.as_completed([future1, future2], timeout=3000))

It doesn't error normally, as it shouldn't, but if you move your clock an hour ahead within 30 seconds of running it you get this:

Traceback (most recent call last):
  File "<stdin>", line 2, in <module>
  File "C:\Python\Python37\lib\concurrent\futures\_base.py", line 588, in result_iterator
    yield fs.pop().result(end_time - time.time())
  File "C:\Python\Python37\lib\concurrent\futures\_base.py", line 434, in result
    raise TimeoutError()
concurrent.futures._base.TimeoutError

Or this if you used the as_completed example:

Traceback (most recent call last):
  File "<stdin>", line 4, in <module>
  File "C:\Python\Python37\lib\concurrent\futures\_base.py", line 238, in as_completed
    len(pending), total_futures))
concurrent.futures._base.TimeoutError: 1 (of 2) futures unfinished

The error stems from map and as_completed using time.time to calculate the duration for the timeout. The problem with time.time is that it's adjustable (i.e. it can skip around) which makes it unideal for comparing relative times. A solution would be to replace the time.time calls with either time.monotonic (preferable?) or time.perf_counter.
msg326538 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2018-09-27 10:10
Thanks for the report and PR. I can find a very similar issue where time.time was changed to time.monotonic across multiprocessing module by Victor for the same reason : issue34054. I don't know why it wasn't changed in concurrent.futures . Seems this was reported here : https://bugs.python.org/issue29733#msg289116. I am adding Victor and Antoine who might have thoughts on this. Feel free to remove yourself if it's not relevant.

Thanks
msg326542 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python triager) Date: 2018-09-27 11:04
Sorry, please ignore the comment reference to https://bugs.python.org/issue29733#msg289116 . I misunderstood that it was about concurrent.futures using time.time but it turns out it was about the program using time.time as verifying the PR against the issue still has the timeout error.

Thanks
msg326548 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2018-09-27 11:16
New changeset a94ee12c26aa8dd7dce01373779df8055aff765b by Antoine Pitrou (orlnub123) in branch 'master':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
https://github.com/python/cpython/commit/a94ee12c26aa8dd7dce01373779df8055aff765b
msg326550 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-09-27 11:20
Oh, I missed the Lib/concurrent/futures/ directory when I tried to patch the whole stdlib to use monotonic clocks for timeouts :-( Thanks for the fix!
msg326552 - (view) Author: miss-islington (miss-islington) Date: 2018-09-27 11:37
New changeset 3a4aa6ac55e04c42757443d5b5854b6d893e0461 by Miss Islington (bot) in branch '3.6':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
https://github.com/python/cpython/commit/3a4aa6ac55e04c42757443d5b5854b6d893e0461
msg326553 - (view) Author: (orlnub123) * Date: 2018-09-27 11:46
Happy to help! I'm surprised it got merged so quickly, amazing response times all-around.
msg326554 - (view) Author: miss-islington (miss-islington) Date: 2018-09-27 11:46
New changeset 2b01121fd4200f1c27873422f7f72d02eec08630 by Miss Islington (bot) in branch '3.7':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
https://github.com/python/cpython/commit/2b01121fd4200f1c27873422f7f72d02eec08630
History
Date User Action Args
2018-09-27 11:47:19pitrousetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2018-09-27 11:46:41miss-islingtonsetmessages: + msg326554
2018-09-27 11:46:15orlnub123setmessages: + msg326553
2018-09-27 11:37:37miss-islingtonsetnosy: + miss-islington
messages: + msg326552
2018-09-27 11:20:45vstinnersetmessages: + msg326550
2018-09-27 11:18:51miss-islingtonsetpull_requests: + pull_request9001
2018-09-27 11:18:45miss-islingtonsetpull_requests: + pull_request9000
2018-09-27 11:16:31pitrousetmessages: + msg326548
2018-09-27 11:04:23xtreaksetmessages: + msg326542
2018-09-27 10:10:19xtreaksetnosy: + pitrou, vstinner
messages: + msg326538
2018-09-27 09:59:30xtreaksetnosy: + xtreak
2018-09-27 09:58:05orlnub123setkeywords: + patch
stage: patch review
pull_requests: + pull_request8996
2018-09-27 09:51:51orlnub123create