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.

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

My change caused a regression on macOS: bpo-33626. I just closed this issue as a duplicate of this one.

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

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

bpo-32708 has been marked as a duplicate of this issue.

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.

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

Andrew, I'm out of capacity here, could you please take a look when you have time?

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

> 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 :-(

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

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 :-(

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...

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

"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.

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

> 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.

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.

Tests are maybe not perfect, but the initial issue is fixed: test_asyncio pass again on FreeBSD buildbots.

stage: patch review -> resolved

stage: patch review -> resolved