asyncio: proactor read transport: use recv_into instead of recv

[tontinton]

BPO	41273
Nosy	@db3l, @scoder, @vstinner, @1st1, @tontinton
PRs	bpo-41273: asyncio's proactor read transport's better performance by using recv_into instead of recv #21439 bpo-41273: asyncio's proactor read transport's better performance by using recv_into instead of recv #21442 bpo-41279: Add StreamReaderBufferedProtocol #21446

^{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 = None
created_at = <Date 2020-07-10.21:08:56.958>
labels = []
title = 'asyncio: proactor read transport: use recv_into instead of recv'
updated_at = <Date 2020-08-06.09:48:07.805>
user = 'https://github.com/tontinton'

bugs.python.org fields:

activity = <Date 2020-08-06.09:48:07.805>
actor = 'vstinner'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = []
creation = <Date 2020-07-10.21:08:56.958>
creator = 'tontinton'
dependencies = []
files = []
hgrepos = []
issue_num = 41273
keywords = ['patch']
message_count = 10.0
messages = ['373483', '373655', '373935', '373969', '373970', '373974', '373981', '373996', '374896', '374924']
nosy_count = 5.0
nosy_names = ['db3l', 'scoder', 'vstinner', 'yselivanov', 'tontinton']
pr_nums = ['21439', '21442', '21446']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue41273'
versions = []

[tontinton]

Using recv_into instead of recv in the transport _loop_reading will speed up the process.

From what I checked it's about 120% performance increase.

This is only because there should not be a new buffer allocated each time we call recv, it's really wasteful.

[1st1]

New changeset 568fb0f by Tony Solomonik in branch 'master':
bpo-41273: asyncio's proactor read transport's better performance by using recv_into instead of recv (bpo-21442)
568fb0f

[scoder]

There have been sporadic buildbot failures in "test_asyncio" since this change, message being "1 test altered the execution environment", e.g.

https://buildbot.python.org/all/#/builders/129/builds/1443

Could someone please check if they are related?

[db3l]

I can at least confirm that this commit is the source of the issue on the Windows 10 buildbot. Interactively, it fails every time with it in place (unlike the buildbot which has had the occasional success) and passes reliably with it reverted.

The error arises during the SubprocessProactorTests test suite, but seemingly not with a specific test, just something that shows up when the entire suite is run. At least I haven't been able to get it to occur by running individual tests.

Since the buildbot test output hides the underlying exception, here's the details of the two unraisable exceptions in question from test_asyncio.test_subprocess.SubprocessProactorTests. I enabled tracemalloc but the original allocation is from the common utils module so probably not that much extra help:

D:\test\cpython\lib\asyncio\windows_utils.py:112: ResourceWarning: unclosed <PipeHandle handle=424>
  _warn(f"unclosed {self!r}", ResourceWarning, source=self)
Object allocated at (most recent call last):
  File "D:\test\cpython\lib\asyncio\windows_utils.py", lineno 164
    self.stdout = PipeHandle(stdout_rh)
D:\test\cpython\lib\asyncio\windows_utils.py:112: ResourceWarning: unclosed <PipeHandle handle=476>
  _warn(f"unclosed {self!r}", ResourceWarning, source=self)
Object allocated at (most recent call last):
  File "D:\test\cpython\lib\asyncio\windows_utils.py", lineno 166
    self.stderr = PipeHandle(stderr_rh)
Exception ignored in: <function _ProactorBasePipeTransport.__del__ at 0x000001DEB55D14B0>
Traceback (most recent call last):
  File "D:\test\cpython\lib\asyncio\proactor_events.py", line 115, in __del__
    _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
  File "D:\test\cpython\lib\asyncio\proactor_events.py", line 79, in __repr__
    info.append(f'fd={self._sock.fileno()}')
  File "D:\test\cpython\lib\asyncio\windows_utils.py", line 102, in fileno
    raise ValueError("I/O operation on closed pipe")
ValueError: I/O operation on closed pipe
Exception ignored in: <function _ProactorBasePipeTransport.__del__ at 0x000001DEB55D14B0>
Traceback (most recent call last):
  File "D:\test\cpython\lib\asyncio\proactor_events.py", line 115, in __del__
    _warn(f"unclosed transport {self!r}", ResourceWarning, source=self)
  File "D:\test\cpython\lib\asyncio\proactor_events.py", line 79, in __repr__
    info.append(f'fd={self._sock.fileno()}')
  File "D:\test\cpython\lib\asyncio\windows_utils.py", line 102, in fileno
    raise ValueError("I/O operation on closed pipe")
ValueError: I/O operation on closed pipe

[tontinton]

I see, I'll start working on a fix soon

[tontinton]

Ok so I checked and the PR I am currently having a CR on fixes this issue: #21446

Do you want me to make a different PR tomorrow that fixes this specific issue to get it faster to master or is it ok to wait a bit?

[db3l]

First, I also no longer see the error with a local PR 21446 build on the Win10 buildbot.

As for timing, I believe policy is to revert, but in my view it can probably depend on how short "a bit" is for the fix. We've been in this state for 4-5 days already, so one more day, for example, probably won't matter that much.

If it looks like it'll be longer, or the timing is uncertain, then I'd probably suggest reverting until the new PR is ready.

[tontinton]

If the error is not resolved yet, I would prefer if we revert this change then.

The new PR is kinda big I don't know when it will be merged.

[db3l]

It looks like there was an underlying asyncio.recv_into bug that was the likely root issue here. It's recently been fixed in bpo-41467, and test_asyncio is passing on at least the Win10 buildbot.

[vstinner]

Tony: "asyncio: proactor read transport: use recv_into instead of recv" seems to be implemented, but PR 21446 "bpo-41279: Add StreamReaderBufferedProtocol" is a new feature. I suggest to open a new issue for this feature, and close this one.