1s+ latency running on puma? #117
Comments
|
Update: After some debugging, I've realized that this only occurs when I configure pinging, either with |
|
Update 2: This seems like a puma bug that won't get fixed around eventmachine+puma, at least based on this issue: sinatra/sinatra#1035 (comment) |
|
As this is an issue in Puma and they're not fixing it, is there anything we can do on this repo? Faye::WebSocket schedules its work on the EventMachine reactor, which should be using different threads from Puma, so I'm not sure why this blocking effect is happening. Does anyone have more information? |
|
Same issue here. Experiencing delay up to ping time if ping is defined. No delay if ping is not set in options. Using puma 5.6.4 |
|
I am facing the exact same issue as well, no ping defined, no delay, but when I defined a ping, the delay happens, although it is really not consistent because sometimes there is also no delay. Also using Puma 5.6.4, but the version does not seem to matter, I also had the issue with 4.3.4. I see some suggestions to handle a custom ping implementation on the client side, but that doesn't look very clean to me with Javascript. Any idea how to handle that on the server side? |
|
I'm not actually able to reproduce this. Running puma v5.6.4, I have tried adding the following to EM.add_periodic_timer(1) do
ws.send('periodic message') if ws
endRunning the server with If it can't be fixed, probably the best thing is to add application-level ping either from the server or client. Many application protocols need to do this anyway because their logic is independent of the WebSocket protocol. The WebSocket ping is just a best-effort mechanism to keep the connection alive, so it's not disconnected due to lack of TCP activity. |
I have made a similar test than you (on my running application though) without the ping option and adding: EM.add_periodic_timer(5) do
websocket.send('ping') # websocket.ping('ping') has same effect
endSame behaviour, all messages are sent right after the time the ping is sent, and it happens consistently. No delay happens if I remove this custom ping. Using faye v 0.11.1 |
|
@BastienBabar To have a chance of investigating this I'd need a small example application that demonstrates the problem happening, containing just enough code and dependencies to show the problem and nothing more. Putting this together will probably help you narrow down which libraries are contributing to the effect you're observing. |
|
Alright, thanks to taking some time setting up a small example, I guess the problem comes from Redis (in my case). Here is my example: # frozen_string_literal: true
require 'rubygems'
require 'active_support'
Bundler.require
require 'grape'
class Base < Grape::API
end
class Chat
attr_reader :env
def initialize(app)
@app = app
@env = nil
end
def call(env)
@env = env
if Faye::WebSocket.websocket?(env)
websocket = Faye::WebSocket.new(env, nil, { ping: 50 })
websocket.on :open do |_event|
puts 'connected'
subscribe_channel('test', websocket)
end
websocket.on :message do |event|
puts "#{Time.now} message #{event.data}"
redis_connection.publish('test', event.data)
rescue StandardError
websocket.close
end
websocket.on :close do |event|
p [:close, websocket.object_id, event.code, event.reason]
websocket = nil
end
websocket.on :error do |event|
p [:error, websocket.object_id, event.code, event.reason]
websocket.close
end
websocket.rack_response
else
@app.call(env)
end
end
def redis_connection
uri = URI.parse('redis://localhost:6379')
Redis.new(host: uri.host, port: uri.port, password: uri.password)
end
def subscribe_channel(channel, websocket)
Thread.new do
redis_connection.subscribe(channel) do |on|
on.subscribe do |ch, subscriptions|
puts "Subscribed to ##{ch} (#{subscriptions} subscriptions)"
end
on.message do |ch, message|
puts "#{Time.now} send message: ##{ch}: #{message} \n"
websocket.send(message)
end
on.unsubscribe do |ch, subscriptions|
puts "Unsubscribed from ##{ch} (#{subscriptions} subscriptions)"
end
end
end
end
end
use Chat
run Basewith Gemfile source 'https://rubygems.org'
ruby '2.7.1'
gem 'grape', '~> 1.3.2'
gem 'puma', '~> 5.6.4'
gem 'rack', '~> 2.2.3'
gem 'faye-websocket'
gem 'redis'Messages are being sent every 50 seconds in this case. But, if you remove the redis implementation, no more delay. Am I doing something wrong here? |
|
The problem with this code is that in EM.next_tick { websocket.send(message) } |
|
@jcoglan Thanks a lot for this, that does the trick! |
|
I don't fully understand the difference either other than this will cause a change in how work is distributed across threads, in particular the work of writing data to the TCP socket. This is one of the ways EventMachine unfortunately "leaks" and you need to be aware of it if you're running any EM-based libraries. I'm not sure there's a general purpose advisory I could add to the docs because this is very dependent on what exactly your application is doing. |
Using this gem with puma and a very simple rack middleware, I was noticing up to 2 seconds of latency between when the server logged that a WS message had been sent and when a browser actually logged receiving it. This can't be due to network latency, because I'm running this on my local computer and I still see the latency.
However, when I switch thin in, the latency is gone, and messages are received within a few ms. How can I go about troubleshooting this issue with puma? Any recommendations?
The text was updated successfully, but these errors were encountered: