Понимание вывода ruby-prof - PullRequest
Новая
       16

Понимание вывода ruby-prof

57 голосов
/ 20 марта 2011

Я запустил ruby-profiler в одной из моих программ. Я пытаюсь выяснить, что означают каждое поле. Я предполагаю, что все время процессора (а не время настенных часов), что фантастика. Я хочу понять, что означает "---". Есть ли какая-то информация о стеке там? Что значит звонки a / b? 

Thread ID: 81980260
Total Time: 0.28

  %total   %self     total      self      wait     child            calls   Name
--------------------------------------------------------------------------------
                      0.28      0.00      0.00      0.28              5/6     FrameParser#receive_data
 100.00%   0.00%      0.28      0.00      0.00      0.28                6     FrameParser#read_frames
                      0.28      0.00      0.00      0.28              4/4     ChatServerClient#receive_frame
                      0.00      0.00      0.00      0.00             5/47     Fixnum#+
                      0.00      0.00      0.00      0.00              1/2     DebugServer#receive_frame
                      0.00      0.00      0.00      0.00            10/29     String#[]
                      0.00      0.00      0.00      0.00            10/21     <Class::Range>#allocate
                      0.00      0.00      0.00      0.00            10/71     String#index
--------------------------------------------------------------------------------
 100.00%   0.00%      0.28      0.00      0.00      0.28                5     FrameParser#receive_data
                      0.28      0.00      0.00      0.28              5/6     FrameParser#read_frames
                      0.00      0.00      0.00      0.00             5/16     ActiveSupport::CoreExtensions::String::OutputSafety#add_with_safety
--------------------------------------------------------------------------------
                      0.28      0.00      0.00      0.28              4/4     FrameParser#read_frames
 100.00%   0.00%      0.28      0.00      0.00      0.28                4     ChatServerClient#receive_frame
                      0.28      0.00      0.00      0.28              4/6     <Class::Lal>#safe_call
--------------------------------------------------------------------------------
                      0.00      0.00      0.00      0.00              1/6     <Class::Lal>#safe_call
                      0.00      0.00      0.00      0.00              1/6     DebugServer#receive_frame
                      0.28      0.00      0.00      0.28              4/6     ChatServerClient#receive_frame
 100.00%   0.00%      0.28      0.00      0.00      0.28                6     <Class::Lal>#safe_call
                      0.21      0.00      0.00      0.21              2/4     ChatUserFunction#register
                      0.06      0.00      0.00      0.06              2/2     ChatUserFunction#packet
                      0.01      0.00      0.00      0.01            4/130     Class#new
                      0.00      0.00      0.00      0.00              1/1     DebugServer#profile_stop
                      0.00      0.00      0.00      0.00             1/33     String#==
                      0.00      0.00      0.00      0.00              1/6     <Class::Lal>#safe_call
                      0.00      0.00      0.00      0.00              5/5     JSON#parse
                      0.00      0.00      0.00      0.00              5/8     <Class::Log>#log
                      0.00      0.00      0.00      0.00              5/5     String#strip!
--------------------------------------------------------------------------------

1 Ответ

64 голосов
/ 20 марта 2011

Каждый раздел вывода ruby-prof разбит на проверку конкретной функции. например, посмотрите на первый раздел вашего вывода. Метод read_frames в FrameParser находится в центре внимания и в основном говорит следующее:

  • 100% профилированного времени выполнения было потрачено внутри FrameParser # read_frames
  • FrameParser # read_frames вызывался 6 раз.
  • 5 из 6 вызовов read_frames поступили из FrameParser # receive_data, и это составило 100% времени выполнения (это строка над строкой read_frames).
  • Строки под методом read_frames (но внутри этого первого раздела) - это все методы, которые вызывает FrameParser # read_frames (вы должны знать об этом, так как это выглядит как ваш код), сколько из этих методов всего вызывает read_frames отвечает за (столбец вызовов a / b) и сколько времени заняли эти вызовы. Им приказано, какой из них занял наибольшее время исполнения. В вашем случае это метод receive_frame в классе ChatServer.
  • Затем вы можете посмотреть вниз на раздел, посвященный receive_frames (2 вниз и центрированы линией «100%» на receive_frame), и посмотреть, как снижается его производительность. каждый раздел настраивается одинаково, и обычно последующий вызов функции, который занимал больше всего времени, является фокусом следующего раздела вниз. ruby-prof продолжит делать это через полный стек вызовов. Вы можете идти так глубоко, как захотите, пока не найдете узкое место, которое хотите устранить.
...