看看如何调试Ruby的性能问题

李哲 — APRIL 08, 2015

Ruby内置的profiler

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

执行:

ruby -rprofile test.rb
输出结果为:

%cumulativeselfselftotaltimesecondssecondscallsms/callms/callname24.240.160.16100010.020.06Object#m218.180.280.12260.00330.00Integer#times18.180.400.12100010.010.06Object#m115.150.500.10100010.010.01Class#new10.610.570.07100000.010.01P1.new6.060.610.04200000.000.00Fixnum#to_s4.550.640.03100000.000.00Struct#initialize3.030.660.02100000.000.00P2#initialize0.000.660.0010.000.00TracePoint#enable0.000.660.0010.000.00Class#initialize0.000.660.0010.000.00nil#0.000.660.0010.000.00Struct.new0.000.660.0070.000.00Module#method_added0.000.660.0030.000.00BasicObject#singleton_method_added0.000.660.0020.000.00Class#inherited0.000.660.0020.000.00IO#set_encoding0.000.660.0010.000.00TracePoint#disable0.000.660.0010.00660.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查看程序内的方法调用占比了。

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'defm15_000_000.times{1+2+3+4+5}enddefm21_000_000.times{1+2+3+4+5}endStackProf.run(mode::cpu,out:'tmp/stackprof.dump')dom1m2end

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

stackprof tmp/stackprof.dump --text

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

Mode:cpu(1000)Samples:75(0.00%missrate)GC:0(0.00%)=====================================================================TOTAL(pct)SAMPLES(pct)FRAME62(82.7%)62(82.7%)blockinObject#m113(17.3%)13(17.3%)blockinObject#m275(100.0%)0(0.0%)<main>75(100.0%)0(0.0%)blockin<main>75(100.0%)0(0.0%)<main>62(82.7%)0(0.0%)Object#m113(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,在页面上的左上角会看到响应时间的毫秒数。如下图所示:

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


本文作者系OneAPM工程师李哲 ,想阅读更多好的技术文章,请访问OneAPM官方技术博客。