Phoenix: Node websocket implementation significantly faster than Phoenix's

[bcardarella]

I'm not sure if this is the best place to put this but here it goes. I've run the thor websocket benchmarking tool against two very simple websocket servers, one with node:

var WebSocketServer = require('ws').Server
  , wss = new WebSocketServer({port: 8080});
wss.on('connection', function(ws) {
    ws.on('message', function(message) {
        console.log('Connected!');
    });
    ws.send('something');
});

and one with phoenix:

defmodule ChannelDemo.ChatChannel do
  use Phoenix.Channel
  require Logger

  def join("room", _message, socket) do
    Logger.debug "Join #{socket.topic}"
    {:ok, socket}
  end
end

with the following thor command:

thor --amount 10000 -C 10000 ws://localhost:XXXX

Node result
Phoenix result

	Time
Node	9257 milliseconds
Phoenix	48038 milliseconds

As you can see the Node implementation was more than _5.1 times faster_. I realize that Node != Phoenix and the better comparison might have been a pure Elixir implementation but I was actually shocked to see such a large difference. Is this expected?

[jeregrine]

Which version of phoenix are you using?  Also not sure the WS you are using matches the phoenix spec and you are probably throwing exceptions instead of getting the result you want. 

Are you seeing the logger messages?

On Tue, Feb 24, 2015 at 9:49 AM, Brian Cardarella
[email protected] wrote:

I'm not sure if this is the best place to put this but here it goes. I've run the thor websocket benchmarking tool against two very simple websocket servers, one with node:

var WebSocketServer = require('ws').Server
  , wss = new WebSocketServer({port: 8080});
wss.on('connection', function(ws) {
    ws.on('message', function(message) {
        console.log('Connected!');
    });
    ws.send('something');
});

and one with phoenix:

defmodule ChannelDemo.ChatChannel do
  use Phoenix.Channel
  require Logger
  def join("room", _message, socket) do
    Logger.debug "Join #{socket.topic}"
    {:ok, socket}
  end
end

with the following thor command:
thor --amount 10000 -C 10000 ws://localhost:XXXX
Node result
Phoenix result

	Time
Node	9257 milliseconds
Phoenix	48038 milliseconds

As you can see the Node implementation was more than _5.1 times faster_. I realize that Node != Phoenix and the better comparison might have been a pure Elixir implementation but I was actually shocked to see such a large difference. Is this expected?

Reply to this email directly or view it on GitHub:
https://github.com/phoenixframework/phoenix/issues/638

[bcardarella]

@jeregrine I'm using Master. And all that the benchmarking tool is doing is opening connections. I confirm in the Phoenix log that there are no exceptions being thrown.

[jeregrine]

Well I mean you are sending a message it doesn’t know how to handle. What if you send up 

{"topic”:"rooms","event":"join","payload”: {}}

Instead of ‘something’ 

or even

{"topic":"phoenix","payload":{},"event":"heartbeat"}

On Tue, Feb 24, 2015 at 9:53 AM, Brian Cardarella
[email protected] wrote:

@jeregrine I'm using Master. And all that the benchmarking tool is doing is opening connections. I confirm in the Phoenix log that there are no exceptions being thrown.

Reply to this email directly or view it on GitHub:
https://github.com/phoenixframework/phoenix/issues/638#issuecomment-75782423

[bcardarella]

@jeregrine the benchmark tool only opens connections, it is not sending any messages.

[bcardarella]

@jeregrine let me double check what I just said...

[jeregrine]

right on.

[chrismccord]

What does your endpoint look like? Are you plugging the session? Also your channel code should never be hit here if you're just opening connections. Our transport layer is also keeping state for the connections. Basically, we need a better comparison than this. Also provide your endpoint. You were running phx in prod mode with consolidated protocols right?

[bcardarella]

It appears the message being sent is a malformed one (from Phoenix's perspective) I'm attempting to fix that and re-run the benchmark. (thor has some screwy message generator)

@chrismccord is the code pasted above not the endpoint? You caught me, wasn't running in production. Just re-ran (without message fix) in production and holy smokes it is much faster:

	Time
Node	9257 milliseconds
Phoenix	7367 milliseconds

[josevalim]

I believe this is expected. Today websocket connections is going to pass through the whole endpoint, so all the overhead of configuring sessions, fetching parameters and what not is going to be triggered. We plan to move the endpoint to its own "stack" though, so this will be fixed sooner than later.

In any case, 49 miliseconds is way too high. It would be nice to know how you are benchmarking it (i.e. if you are using production, with protocol consolidation, if logging is enabled since it isn't on node, etc).

[josevalim]

Oh, thanks for the update @bcardarella. My comments are still valid though, it is going to get even faster in future releases. And you can also get more performance now if you consolidate protocols (which you should for prod).

[bcardarella]

@josevalim that is good to know, considering the production build is faster than node as-is I'm excited to see there are still potential performance wins to be had with its own stack.

[bcardarella]

I'll close this, thank you guys for the feedback.

[bcardarella]

Just as a follow-up, I changed the Logger level in development to info (same as production) and there was no significant impact on the results. 49s -> 44s

[josevalim]

@bcardarella Sorry, I was not clear. I meant we should disable log if the Node.js one does not log. When logging is enabled, it ends up taking a huge chunk in those benchmarks.

[bcardarella]

gotcha, I know how the change the log level, I am unclear on how to remove the logger

[bcardarella]

also, FWIW does it make sense to log ws connections in general? This seems like something the logger might want to just ignore all around

[josevalim]

@bcardarella everything is explicitly plugged on lib/your_app/endpoint.ex (that's the endpoint Chris mentioned earlier). Removing the Logger from there will get rid of it completely. Although increasing the level to :error should make it close to a noop too.

[bcardarella]

removing logger from Phoenix and removing console.log from node implementations:

	Time
Node	8564 milliseconds
Phoenix	6612 milliseconds

Nice perf bump, now Phoenix is showing a ~ 29% benefit over Node. (albeit for this very simple benchmark)

[jeregrine]

Not to mention that phoenix is still doing more things than the node example :) If you ran this purely against the cowboy web socket I’m sure the numbers would be higher.

On Tue, Feb 24, 2015 at 11:23 AM, Brian Cardarella
[email protected] wrote:

removing logger from Phoenix and removing console.log from node implementations:

	Time
Node	8564 milliseconds
Phoenix	6612 milliseconds

Nice perf bump, no Phoenix is showing a ~ 29% benefit over Node. (albeit for this very simple benchmark)

Reply to this email directly or view it on GitHub:
https://github.com/phoenixframework/phoenix/issues/638#issuecomment-75801386