Too much delay with EM.defer on Ruby 1.9?

[kenn]

Hi,

I'm observing a weird problem.

Consider that the EM process acts as a TCP server, which notifies an
event for subscribed observers.
When I use EM.defer in notify, observers receive the notification far
too later, like 2-10 seconds.

Here's a simplified version of the code that I'm using.

def observe(session_id)
@@conns[session_id] = self # self represents an EM::Connection
instance
end

def unbind
super
@@conns.delete @@conns.key(self)
end

def self.notify(event)
EM.defer do
logger.debug "Step 1"
subscriptions = Subscription.all :topic => event.topic #
DataMapper
logger.debug "Step 2"
subscriptions.each do |subscription|
@@conns[subscription.session_id].send_data
(event.to_json_with_delimiter)
end
end
end

So, thing is, if I remove the EM.defer block from notify class method,
everything works just fine. Super fast, no visible delay even with
many observers.

But with EM.defer, observers receive a notification after a varying
seconds elapsed. By tailing the server log, even the time between
"Step 1" and "Step 2" looked laggy, for what it's worth.

EM version is 0.12.10.

Note that this problem began right after I migrated from Ruby 1.8.7 to
Ruby 1.9.1 (using rvm). Before that, EM.defer seemed to work fine.
Also note that I only see this delay on production (Debian 5 on
Slicehost), but not on development (Snow Leopard).

Am I doing wrong? Any ideas?

[Iñaki Baz Castillo]

Not sure if it's related but check this issue in EventMachine:

http://rubyeventmachine.com/ticket/133

I also reported it to Thin bug tracker but got not too much feedback:

https://thin.lighthouseapp.com/projects/7212-thin/tickets/118-threaded-
makes-thin-very-very-slow-under-ruby19

--
Iñaki Baz Castillo <i...@aliax.net>

[Jake Douglas]

I think this is just our epoll + threads bug which should be fixed in master.

On Jan 13, 2010 3:24 PM, "Iñaki Baz Castillo" <i...@aliax.net> wrote:

El Jueves, 14 de Enero de 2010, kenn escribió:

> Hi, > > I'm observing a weird problem. > > Consider that the EM process acts as a TCP server, wh...

Not sure if it's related but check this issue in EventMachine:

 http://rubyeventmachine.com/ticket/133

I also reported it to Thin bug tracker but got not too much feedback:

 https://thin.lighthouseapp.com/projects/7212-thin/tickets/118-threaded-
makes-thin-very-very-slow-under-ruby19



--
Iñaki Baz Castillo <i...@aliax.net>

--
You received this message because you are subscribed to the Google Groups "EventMachine" group.
To post to this group, send email to eventm...@googlegroups.com.
To unsubscribe from this group, send email to eventmachine...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/eventmachine?hl=en.

[Kenn Ejima]

Awesome guys, thank you so much!

--
Regards,
Kenn Ejima

[Aman Gupta]

On Wed, Jan 13, 2010 at 4:14 PM, Kenn Ejima <kenn....@gmail.com> wrote:
> Awesome guys, thank you so much!

Can you try master and see if its any better?

Aman

[Iñaki Baz Castillo]

El Jueves, 14 de Enero de 2010, Aman Gupta escribió:
> Can you try master and see if its any better?
>

I've tested the example in bug 133 with master branch and the issue doesn't
occur anymore :)

http://rubyeventmachine.com/ticket/133

[Kenn Ejima]

> Can you try master and see if its any better?

I haven't tried master yet, but I confirmed that disabling EM.epoll
successfully made the problem go away.

[James Tucker]

On 13 Jan 2010, at 23:16, kenn wrote:
> def self.notify(event)
> EM.defer do
> logger.debug "Step 1"
> subscriptions = Subscription.all :topic => event.topic #
> DataMapper
> logger.debug "Step 2"
> subscriptions.each do |subscription|
> @@conns[subscription.session_id].send_data
> (event.to_json_with_delimiter)
> end
> end
> end

The send_data should be done on the reactor thread, so there you should either be using EM.schedule or the second argument to defer.

You'd probably find you also get better performance out of one of these:

# This one shows proper usage of defer for long running operations, then aggregating the result and acting on the reactor thread:

def self.notify(event)
logger.debug "Step 1"
EM.defer lambda {
# N.B. you probably want to preselect just a list of session_ids, not whole rows, too.
subs = Subscription.all(:topic => event.topic).map { |s| s.session_id } # DataMapper
[subs, event.to_json_with_delimiter]
},
lambda { |sj|
subs, json = *sj
logger.debug "Step 2"
subs.each do |subscription|
@@conns[subscription.session_id].send_data(json)
end
}
end

# This one shows a basic use of EM.schedule, which can be more easily refactored, as it will fast-pass code that is already executing on the reactor thread. In this specific example, we do quite a lot of work on the reactor thread, but also queue it all in a single tick.

def self.notify(event)
logger.debug "Step 1"
EM.defer do
# N.B. you probably want to preselect just a list of session_ids, not whole rows, too.
subs = Subscription.all(:topic => event.topic).map { |s| s.session_id } # DataMapper
json = event.to_json_with_delimiter
logger.debug "Step 2"
EM.schedule do
subs.each do |subscription|
@@conns[subscription.session_id].send_data(json)
end
end
end
end

# Here we more granularly queue work onto the reactor thread, but note that this is more ruby method calls, and also more data written to the loopback connection, among other things. It may in some interpretations be considered "more correct" however.

def self.notify(event)
logger.debug "Step 1"
EM.defer do
# N.B. you probably want to preselect just a list of session_ids, not whole rows, too.
subs = Subscription.all(:topic => event.topic).map { |s| s.session_id } # DataMapper
json = event.to_json_with_delimiter
logger.debug "Step 2"
subs.each do |subscription|
EM.schedule { @@conns[subscription.session_id].send_data(json) }
end
end
end

HTH

[Kenn Ejima]

James,

Thanks for your elaborate suggestion- I completely forgot that
send_data is not thread-safe!

However, another question came to my mind: while I thought I
understood the general concept, I realized I'm not sure *how* a thread
safety problem occurs. (I'm not good at reading C++)

In this case, send_data is called upon a specific EM::Connection
instance, so it seemed to me that there won't be a problem like stream
getting mixed with another send_data to some *other* connection that
the reactor thread is processing at the same time, as long as they are
working on different FDs. Is there yet any problem in this case?

I know it is a dumb question and I'm wrong, but I want to learn
*where* I am wrong.
Maybe a single link would be sufficient, but I couldn't find one.
Thanks again!

[Kenn Ejima]

Oops, it was a dumb question indeed.

It's quite possible that consecutive notify calls could be writing to
one same connection at the same time.

Sorry I didn't mean to mess up the conversation. :)

--
Regards,
Kenn Ejima