如何调试需要太多时间才能完成的请求? [英] How to debug requests taking too much time to complete?

问题描述

XHR请求随机花费太多时间来完成.而且我找不到发生这种情况的地方.如果有一个.当我在可疑的红宝石代码块周围启用探查器时，这种阻止在其他地方发生.但是，我无法使用 webrick 复制它.有什么想法吗?

XHR requests randomly take too much time to complete. And I fail to find a place where this is happening. If there is one. When I enable profiler around suspicious ruby code blocks, the hold-up is happening elsewhere. I couldn't reproduce it with webrick however. Any ideas?

UPD 这是一个使用续集连接到Postgresql的Rails应用程序.此处是

UPD It's a rails application using sequel to connect to postgresql. Here are more details on the issue I'm facing.

推荐答案

这就是我所做的:

1)将以下代码添加到/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb 的开头:

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/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 方法的开头添加了以下代码:

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)将方法末尾的大 begin ... end 块的结果放入 r 变量

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

4)在该方法的末尾添加了以下代码:

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)在每次测试运行之前:

5) before each test ran:

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

并且能够找到罪魁祸首:

And was able to find the culprit:

 %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
...

这篇关于如何调试需要太多时间才能完成的请求?的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！