Requests take too much time to complete

[Yuri Kanivetsky]

Hi,

XHR requests randomly take too much time to complete. When I enable profiler around suspicious code blocks, the hold-up happens elsewhere. I can't reproduce it with webrick though. And ideas how to fight the issue?

I'm running passenger-5.0.30 under ubuntu/xenial.

Regards,

Yuri

[Yuri Kanivetsky]

Hi,

To tell you some more details. It's a rails application using sequel to connect to postgresql. And I've managed to pinpoint a call that's taking too long. By profiling passenger's PhusionPassenger::Rack::ThreadHandlerExtension#process_request method, located at /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:

 %self      total      self      wait     child     calls  name
 99.92     65.713    65.713     0.000     0.000        5   PG::Connection#async_exec

  0.00      0.002     0.002     0.000     0.000      264   Set#delete

...

In case someone will run into it and find it useful, here's what exactly I did:

1) added the following code to the beginning of /usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:

def __l *args
  File.open('/home/gccs/' + Process.pid.to_s + '.log', 'a') { |f| f.puts *args }
end

require 'ruby-prof'
def __start_profiler
    RubyProf.start
    if false
        require 'profiler'
        $old_compile_option = RubyVM::InstructionSequence.compile_option.select { |k, v|
          [:trace_instruction, :specialized_instruction].include? k
        }
        RubyVM::InstructionSequence.compile_option = {
          :trace_instruction => true,
          :specialized_instruction => false
        }
        Profiler__::start_profile
    end
end

def __get_profiler_output
    sio = StringIO.new
    result = RubyProf.stop
    # printer = RubyProf::GraphPrinter.new(result)
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(sio)
    return sio.string
    if false
        Profiler__::print_profile(sio)
        RubyVM::InstructionSequence.compile_option = $old_compile_option
        sio.string
    end
end

2) added the following code at the beginning of process_action method:

__start = Time.now
__l '-' * 80, __start, env['REQUEST_URI'], env['HTTP_X_REAL_IP']
__start_profiler

3) put result of big begin...end block at the end of the method into r variable

4) added the following code at the end of the method:

__r = __get_profiler_output
if Time.now - __start > 10
    __l 'profiler'
    __l __r
    __l 'profiler'
end
__l 'elapsed: %g: %s' % [Time.now - __start, env['REQUEST_URI']], '-' * 80
r

5) before each test ran:

rm -f ~/*.log && touch tmp/restart.txt && watch 'grep elapsed ~/*.log | sort -gr -k2 | head'

Now then, maybe you have any suggestions now?

Regards,

Yuri

[Yuri Kanivetsky]

Hi,

Well, under `unicorn` I experience the same issue. But anyways, if you've got any suggestions, you're welcome.

I'm using passenger-5.0.30, unicorn-5.1.0, ruby-2.3.0, postgresql-9.4, pg-0.19.0, rails-5.0.0.1. The app is running in lxc container. Host and guest OSs are ubuntu/xenial.

[Daniel Knoppel]

It's not really clear to me what you mean by "XHR requests randomly take too much time to complete.". What is too long? Does it hang forever?

The first step would be to identify which requests trigger the issue. It doesn't look like a Passenger issue but something happening somewhere later in your stack. Passenger does offer some analytics options:

- If you are live debugging and see that a call appears to be hanging, then you can ask Passenger to get backtraces from the application process by sending a SIGQUIT to the app process (PID can be seen with passenger-status). 

- You can also find and inspect requests by attaching Union Station (https://www.unionstationapp.com) to Passenger.

Daniel

[Yuri Kanivetsky]

Hi,

Thanks for reply. Indeed, it doesn't look like an issue with passenger
anymore. From what I can tell, it gets stuck in
PG::Connection#async_exec:

%self total self wait child calls name 99.92
65.713 65.713 0.000 0.000 5
PG::Connection#async_exec 0.00 0.002 0.002 0.000
0.000 264 Set#delete ...

But I can't see waiting locks in database. (Only two records in
pg_locks, which are there right after starting postgresql, and when
nginx is not started yet.) I tried different configurations, but to no
avail. There's one server where it works, but I've got no clue why.
(I've got to set up one more instance of the site.)

Regards,
Yuri

[Yuri Kanivetsky]

Hi,

The issue was resolved after we started reestablishing connections to database. We were using sequel on the project, and Passenger handles the issue itself only when ActiveRecord is used.

Before that, we also moved handling WebSocket connections to a separate process. Not sure if it contributed to the issue however.

More info here:

http://sequel.jeremyevans.net/rdoc/files/doc/code_order_rdoc.html#label-Disconnect+If+Using+Forking+Webserver+with+Code+Preloading

https://www.phusionpassenger.com/library/indepth/ruby/spawn_methods/#unintentional-file-descriptor-sharing

https://www.phusionpassenger.com/library/config/nginx/action_cable_integration/#running-the-action-cable-server-on-the-same-host-and-port-under-a-sub-uri

Regards,

Yuri