GeezerVison

The failing test is unstable, checking now.

Unexpected calls to loop.call_exception_handler():
...
 {'exception': RuntimeError('no python buffer is allocated in on_read; nread=-4095',),
  'message': 'Fatal error on transport UnixTransport',
  'protocol': <uvloop.loop.SSLProtocol object at 0x7f1749650470>,
  'transport': <UnixTransport closed=True reading=False 0x7f1749643a08>}]
FAIL

======================================================================
FAIL: test_create_unix_connection_ssl_1 (tests.test_unix.Test_UV_UnixSSL)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/decentfox/uvloop/uvloop/_testbase.py", line 102, in tearDown
    self.fail('unexpected calls to loop.call_exception_handler()')
AssertionError: unexpected calls to loop.call_exception_handler()

According to libuv docs, the following read_cb might be called with nread=UV_EOF with no buffer allocated.

However, this code didn't handle UV_EOF before above error got raised.

According to libuv docs, the following read_cb might be called with nread=UV_EOF with no buffer allocated.

Ah, that makes sense. Thanks for fixing that; can you make a fix in a separate PR?

What's the projected timeline for this PR? I assume you are planning to add more SSL tests, right? Or is it ready for a review now?

Ah, that makes sense. Thanks for fixing that; can you make a fix in a separate PR?

Oh sure thing, will do.

What's the projected timeline for this PR? I assume you are planning to add more SSL tests, right? Or is it ready for a review now?

Yes, I was planning to add more tests (renegotiation for example), and fix some obvious issues and make improvements during the testing. Let's do the review tomorrow anyway, shall we? 😃

Anytime this week works.

In short: I like the new code, it's easy to follow. Great job! Don't have any major comments. The state transitions seem fine, the overall logic is OK too.

I'd continue iterating on the codebase and adding tests (your current ToDo is great too!)

At some point when we think it's ready we'll commit the Python implementation (to have it in the repo) and start to Cythonize it to make it slightly faster. The pure-Python implementation will go straight to asyncio 3.8.

I'm adding a new state FLUSHING before SHUTDOWN (please see updated diagram at top), for cases that:

• transport.close() is called, but there is still data in _write_backlog
• close_notify is received, but there is still data in _write_backlog

Usually APP data will transiently stay in _write_backlog and immediately be encrypted into SSL data in outgoing buffer. But when the other peer starts an renegotiation, SSLObject will stop the encryption work and wait for renegotiation to finish. So both cases do exist.

While in FLUSHING state:

• No further data will be fed to APP protocol - it'll be simply discarded
• Writing to the transport has no effect - data is discarded and warning will be raised after a few attempts, similar to the behavior of TCPTransport
• The SSLProtocol keeps trying to flush the data in _write_backlog, and moves to SHUTDOWN state once done
• The newly-added ssl_shutdown_timeout also covers this state - that means the countdown starts when it enters FLUSHING state

(Took 1.5 hours to correctly write a FLUSHING test first, but only half an hour to actually implement the FLUSHING state 😃)

Working on eof_received() case when peer closes the writing channel only, we still flush all pending data if any if possible, send close_notify without waiting for peer's close_notify and close the transport.

A question here - do we want to treat peer's close_notify as a half-close, calling APP's eof_received()? Theoretically it is still possible to send data as far as we don't send close_notify. (Reading this paper, it seems important to let APP protocol know that whether close_notify is received or not. So I think no matter half-close should be supported or not, eof_received() should get called first. Please see new diagram above.)

Update: it is now implemented as follows: treating TLS as transport details, close_notify is always considered as EOF for upper APP protocols, while EOF from lower transport level (TCP for example) is considered as a brutal disconnection, thus not causing APP-level EOF.

Spent some time to make it run faster in uvloop - about 20% ~ 40% faster than original uvloop in 1~100 KiB echo benchmark. Here're the cProfiled diagrams for time spent on each module:

And here's the SSL benchmark running modified vmbench on a 4-core 2.5GHz cloud server, all benchmarked servers are running in python:3.7 (Debian 9) docker containers (full benchmark data here):

Where:

• ssl raw is pure OpenSSL 1.1.0f echo encryption and decryption without network I/O written in C++ based on openssl-bench initially referenced by Elvis, it is the theoretical computing limit.
• golang (1.7.4) implemented its own TLS transport, well optimized it is assumed, thus it is considered as the computing limit + network I/O.
• ssl uvloop protocol is using the new sslproto.pyx with regular EchoProtocol inherited from asyncio.Protocol.
• ssl uvloop buffered is similar, but uses EchoBufferedProtocol which has less memory copies, but additional calls added more overhead.
• ssl orig uvloop is original uvloop with asyncio.Protocol.
• nodejs is on version 4.8.2.
• ssl asyncio protocol is vanilla asyncio with asyncio.Protocol.
• gevent is on version 1.3.5 (with greenlet 0.4.13).
• ssl threaded is copied from Curio.
• twisted is on version 18.7.0.

The new sslproto.pyx is performing slightly better than Golang at 100KiB, but MemoryBIO added much memory copy overhead which is significant for smaller payloads, still it is 10% ~ 20% faster than original uvloop on throughtput, and 60%~80% faster than cpython.

Thanks a lot for reviewing in late night! ❤️

I'm testing this in debug mode just to make sure we haven't made some silly mistakes. I see that the process memory grows aggressively to some point and then flats out; this might be Python's famous memory fragmentation issue. But just in case, I'd like you to see if you can reproduce this locally.

Instructions:

• build uvloop with make debug;
• run python examples/bench/echoserver.py --proto --uvloop --ssl; you should see some debug info printed on the screen and dynamically updated;
• run python examples/bench/echoclient.py --workers 6 --msize 10241 --num 10000 --ssl and watch how the Process memory metric increases.
• repeat the last step a few times; then increase the payload size; repeat again.

So the process' memory usage grows with time. I'm 99% sure that this is just memory fragmentation. But maybe we also need to ensure that it's contained; for instance, it might be a good idea to cap max buffer size when we realloc. In general, I'd appreciate if you take another quick glance over sslproto.pyx to make sure we're not leaking memory.

Other than that, the PR is ready :)

Totally reasonable. Will do, and I'll see if I can find some more tools or ways to check possible memory issues.

Check sendfile support

We don't support the new sendfile in uvloop yet.

And here's the SSL benchmark running modified vmbench on a 4-core 2.5GHz cloud server, all benchmarked servers are running in python:3.7 (Debian 9) docker containers (full benchmark data here):

BTW, we should merge your additions back to the vmbench project.

I could reproduce the memory pattern. The memory increase seems to be more relevant to new SSL connection, rather than repeated echo send and recv. So I tested with python examples/bench/echoclient.py --workers 6 --msize 10241 --num 10 --ssl --times 10000, and memory usage of the server stabilized at around 30MB. Increasing the number of concurrent workers to 12, the server memory usage ended up at around 40MB.

I've also reviewed the code, and made a few small changes. (I'll create a separate PR for the vmbench changes)

If okay, I'll rebase again and squash all commits.

If okay, I'll rebase again and squash all commits.

go for it!

@elprans can you take a quick look at this before I merge?

@fantix hey, could you please take a look at the failed CI?

Sure thing! Sorry been out of office, will check today.

Seems to be an unstable test, a retest passed. Tried but didn't reproduce locally, I'll try to find clues in the failing log.

@asvetlov could you also take a look? This is something that we'll use pretty much as is in asyncio in 3.8.

Thank you so much, @fantix! 💯🎉🚀

Thanks a lot @1st1 😃🍻

Huge improvement! Thanks!