了解 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 次。
• 对 read_frames 的 6 次调用中有 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 将通过完整的调用堆栈继续执行此操作。您可以随心所欲地深入，直到找到您想要解决的瓶颈。