了解ruby-prof输出

Question

我在我的一个程序上运行了ruby-profiler.我想弄清楚每个字段的含义.我猜测一切都是CPU时间(而不是挂钟时间),这太棒了.我想了解"---"代表什么.那里有某种堆栈信息.调用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!
--------------------------------------------------------------------------------

Answer 1

ruby-prof输出的每个部分都分解为特定函数的检查.例如,查看输出的第一部分.FrameParser上的read_frames方法是焦点,它基本上说如下:

• 被分析的100%执行时间花费在FrameParser#read_frames中
• FrameParser #read_frames被调用了6次.
• 6个read_frames调用中有5个来自FrameParser#receive_data,这占执行时间的100%(这是read_frames行之上的行).
• read_frames下面的行(但在第一部分内)方法是FrameParser #read_frames调用的所有方法(你应该知道,因为这看起来像是你的代码),有多少方法总调用read_frames负责(a/b调用列),以及这些调用花了多少时间.按顺序排列它们占用了最多的执行时间.在您的情况下,这是ChatServer类上的receive_frame方法.
• 然后,您可以向下看看关注于receive_frames的部分(2个向下并以receive_frame上的'100%'为中心)并查看其性能如何分解.每个部分都以相同的方式设置,通常随后花费最多时间的函数调用是下一部分的焦点.ruby-prof将继续通过完整的调用堆栈执行此操作.你可以尽可能深入,直到找到你想要解决的瓶颈.