classification
Title: asyncio: proactor read transport: use recv_into instead of recv
Type: Stage: patch review
Components: Versions:
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: db3l, scoder, tontinton, vstinner, yselivanov
Priority: normal Keywords: patch

Created on 2020-07-10 21:08 by tontinton, last changed 2020-08-06 09:48 by vstinner.

Pull Requests
URL Status Linked Edit
PR 21439 closed tontinton, 2020-07-11 02:11
PR 21442 merged tontinton, 2020-07-11 09:09
PR 21446 open tontinton, 2020-07-11 17:18
Messages (10)
msg373483 - (view) Author: Tony (tontinton) * Date: 2020-07-10 21:08
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.
msg373655 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2020-07-14 19:41
New changeset 568fb0ff4aa641329261cdde20795b0aa9278175 by Tony Solomonik in branch 'master':
bpo-41273: asyncio's proactor read transport's better performance by using recv_into instead of recv (#21442)
https://github.com/python/cpython/commit/568fb0ff4aa641329261cdde20795b0aa9278175
msg373935 - (view) Author: Stefan Behnel (scoder) * (Python committer) Date: 2020-07-19 06:55
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?
msg373969 - (view) Author: David Bolen (db3l) * Date: 2020-07-19 18:58
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
msg373970 - (view) Author: Tony (tontinton) * Date: 2020-07-19 19:10
I see, I'll start working on a fix soon
msg373974 - (view) Author: Tony (tontinton) * Date: 2020-07-19 22:04
Ok so I checked and the PR I am currently having a CR on fixes this issue: https://github.com/python/cpython/pull/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?
msg373981 - (view) Author: David Bolen (db3l) * Date: 2020-07-20 03:45
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.
msg373996 - (view) Author: Tony (tontinton) * Date: 2020-07-20 10:19
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.
msg374896 - (view) Author: David Bolen (db3l) * Date: 2020-08-05 18:57
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.
msg374924 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-08-06 09:48
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.
History
Date User Action Args
2020-08-06 09:48:07vstinnersetnosy: + vstinner
messages: + msg374924
2020-08-05 18:57:37db3lsetmessages: + msg374896
2020-07-20 10:19:05tontintonsetmessages: + msg373996
2020-07-20 03:45:02db3lsetmessages: + msg373981
2020-07-19 22:04:42tontintonsetmessages: + msg373974
2020-07-19 19:10:12tontintonsetmessages: + msg373970
2020-07-19 18:58:17db3lsetnosy: + db3l
messages: + msg373969
2020-07-19 06:55:37scodersetnosy: + scoder
messages: + msg373935
2020-07-14 19:41:39yselivanovsetnosy: + yselivanov
messages: + msg373655
2020-07-11 17:18:17tontintonsetpull_requests: + pull_request20593
2020-07-11 09:09:17tontintonsetpull_requests: + pull_request20589
2020-07-11 02:11:25tontintonsetkeywords: + patch
stage: patch review
pull_requests: + pull_request20588
2020-07-10 21:08:56tontintoncreate