如何读取 ruby​​ profiler 的输出

Posted 2023-03-06

【中文标题】如何读取 ruby​​ profiler 的输出

【英文标题】：How to read ruby profiler's output

【发布时间】：2015-08-25 19:58:50

【问题描述】：

让我们以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？

【问题讨论】：

我看到(130/0.6842)/2 #=> 95.001... 可能是个线索？

@CarySwoveland 计算不适合其他行。我会说total ms/call 表示自第一个堆栈从顶层进入而不是从最近的外部堆栈进入以来每次方法调用的时间（以毫秒为单位） - 那是self ms/call。表中没有基值，只有调用次数，因此从中推导出公式没有意义。

看来这是正确的意思：Profiler source

又是一个gprof clone。它说Profiling your program is a way of determining which methods are called and how long each method takes to complete. This way you can detect which methods are possible bottlenecks.错了。

我确实打算试试ruby-prof。只是想澄清一下，关于这个。

【参考方案1】：

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

好的，让我们深入研究source。有两个procs，在那里收集信息：PROFILE_CALL_PROC、PROFILE_RETURN_PROC。前者在进入方法之前被调用，后者在退出之前被调用。

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

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

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

附：在ruby-prof 中几乎提醒flat profiles。

【参考方案2】：

一个方法可能会单独花费时间，或者由于它调用的方法所花费的时间而花费时间。 self ms/call 只计算前者，而 total ms/call 计算两者之和。代表self seconds 是有意义的，但不是total seconds，因为这会在所有地方累积。

【讨论】：

你认为自我时间有意义吗？

@MikeDunlavey 因为self seconds 较大的方法是您要改进的地方。

仅当程序很小时。检查第二个答案here。