Tornado Websocket write message performance degradation when binary is False

Open
#3,362 2 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Assessment

Difficulty
4/5
Estimated time
3-5 days
Newbie friendliness
30/100
Issue type
Bug
Clarity
Needs clarification
Activity status
Stale
Tech stack
python

Research direction

Start by reproducing the binary=False and binary=True comparisons described in the issue, using the reported message sizes and profiling output. Inspect websocket.py at lines 306 and 1058, where write_message appears in the profiles, and trace the event-loop behavior around the epoll wait. Done means identifying the cause of the disproportionate wait and documenting or correcting the performance regression with evidence from comparable measurements.

Written by the indexing model from the issue text.

Description

websocket

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)
image

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}
image

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]]
image

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

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.

Dominant language
Python
Stars
22.2k
Forks
5.6k
Avg merge
3h 42m
Merged PRs (30d)
16

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from tornadoweb/tornado

All issues in tornadoweb/tornado

Similar issues

More Python issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.