ruby - 如何读取 ruby​​ 分析器的输出

Question

让我们以 docs 为例:

require 'profile'

def slow_method
  5000.times do
    9999999999999999*999999999
  end
end

def fast_method
  5000.times do
    9999999999999999+999999999
  end
end

slow_method
fast_method

输出:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 68.42     0.13      0.13        2    65.00    95.00  Integer#times
 15.79     0.16      0.03     5000     0.01     0.01  Fixnum#*
 15.79     0.19      0.03     5000     0.01     0.01  Fixnum#+
  0.00     0.19      0.00        2     0.00     0.00  IO#set_encoding
  0.00     0.19      0.00        1     0.00   100.00  Object#slow_method
  0.00     0.19      0.00        2     0.00     0.00  Module#method_added
  0.00     0.19      0.00        1     0.00    90.00  Object#fast_method
  0.00     0.19      0.00        1     0.00   190.00  #toplevel

• % time 是在这些方法中花费的时间。
• cumulative seconds是之前的cumulative seconds加上self seconds，即0 + 0.13 = 0.13， 0.13 + 0.03 = 0.16，0.16 + 0.03 = 0.19，依此类推。
• self seconds 是 % time 以秒为单位。
• calls 表示该方法被调用了多少次。
• self ms/call 是 self seconds/calls。
• 什么是total ms/call？

Answer 1

tl;dr self seconds + 被调用方法花费的时间

好吧，让我们深入研究 source .有两个 proc，在那里收集信息:PROFILE_CALL_PROC , PROFILE_RETURN_PROC .前者在进入方法之前被调用，后者在退出之前被调用。

@@maps[Thread.current] 积累关于方法的信息，即calls , total seconds (成本)，self seconds和 name按照这个特定的顺序。这些信息稍后会以更冗长的方式提供给用户。被aggregated之后.

@@stacks[Thread.current] 在堆栈中存储有关正在运行的方法的信息。即“方法何时启动”，以及“调用的(子)方法花费了多少时间”(tick[1])。这更像是一种临时数据结构，旨在帮助将数据收集到 @@maps 中。

正如人们现在可以看到的那样，self seconds是total seconds负 cost (在调用方法中花费的时间)。也就是说，total seconds 是在方法本身和它调用的方法中花费的时间。

附言非常提醒flat profiles在 ruby-prof 中。