Long ssl handshake latencies

[mvalkon]

This is more of a question than an issue report. How can I debug SSL handshake latencies? Occasionally the handshakes take hundreds of milliseconds, which seems a little bit unreasonable. I am running an aiohttp server which exposes an API, the load is very small, something like 10-20rps load-balanced on 3 instances of the application. Are there any configuration parameters that I can tune? I am not very familiar with the asyncio-internals in python.

Some random examples from logs

<uvloop.loop.SSLProtocol object at 0x7f106f451050>: SSL handshake took 252.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f4511c0>: SSL handshake took 252.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f451330>: SSL handshake took 252.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f4514a0>: SSL handshake took 252.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430780>: SSL handshake took 504.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430bd0>: SSL handshake took 503.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f4304a0>: SSL handshake took 509.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430a60>: SSL handshake took 508.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f4308f0>: SSL handshake took 508.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430610>: SSL handshake took 509.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430eb0>: SSL handshake took 507.0 ms
<uvloop.loop.SSLProtocol object at 0x7f106f430d40>: SSL handshake took 508.0.ms

Here's 10k measurements from the past 24 hours

• uvloop version: 0.14.0
• Python version: 3.7.6
• Platform: docker
• Can you reproduce the bug with PYTHONASYNCIODEBUG in env?:
• Does uvloop behave differently from vanilla asyncio? How?:

[1st1]

@fantix any ideas?

[fantix]

For a bit more background about SSL handshake - it takes several network round trips to finish. I'm curious how you measured the latency of SSL handshake? Some sample code would be great. I would guess it included the time waiting for clients to respond. So for e.g. mobile devices with the cellular network, it may make sense when the connectivity is unstable.

How can I debug SSL handshake latencies?

I would recommend using a development version of uvloop, add additional logging/statistics in sslproto.pyx at the points where I/O happens. Then it'll be possible to observe the timeline and latency.

Are there any configuration parameters that I can tune?

• Timeouts. You can set timeouts to prevent long-running SSL handshakes.
• SSLContext. uvloop uses the built-in SSLContext in Python to handle TLS transport. You could feed uvloop with a customized SSLContext for your need, e.g. selected TLS versions, disablinng features, etc.

[mvalkon]

Thank you @fantix. I did not actually measure specifically the ssl handshake but trusted the logs that uvloop produces when asyncio debug logging is enabled. The graph is an extract of 10k debug log events over a 24-hour period. I'm not sure of the accuracy of this, but it does correlate with higher latencies in my application.

I would guess it included the time waiting for clients to respond

Can you elaborate on what you mean by this? My assumption is that the number produced by the logging represents the complete handshake operation.

• Timeouts. You can set timeouts to prevent long-running SSL handshakes.
• SSLContext. uvloop uses the built-in SSLContext in Python to handle TLS transport. You could feed uvloop with a customized SSLContext for your need, e.g. selected TLS versions, disablinng features, etc.

Thanks for this, would you have any pointers to documentation or code where I can start from?

[1st1]

This is another area where monitoring APIs (#322) can potentially help us.

[fantix]

I would guess it included the time waiting for clients to respond

Can you elaborate on what you mean by this? My assumption is that the number produced by the logging represents the complete handshake operation.

Yes. As I mentioned:

SSL handshake takes several network round trips to finish.

This means, before an SSL connection is fully established, several TCP recv/send would happen. And the SSL handshake time recorded in the log starts from the moment TCP connection is made, and ends when SSL handshake succeeds. Therefore, it includes all the network time.

• Timeouts. You can set timeouts to prevent long-running SSL handshakes.
• SSLContext. uvloop uses the built-in SSLContext in Python to handle TLS transport. You could feed uvloop with a customized SSLContext for your need, e.g. selected TLS versions, disablinng features, etc.

Thanks for this, would you have any pointers to documentation or code where I can start from?

Please see:

• ssl_handshake_timeout
• create_default_context
• SSLContext

[fantix]

Closing due to inactivity. Please feel free to reopen if you have further questions.