如何调试请求需要花费太多时间才能完成?
XHR请求随机需要花费太多时间才能完成。 我找不到发生这种情况的地方。 如果有的话。 当我在可疑的ruby代码块周围启用探查器时,阻塞就发生在其他地方。 然而,我无法用webrick
重现它。 有任何想法吗?
UPD这是一个使用续集连接到postgresql的rails应用程序。 以下是我正面临的问题的更多细节。
这是我做的:
1)将以下代码添加到/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb
的开头:
def __l *args File.open('/home/USER/' + 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)在process_action
方法的开头添加以下代码:
__start = Time.now __l '-' * 80, __start, env['REQUEST_URI'], env['HTTP_X_REAL_IP'] __start_profiler
3)将方法begin...end
处的大begin...end
块的结果放入r
变量
4)在方法结束时添加以下代码:
__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)每次测试运行前:
rm -f ~/*.log && touch tmp/restart.txt && watch 'grep elapsed ~/*.log | sort -gr -k2 | head'
并找到了罪魁祸首:
%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 ...