classification
Title: test_asyncio: test_sock_sendfile_mix_with_regular_send() hangs on FreeBSD
Type: Stage: resolved
Components: asyncio, FreeBSD Versions: Python 3.8, Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, koobs, miss-islington, vstinner, yselivanov
Priority: normal Keywords: patch

Created on 2018-04-25 14:08 by vstinner, last changed 2018-05-29 19:59 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 7083 merged vstinner, 2018-05-23 22:38
PR 7084 closed miss-islington, 2018-05-23 22:57
PR 7086 merged vstinner, 2018-05-24 00:29
PR 7087 merged vstinner, 2018-05-24 00:58
PR 7200 merged vstinner, 2018-05-29 12:31
PR 7202 merged miss-islington, 2018-05-29 14:02
Messages (20)
msg315733 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-04-25 14:08
Example with a timeout of 10 seconds:

vstinner@freebsd$ ./python -m test -v test_asyncio -m test_sock_sendfile_mix_with_regular_send -v --timeout=10
== CPython 3.8.0a0 (heads/master:0977091dca, Apr 25 2018, 14:02:04) [Clang 4.0.0 (tags/RELEASE_400/final 297347)]
== FreeBSD-11.1-RELEASE-amd64-64bit-ELF little-endian
== cwd: /usr/home/vstinner/prog/python/master/build/test_python_8317
== CPU count: 2
== encodings: locale=UTF-8, FS=utf-8
Run tests sequentially
0:00:00 load avg: 0.59 [1/1] test_asyncio
test_sock_sendfile_mix_with_regular_send (test.test_asyncio.test_events.KqueueEventLoopTests) ... Timeout (0:00:10)!
Thread 0x0000000801a16000 (most recent call first):
  File "/usr/home/vstinner/prog/python/master/Lib/asyncio/selector_events.py", line 456 in _sock_sendall
  File "/usr/home/vstinner/prog/python/master/Lib/asyncio/events.py", line 88 in _run
  File "/usr/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 1738 in _run_once
  File "/usr/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 521 in run_forever
  File "/usr/home/vstinner/prog/python/master/Lib/asyncio/base_events.py", line 553 in run_until_complete
  File "/usr/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_events.py", line 2117 in run_loop
  File "/usr/home/vstinner/prog/python/master/Lib/test/test_asyncio/test_events.py", line 2213 in test_sock_sendfile_mix_with_regular_send
  (...)

The test has been introduced in by the commit a19fb3c6aaa7632410d1d9dcb395d7101d124da4, bpo-32622.

The FreeBSD 3.7 and 3.x buildbots are broken, likely since this commit.
msg317470 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-23 22:56
New changeset 2932755cc11fd82b4908d60b24b837aa4f3028e6 by Victor Stinner in branch 'master':
bpo-33353: test_asyncio uses smaller sendfile data (#7083)
https://github.com/python/cpython/commit/2932755cc11fd82b4908d60b24b837aa4f3028e6
msg317481 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 00:31
My change caused a regression on macOS: bpo-33626. I just closed this issue as a duplicate of this one.
msg317483 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 00:43
New changeset b97de3dd86046ac46567146d86a69d4f78ea09db by Victor Stinner in branch 'master':
bpo-33353: test_asyncio set SO_SNDBUF after connect (GH-7086)
https://github.com/python/cpython/commit/b97de3dd86046ac46567146d86a69d4f78ea09db
msg317489 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 01:21
New changeset fa24c1c5afa9ba2453d88db5ed6b9d2cc3b58384 by Victor Stinner in branch '3.7':
[3.7] bpo-33353: Fix test_asyncio on FreeBSD (GH-7087)
https://github.com/python/cpython/commit/fa24c1c5afa9ba2453d88db5ed6b9d2cc3b58384
msg317496 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 01:35
bpo-32708 has been marked as a duplicate of this issue.
msg317503 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-24 02:04
test_asyncio doesn't hang on FreeBSD 3.x buildbot anymore! macOS buildbot is back to green as well. It seems like I can close the issue.
msg317944 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-28 22:56
Hum, the test still fails on AMD64 FreeBSD CURRENT Debug 3.x :-(

http://buildbot.python.org/all/#/builders/60/builds/77

test_sock_client_ops (test.test_asyncio.test_events.PollEventLoopTests) ... ok
Timeout (0:15:00)!
Thread 0x000000080139d000 (most recent call first):
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/selectors.py", line 415 in select
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/asyncio/base_events.py", line 1707 in _run_once
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/asyncio/base_events.py", line 523 in run_forever
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/asyncio/base_events.py", line 555 in run_until_complete
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/test/test_asyncio/test_events.py", line 2117 in run_loop
  File "/usr/home/buildbot/python/3.x.koobs-freebsd-current/build/Lib/test/test_asyncio/test_events.py", line 2220 in test_sock_sendfile_mix_with_regular_send
msg317946 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-05-28 23:00
Andrew, I'm out of capacity here, could you please take a look when you have time?
msg317953 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-28 23:14
Similar failure on AMD64 FreeBSD CURRENT Non-Debug 3.7:

http://buildbot.python.org/all/#/builders/112/builds/62

Timeout (0:15:00)!
Thread 0x0000000801324000 (most recent call first):
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/selectors.py", line 323 in select
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/asyncio/base_events.py", line 1707 in _run_once
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/asyncio/base_events.py", line 523 in run_forever
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/asyncio/base_events.py", line 555 in run_until_complete
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/test/test_asyncio/test_events.py", line 2117 in run_loop
  File "/usr/home/buildbot/python/3.7.koobs-freebsd-current.nondebug/build/Lib/test/test_asyncio/test_events.py", line 2311 in test_sendfile
msg317955 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-28 23:18
> http://buildbot.python.org/all/#/builders/112/builds/62

On the previous build, test_asyncio only took 3 min 54 sec: far from the 15 min timeout limit :-(
msg318022 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 13:07
Yury Selivanov made recent changes on sendfile(): bpo-32410, commit 7165754b6b5f3b7c07050d921fa1c58bba5f0ff1.

I ran the following command on my FreeBSD VM:

  ./python -m test test_asyncio -m '*sendfile*' -v

Results:

* master (commit 73cbe7a01a22d02dbe1ec841e8779c775cad3d08): 22 min 28 sec (!!!)
* PR 7200 with BUF_SIZE = 1 KiB: 47 sec
* PR 7200 with BUF_SIZE = 4 KiB: 12 sec
msg318023 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 13:14
Timing at my previous commit b97de3dd86046ac46567146d86a69d4f78ea09db: 3 min 40 sec

It seems like Yury's commit 7165754b6b5f3b7c07050d921fa1c58bba5f0ff1 made sendfile tests of test_asyncio 6x slower on FreeBSD :-(
msg318024 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 13:22
On my PR 7200, test_sendfile_close_peer_in_the_middle_of_receiving() fails on Windows (AppVeyor) :-(

For the SelectorEventLoop, it seems like sock.setsockopt(socket.SOL_SOCKET, socket.SO_SNDBUF, 1024) doesn't work as intented: sock.send(<16384 bytes>) returns 16384, as the 1024 limit is not taken in account :-(

Same issue for the ProactorEventLoop...
msg318029 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 14:02
New changeset 9551f7719213243fd96c4f284079243773c26b3c by Victor Stinner in branch 'master':
bpo-33353: test_asyncio use set_write_buffer_limits() (GH-7200)
https://github.com/python/cpython/commit/9551f7719213243fd96c4f284079243773c26b3c
msg318032 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 14:08
"On my PR 7200, test_sendfile_close_peer_in_the_middle_of_receiving() fails on Windows (AppVeyor) (...)"

I worked around this bug in my commit 9551f7719213243fd96c4f284079243773c26b3c by using a buffer of 128 KiB instead of 64 KiB.

I created the issue bpo-33683 to discuss this weird behaviour.
msg318036 - (view) Author: miss-islington (miss-islington) Date: 2018-05-29 14:21
New changeset 441afbd9c3ae3a9f1d6c985c8aa13e6205ba080b by Miss Islington (bot) in branch '3.7':
bpo-33353: test_asyncio use set_write_buffer_limits() (GH-7200)
https://github.com/python/cpython/commit/441afbd9c3ae3a9f1d6c985c8aa13e6205ba080b
msg318042 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-05-29 15:09
> It seems like Yury's commit 7165754b6b5f3b7c07050d921fa1c58bba5f0ff1 made sendfile tests of test_asyncio 6x slower on FreeBSD :-(

Well, yeah, I kind of expected to see a performance regression here.  Before, we were reading from a file directly, which is a blocking operation and can potentially block the event loop.  Now we're using a thread pool to do the read, but its more overhead.

In this case I think we have to do it the *correct* way, even if it means sacrificing the performance.  As a workaround, I propose to rise the read buffer size to 1Mb.
msg318054 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 16:09
With my latest change, all sendfile tests pass in 17 sec on my FreeBSD VM, so I think that it's fine. Let's see if this test now always pass on FreeBSD buildbots.
msg318079 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2018-05-29 19:59
Tests are maybe not perfect, but the initial issue is fixed: test_asyncio pass again on FreeBSD buildbots.
History
Date User Action Args
2018-05-29 19:59:23vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg318079

stage: patch review -> resolved
2018-05-29 16:09:00vstinnersetmessages: + msg318054
2018-05-29 15:09:43yselivanovsetmessages: + msg318042
2018-05-29 14:21:49miss-islingtonsetnosy: + miss-islington
messages: + msg318036
2018-05-29 14:08:13vstinnersetmessages: + msg318032
2018-05-29 14:02:46miss-islingtonsetpull_requests: + pull_request6837
2018-05-29 14:02:10vstinnersetmessages: + msg318029
2018-05-29 13:22:15vstinnersetmessages: + msg318024
2018-05-29 13:14:04vstinnersetmessages: + msg318023
2018-05-29 13:07:00vstinnersetmessages: + msg318022
2018-05-29 12:31:13vstinnersetstage: resolved -> patch review
pull_requests: + pull_request6835
2018-05-28 23:18:20vstinnersetmessages: + msg317955
2018-05-28 23:14:04vstinnersetmessages: + msg317953
2018-05-28 23:00:23yselivanovsetmessages: + msg317946
2018-05-28 22:56:06vstinnersetstatus: closed -> open
resolution: fixed -> (no value)
messages: + msg317944
2018-05-24 02:04:08vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg317503

stage: patch review -> resolved
2018-05-24 01:35:13vstinnersetmessages: + msg317496
2018-05-24 01:35:00vstinnerlinkissue32708 superseder
2018-05-24 01:21:16vstinnersetmessages: + msg317489
2018-05-24 00:58:14vstinnersetpull_requests: + pull_request6721
2018-05-24 00:43:48vstinnersetmessages: + msg317483
2018-05-24 00:32:27vstinnerlinkissue33626 superseder
2018-05-24 00:31:58vstinnersetmessages: + msg317481
2018-05-24 00:29:00vstinnersetpull_requests: + pull_request6719
2018-05-23 22:57:25miss-islingtonsetpull_requests: + pull_request6716
2018-05-23 22:56:11vstinnersetmessages: + msg317470
2018-05-23 22:38:58vstinnersetkeywords: + patch
stage: patch review
pull_requests: + pull_request6714
2018-04-25 14:08:30vstinnercreate