#118 open
Iñaki Baz Castillo

--threaded makes Thin very very slow under Ruby1.9

Reported by Iñaki Baz Castillo | December 19th, 2009 @ 07:54 PM | in Future

Note this simple config.ru:

run lambda { |env|
  puts "Request URI: #{env["REQUEST_URI"]}"
  [201, {'Content-Type'=>'text/plain'}, ["Bye World"]]
}

I've done tests with:

  • apache 'ab' command sending 1000 requests with concurrency 20.
  • Ruby 1.8.7 and 1.9.1p376 (thin1.8 and thin1.9).
  • thin in pure event model and using threads ("--threaded").

Tests:

1) ~# thin1.8 -R config.ru start             =>  0.997 seconds
2) ~# thin1.8 -R config.ru --threaded start  =>  1.544 seconds
3) ~# thin1.9 -R config.ru start             =>  1.061 seconds
4) ~# thin1.9 -R config.ru --threaded start  => 14.709 seconds !!!

An important point is that running the above commands in foreground, the "puts" command displays "Request URI: /index.xml" line by line, except in case 4 (thin1.9 --threaded) in which it's wrongly displayed (lines mixed):

Request URI: /index.xml
Request URI: /index.xml
Request URI: /index.xmlRequest URI: /index.xmlRequest URI: /index.xmlRequest URI: /index.xmlRequest URI: /index.xmlRequest URI::/index.xmlRequest URI: /index.xmlRequest URI: /index.xmlRequest URI: /index.xml                                           








Request URI: /index.xml
Request URI: /index.xml
Request URI: /index.xml

Comments and changes to this ticket

  • macournoyer

    macournoyer December 20th, 2009 @ 01:28 PM

    • State changed from “new” to “open”

    That is some weird behaviour. Specially that --threaded should be way faster on 1.9 than 1.8.

    What OS are you on?

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 04:57 PM

    I use Kubuntu 9.04 64 bits with Ruby 1.9.1p376 compiled from sources.
    The problem is not that it's slow or not, the problem is that Thin gets blocked/paused each X seconds. But the issue doesn't occur when the "puts" line is commented. In that case:

    ~# thin1.8 -R config.ru --threaded start  =>  1.767 seconds
    ~# thin1.9 -R config.ru --threaded start  =>  1.254 seconds
    

    But in my case, until now I used thin1.9 in a custom way by directly calling:

    ::Thin::Server.new(host, port, rack_app).start
    

    and in 'rack_app' I call to "MyApp::Threaded" which looks like:

    class MyApp
    
      class Threaded
        def self.call(env)
          ::EM.defer(
            lambda { ::MyApp.call(env) },
            lambda { |r| env["async.callback"].call(r) }
          )
          ASYNC_RESPONSE
        end
      end
    
      def self.call(env)
        ### my stuff containing lots of "puts" ###
      end
    
    end
    

    By running this code under Ruby1.9 I didn't issue the reported problem and it was really fast (more than with Ruby1.8). Note that this last code also uses EV.defer but doens't use the "--threaded" option (as I don't use "thin" executable there, neither "Thin::Runner.new(ARGV).run!".

    So IMHO there is some issue with "--threaded" option in Ruby1.9 when using "thin" executable. I'll try to investigate it more.

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 05:48 PM

    Ok, I expect the following real example gives some light (note there is no "puts" in the Rack application):

    config.ru:

    class ::MyApp
    
      class Threaded
        ASYNC_RESPONSE = [-1, {}, []].freeze
        def self.call(env)
          ::EM.defer(
            lambda { ::MyApp.call(env) },
            lambda { |r| env["async.callback"].call(r) }
          )
          ASYNC_RESPONSE
        end
      end
    
      def self.call(env)
        [201, {'Content-Type'=>'text/plain'}, ["Bye World"]]
      end
    
    end
    
    #run MyApp
    run ::MyApp::Threaded
    

    myserver1.rb:

    require "rubygems"
    require "rack"
    require "thin"
    
    rackup_code = File.read("config.ru")
    rack_app = eval("Rack::Builder.new {( #{rackup_code}\n )}.to_app", TOPLEVEL_BINDING, "config.ru")
    
    ::Thin::Server.new("127.0.0.1", 9292, rack_app).start
    

    Testing under Ruby1.9:

    ~# ruby1.9 myserver1.rb    => 1.112 seconds
    

    Now let's test the same "config.ru" running "thin" executable (with Ruby 1.8 and 1.9):

    ~# thin1.8 -p 9292 -R config.ru start    =>  1.639 seconds
    ~# thin1.9 -p 9292 -R config.ru start    => 12.722 seconds !!!
    

    In the second case (using "thin" executable under Ruby1.9) "thin" server gets blocked for some seconds several times during the apache "ab" command, so it takes so exagerate time to finish.

    Note that I don't use "--threaded" option (instead I do "EV.defer" by myself into "config.ru", neither a "puts".

    Now let's remove the "Threaded" class from "config.ru":

    class ::MyApp
      def self.call(env)
        #puts "Request URI: #{env["REQUEST_URI"]}"
        [201, {'Content-Type'=>'text/plain'}, ["Bye World"]]
      end
    end
    
    run MyApp
    

    Note that "puts" line is commented. Let's test under Ruby1.8 and 1.9:

    1) thin1.8 -p 9292 -R config.ru --threaded start    =>  9.545 seconds
    2) thin1.9 -p 9292 -R config.ru --threaded start    => 14.014 seconds (it gets blocked sometimes)
    3) thin1.9 -p 9292 -R config.ru --threaded start    => crash !!!
    

    Case 3 is same as 2, but it crashed (nothing changes):

    <internal:prelude>:6:in `lock': deadlock detected (fatal)
        from <internal:prelude>:6:in `synchronize'
        from /usr/local/lib/ruby1.9/1.9.1/thread.rb:148:in `push'
        from /usr/local/lib/ruby1.9/gems/1.9.1/gems/eventmachine-0.12.10/lib/eventmachine.rb:1052:in `defer'
        from /usr/local/lib/ruby1.9/gems/1.9.1/gems/thin-1.2.5/lib/thin/connection.rb:54:in `process'
        from /usr/local/lib/ruby1.9/gems/1.9.1/gems/thin-1.2.5/lib/thin/connection.rb:42:in `receive_data'
    

    So it seems a problem (just under Ruby1.9) when using "thin" executable and threads (using "--threaded" option or implementing threads by using "EV.defer" in config.ru).

    But using Ruby1.8 or using 'Thin::Server.new("127.0.0.1", 9292, rack_app).start' the problem never occurs.

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 06:12 PM

    Interesting, by adding "--no-epoll" I cannot reproduce the above problems under Ruby1.9.

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 06:37 PM

    Yes! "EM.epoll" is causing the issue under Ruby1.9!

    In my second comment I said that using "::Thin::Server.new(host, port, rack_app).start" I didn't issue the problem (when "config.ru" contains "EV.defer" stuff). However I've realized that buy calling "::Thin::Server.new(host, port, rack_app).start" thin doesn't use epoll.

    But if I add EV.epoll" then the problem also arises:

    EM.epoll
    ::Thin::Server.new("127.0.0.1", 9292, rack_app).start
    

    So EV.epoll must be the cause of the problem (just under Ruby1.9).

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 07:06 PM

    After re-checking I've realized that "EV.epoll" is enabled by default:

    rackup_code = File.read("config.ru")
    rack_app = eval("Rack::Builder.new {( #{rackup_code}\n )}.to_app", TOPLEVEL_BINDING, "config.ru")
    
    puts "EM.epoll? = #{EM.epoll?}"  # shows "true"
    ::Thin::Server.new("127.0.0.1", 9292, rack_app).start  # rack_app uses "EV.defer"
    

    The above code works perfect under Ruby1.9, and "EM.epoll" is true.

    However, if I add "EV.epoll" before "::Thin::Server.new" then the problem arises (just in Ruby1.9) and thin is blocked each X requests for some seconds:

    rackup_code = File.read("config.ru")
    rack_app = eval("Rack::Builder.new {( #{rackup_code}\n )}.to_app", TOPLEVEL_BINDING, "config.ru")
    
    puts "EM.epoll? = #{EM.epoll?}"  # shows "true"
    EM.epoll  # it was already enabled by default.
    ::Thin::Server.new("127.0.0.1", 9292, rack_app).start  # rack_app uses "EV.defer"
    

    It seems a EventMachine issue, right?

  • Iñaki Baz Castillo

    Iñaki Baz Castillo December 20th, 2009 @ 07:22 PM

    Forget my last comment as EM.epoll? just means that HAVE_EPOLL compile-time flags exist in EventMachine. The problem occurs under Ruby1.9 when using "EM.epoll".

  • Iñaki Baz Castillo
  • Iñaki Baz Castillo

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

People watching this ticket

Referenced by

Pages