Tornado Websocket write message performance degradation when binary is False

[lalnarik]

When I try to write a message of size around 142000 which is a base64 string and I am using binary is False,
I am seeing an performance impact in write_message which involves a lot of epoll.

[[binary = False and Size of String = 142000]]
Traceback (most recent call last):
150821 function calls (150781 primitive calls) in 18.617 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
2649 0.043 0.000 18.257 0.007 base_events.py:1845(_run_once)
2649 0.015 0.000 18.141 0.007 selectors.py:451(select)
2649 18.122 0.007 18.122 0.007 {method 'poll' of 'select.epoll' objects}
1272 0.013 0.000 0.360 0.000 websocket.py:306(write_message)
1272 0.025 0.000 0.338 0.000 websocket.py:1058(write_message)

As seen in the image the per call wait for ~:0(<method 'poll' of 'select.epoll' objects>) 0.006841 seconds

But When I try to do the same for an base64 string of size 102000,
[[binary = False and Size of String = 102000]]
Ordered by: cumulative time

ncalls tottime percall cumtime percall filename:lineno(function)
3301 0.056 0.000 5.531 0.002 base_events.py:1845(_run_once)
3301 0.015 0.000 5.398 0.002 selectors.py:451(select)
3301 5.379 0.002 5.379 0.002 {method 'poll' of 'select.epoll' objects}

Here is comparatively dropped well,
from 0.068 it dropped to 0.016 which is about 4.25 times, Since the string I am sending an base64 string as image it is not possible to split the image into chunks of smaller size.

Just want to understand why there is an impact of 4.25x in performance when the size of message is just increased by 1.4x.

NOTE: I am not seeing the impact of this way when I tried the same thing with binary=True in write_message for that of same size string the numbers are as below.

[[binary = True and Size of String = 145000]]

[[binary = True and Size of String = 102000]]

When binary is true the amount of time consumed in epoll is almost negligible and it doesn't seem to be having any performance difference based on the size of string as well.

[bdarnell]

Just want to understand why there is an impact of 4.25x in performance when the size of message is just increased by 1.4x.

It seems likely that you're hitting a 128KB socket send buffer (SO_SNDBUF). The first N bytes written to a socket will appear to be instantaneous, but once that buffer is full, no more can be sent until we've received an ACK from the other side of the connection. This can show up as time spent in epoll (but be careful, because epoll is a shared resource across all connections in the process - generally when you're profiling an async application you should ignore epoll time; it's what the server is doing when it's idle).

When binary is true the amount of time consumed in epoll is almost negligible and it doesn't seem to be having any performance difference based on the size of string as well.

This is surprising - there's almost no difference on the write path between binary and text messages - just a call to str.encode(). Everything at the network level should be equivalent. Is everything but the binary flag the same in these tests?

[lalnarik]

Thanks for responding.
@bdarnell

I have shared the epoll impact particulary because, I have done profiling at that one line of code which writes data to encode and observed the impact on epoll,
await client["client"].write_message(frame_data, is_binary)
I did profliling on this very exact line.

The size change doesn't seem to affect is_binary as true and it does only when is_binary is false in the above case everything else is exactly same in the enviroment.