Ruby Ruby 中的 Profiling 工具

oneapm · 2015年06月02日 · 最后由 oneapm 回复于 2016年06月24日 · 6410 次阅读
本帖已被设为精华帖!

Ruby 内置的 profiler

内置的 profiler 实现的很简单,在 ruby2.2 中只有 150 行代码,大家可以看看它的实现profile.rb 。内置的 profiler 使用起来非常的方便,只需要加上-rprofile参数即可。例如:

执行:

ruby -rprofile test.rb

输出结果为:

 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
24.24     0.16      0.16    10001     0.02     0.06  Object#m2
18.18     0.28      0.12        2    60.00   330.00  Integer#times
18.18     0.40      0.12    10001     0.01     0.06  Object#m1
15.15     0.50      0.10    10001     0.01     0.01  Class#new
10.61     0.57      0.07    10000     0.01     0.01  P1.new
 6.06     0.61      0.04    20000     0.00     0.00  Fixnum#to_s
 4.55     0.64      0.03    10000     0.00     0.00  Struct#initialize
 3.03     0.66      0.02    10000     0.00     0.00  P2#initialize
 0.00     0.66      0.00        1     0.00     0.00  TracePoint#enable
 0.00     0.66      0.00        1     0.00     0.00  Class#initialize
 0.00     0.66      0.00        1     0.00     0.00  nil#
 0.00     0.66      0.00        1     0.00     0.00  Struct.new
 0.00     0.66      0.00        7     0.00     0.00  Module#method_added
 0.00     0.66      0.00        3     0.00     0.00  BasicObject#singleton_method_added
 0.00     0.66      0.00        2     0.00     0.00  Class#inherited
 0.00     0.66      0.00        2     0.00     0.00  IO#set_encoding
 0.00     0.66      0.00        1     0.00     0.00  TracePoint#disable
 0.00     0.66      0.00        1     0.00   660.00  #toplevel

通过打印出的结果能够很明显的看出耗时的方法。内置的 profiler 很简单,只能打印出这样的结果,没有 其他输出格式的选项,下面介绍的其他几种都有丰富的格式输出。

ruby-prof

repo: https://github.com/ruby-prof/ruby-prof

ruby-prof具有 C 扩展,所以它能运行的更快,同时它支持丰富的输出格式,方便我们去查找性能瓶颈。 ruby-prof支持输出GraphViz支持的 dot 格式,两者的安装方法如下:

gem install ruby-prof

ubuntu | sudo apt-get install graphviz
Mac    | brew install graphviz

执行命令很简单,如下:

ruby-prof --mode=wall --printer=dot --file=output.dot test.rb 25

此命令的详细使用方法请参考帮助信息ruby-prof --help

上面命令的执行结果会输出一个 graphviz 的 dot 文件,graphviz 提供一个格式转换命令,可以将此文件 转换为一个 pdf 文件以方便查看,如下:

dot -T pdf -o output.pdf output.dot

这样就可以打开 output.pdf 查看程序内的方法调用占比了。

ruby-prof

perftools.rb

repo: https://github.com/tmm1/perftools.rb

perftools.rbgoogle-perftools的 ruby 版本,不过它只支持 ruby2.1 以下版本,2.1 及以上 版本就需要用到下面的stackprof了,这两个工具都是一个人写的。鉴于此,我们略过perftools.rb, 作者实现stackprof,就是为了替代perftools.rb。如果有需求的话,就请参考其 github 主页。

stackprof

repo: https://github.com/tmm1/stackprof

stackprof只支持 Ruby2.1+,不过现在 ruby 的版本发布很快,每一个版本都能带来一些新东西,2.1 应该很快就能成为很基础的版本,我们就在这个版本上来做一些测试。

安装:

gem install stackprof

这次我们直接在代码中使用 stackprof 的方法:

require 'stackprof'

def m1
  5_000_000.times{ 1+2+3+4+5 }
end

def m2
  1_000_000.times{ 1+2+3+4+5 }
end

StackProf.run(mode: :cpu, out: 'tmp/stackprof.dump') do
  m1
  m2
end

我们执行这个 ruby 程序,ruby test.rb,会在当前目录的 tmp 目录中产生一个文件stackprof.dump, 然后来分析以下这个文件,stackprof命令本身可以解析这个文件,执行下面的命令:

stackprof tmp/stackprof.dump --text

则会产生下面的结果,结果应该是很清晰的,很明显在代码中m1方法要占有绝大部分的运行时间。

==================================
  Mode: cpu(1000)
  Samples: 75 (0.00% miss rate)
  GC: 0 (0.00%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
        62  (82.7%)          62  (82.7%)     block in Object#m1
        13  (17.3%)          13  (17.3%)     block in Object#m2
        75 (100.0%)           0   (0.0%)     <main>
        75 (100.0%)           0   (0.0%)     block in <main>
        75 (100.0%)           0   (0.0%)     <main>
        62  (82.7%)           0   (0.0%)     Object#m1
        13  (17.3%)           0   (0.0%)     Object#m2

其他更加丰富的输出方式和分析方式,就请参考stackprof的 github 主页,讲解的很全面。

如果你希望在 web 前端中展示相关信息,就请看看stackprof-webnav这个 gem,它提供了比较全面的 展示,操作等等,适合在一些 web 应用中使用,github 地址:stackprof-webnav

rack-mini-profiler

repo: https://github.com/MiniProfiler/rack-mini-profiler

rack-mini-profiler专门应用于基于rack的 web 应用的性能调优,在 rails 中的使用方法如下:

首先将 gem 添加到 gemfile 中:

gem 'rack-mini-profiler'

执行:

bundle install

然后重启你的服务器,访问任意的 URl,在页面上的左上角会看到响应时间的毫秒数。如下图所示:

rack-mini-profiler

点击query time(ms)列中的1 sql则可以查看到执行的 sql 语句及耗时:

rack-mini-profiler-sql

Profiler 详细的使用请参考以下 RubyChina 帖子:

Ruby Profiler 详解之 ruby-prof(I)


本文由OneAPM工程师原创,欢迎大家来OneAPM做客,共同讨论各种技术问题,OneAPM提供包括Ruby在内的主流 6 种编程语言,以及浏览器端、移动端、服务器软硬件环境的性能监测服务。

这个不错

:plus1:

rack-mini-profiler + flamegraph 就更形象啦

直接用 oneapm 就好啦~

:plus1: 喜欢+关注+收藏

匿名 #6 · 2015年06月03日

:plus1:

感谢分享

rack-mini-profiler 用上了对于大型的应用开发时性能影响还是挺大的

用 profiler 倒是很容易检查简单的程序性能,比如比对{}.merge {}.update 两种写法的效率

 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
42.86     0.03      0.03        1    30.00    70.00  Integer#times
14.29     0.04      0.01     1000     0.01     0.03  Hash#merge
14.29     0.05      0.01     1000     0.01     0.01  Hash#initialize_copy
14.29     0.06      0.01     1000     0.01     0.02  Kernel#initialize_dup
14.29     0.07      0.01     1000     0.01     0.04  nil#
 0.00     0.07      0.00        1     0.00     0.00  TracePoint#enable
 0.00     0.07      0.00     1000     0.00     0.00  Hash#update
 0.00     0.07      0.00        2     0.00     0.00  IO#set_encoding
 0.00     0.07      0.00        1     0.00     0.00  TracePoint#disable
 0.00     0.07      0.00        1     0.00    70.00  #toplevel

另外 profiler 应该是 2.0.0 就应该有了吧

大赞一个!一直在用,很高效~~

#11 楼 @gene_wu rack-mini-profiler线上是不能用的,这个工具设计的初衷就是开发时用的。

#12 楼 @gene_wu profiler 是早就有了。如果只是比较效率的话,benchmark 是不是更好的工具呢?

#14 楼 @oneapm 就是开发时候性能下降也很大

#16 楼 @gene_wu 开发就无所谓了,基本上都会是你觉得有不太对的地方,才会专门去用它调试一下。😄

18楼 已删除

#18 楼 @karen2015 这是什么意思,你这么招人,估计也不会有人和你联系吧,为什么不发个招聘贴呢?

请教一个问题 同一段代码下比较 使用 内置的 profiler 和 ruby-prof 显示出的 total_time 似乎不一样,相差的值比较大, 而且使用 ruby-prof 的运行速度快好多。

#20 楼 @pathbox 互相学习啊,😄, 快是因为 ruby-prof 是 c 实现的,而时间不一样也跟这个实现有关系,再一个 ruby 的 gc 是个很耗时的操作,ruby 实现的 profiler 也会增加 gc 的压力,代码写的不好的时候这个 gc 的时间可能就会占掉一半,导致计算的时间出现较大的误差,不过一般我们调优的话,不是用两个工具去调,而是用一个,先多跑几次取一个跳动不大的作为基准,针对这个基准再去调,而不是用一个绝对的值去调,所有的 profiler 都会增加程序的绝对执行时间,得出的程序运行时间都是不准确的,越是贴近底层越是接近实际的执行时间。

看看下面这几个简单的 time 结果:

没有 Profiler

real    0m1.462s
user    0m1.392s
sys     0m0.068s

内置的 Profiler

real    0m20.021s
user    0m19.188s
sys     0m0.832s

Ruby-Prof

real    0m2.456s
user    0m1.891s
sys     0m0.535s

内置 profiler 耗时主要增加在用户态,主要是还是因为 ruby 实现比较慢和 GC 造成的。下周可能要写一篇 GC 和内存的帖子,正好拿这个作为例子,😄

#21 楼 @oneapm 原来如此。不过我会选择 ruby-prof 吧,功能够丰富了。 等你下一篇帖子

#22 楼 @pathbox ruby-prof 可以看看 RubyChina 的这篇:Ruby Profiler 详解之 ruby-prof(I),也是我们写的,Profiler 一般会输出一些格式化的数据,这时候一个好的数据查看工具也是很有帮助的。

#23 楼 @oneapm 哈哈,这个看过了。所以觉得 ruby-prof 不错

赞!

赞赞赞

oneapm Ruby Profiler 详解之 ruby-prof (I) 中提及了此贴 06月24日 14:23
需要 登录 后方可回复, 如果你还没有账号请点击这里 注册