Executor.map and as_completed timeouts are able to deviate

[orlnub123]

BPO	34819
Nosy	@pitrou, @vstinner, @miss-islington, @tirkarthi, @orlnub123
PRs	bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures #9599 [3.6] bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599) #9600 [3.7] bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599) #9601

^{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 = None
closed_at = <Date 2018-09-27.11:47:19.724>
created_at = <Date 2018-09-27.09:51:51.392>
labels = ['3.7', '3.8', 'type-bug', 'library']
title = 'Executor.map and as_completed timeouts are able to deviate'
updated_at = <Date 2018-09-27.11:47:19.723>
user = 'https://github.com/orlnub123'

bugs.python.org fields:

activity = <Date 2018-09-27.11:47:19.723>
actor = 'pitrou'
assignee = 'none'
closed = True
closed_date = <Date 2018-09-27.11:47:19.724>
closer = 'pitrou'
components = ['Library (Lib)']
creation = <Date 2018-09-27.09:51:51.392>
creator = 'orlnub123'
dependencies = []
files = []
hgrepos = []
issue_num = 34819
keywords = ['patch']
message_count = 8.0
messages = ['326535', '326538', '326542', '326548', '326550', '326552', '326553', '326554']
nosy_count = 5.0
nosy_names = ['pitrou', 'vstinner', 'miss-islington', 'xtreak', 'orlnub123']
pr_nums = ['9599', '9600', '9601']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34819'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[orlnub123]

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.

[tirkarthi]

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 : bpo-34054. 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

[tirkarthi]

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

[pitrou]

New changeset a94ee12 by Antoine Pitrou (orlnub123) in branch 'master':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
a94ee12

[vstinner]

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!

[miss-islington]

New changeset 3a4aa6a by Miss Islington (bot) in branch '3.6':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
3a4aa6a

[orlnub123]

Happy to help! I'm surprised it got merged so quickly, amazing response times all-around.

[miss-islington]

New changeset 2b01121 by Miss Islington (bot) in branch '3.7':
bpo-34819: Use a monotonic clock to compute timeouts in concurrent.futures (GH-9599)
2b01121