Ruby Profiler详解之ruby-prof（I）
项目地址： ruby-profhtml
在上一篇 Ruby 中的 Profiling 工具中，咱们列举了几种最经常使用的 Profiler，不过只是简单介绍，这一次详细介绍一下 ruby-prof 的使用方法。git
ruby-prof 是比较强大的，支持 cpu，内存使用，对象分配等等的性能分析，并且提供了不少友好的输出格式，不只仅是有基于文字，html 的格式，还能输出 graphviz 格式的 dot 文件，以及适用与 KCacheGrind 的call tree格式， 其实这个格式是基于 Valgrind 的，这个工具很棒，你们能够去官网了解一下。github
有两种方式运行 ruby-prof，一种是须要在源码中插入 ruby-prof 的启动和中止代码：ubuntu
require 'ruby-prof' RubyProf.start # 这里写入要进行性能剖析的代码 result = RubyProf.stop # 选择一个Printer printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)
还有一种是在命令行直接运行的，安装了 Gem 包 ruby-prof 以后，会同时安装 ruby-prof 命令，使用以下：ruby
ruby-prof -p flat test.rb
这种方法更灵活，咱们使用这种方法来讲明ruby-prof的使用方法。多线程
直接运行ruby-prof -h获得ruby-prof的帮助信息，因为太多，这里就不列出来了，你们能够本身在系统中执行看看。工具
其中-p参数为输出格式，如下就会逐一介绍各个 Printer 的格式，指数的意义以及相关显示工具的使用。在介绍输出格式的过程当中，也会相应的介绍其余的几个参数的用途。性能
##输出格式类型测试
flat - Prints a flat profile as text (default). flat_with_line_numbers - same as flat, with line numbers. graph - Prints a graph profile as text. graph_html - Prints a graph profile as html. call_tree - format for KCacheGrind call_stack - prints a HTML visualization of the call tree dot - Prints a graph profile as a dot file multi - Creates several reports in output directory
##示例程序ui
def m1
"string" * 1000
end
def m2
"string" * 10000
end
def start
n = 0
n = n + 1 while n < 100_000
10000.times do
m1
m2
end
end
start
这是最基础的测试程序，咱们会在介绍ruby-prof的功能的同时添加其余代码来进行演示。
##GC 对性能剖析的影响
进行性能剖析的时候 GC 的运行总会对结果产生比较大的影响，这里咱们暂时不考虑它，咱们会有另一篇文章作专门的介绍。
##最简单的输出格式 - flat
ruby-prof -p flat test.rb Measure Mode: wall_time Thread ID: 12161840 Fiber ID: 19223800 Total: 0.206998 Sort by: self_time %self total self wait child calls name 68.50 0.142 0.142 0.000 0.000 20000 String#* 10.45 0.207 0.022 0.000 0.185 1 Object#start 6.82 0.014 0.014 0.000 0.000 100001 Fixnum#< 6.46 0.013 0.013 0.000 0.000 100000 Fixnum#+ 2.84 0.158 0.006 0.000 0.152 1 Integer#times 2.52 0.128 0.005 0.000 0.123 10000 Object#m2 2.40 0.024 0.005 0.000 0.019 10000 Object#m1 0.01 0.207 0.000 0.000 0.207 2 Global#[No method] 0.01 0.000 0.000 0.000 0.000 2 IO#set_encoding 0.00 0.000 0.000 0.000 0.000 3 Module#method_added * indicates recursively called methods
先来一一解释一下各项指标的意思：
| Indicator | Explanation |
|---|---|
| %self | 方法自己执行的时间占比，不包括调用的其余的方法执行时间 |
| total | 方法执行的总时间，包括调用的其余方法的执行时间 |
| self | 方法自己执行的时间，不包括调用的其余的方法执行时间 |
| wait | 多线程中，等待其余线程的时间，在单线程程序中，始终为0 |
| child | 方法调用的其余方法的总时间 |
| calls | 方法的调用次数 |
他们之间的基本关系就是：
total = self + wait + child
具体来讲就是String#*这个方法占据程序运行时间的 68.50%，花费了0.142秒，执行了20000次，而 Object#start方法就是代码中定义的start方法，它占据程序运行时间的10.45%，花费了0.022秒，调用的 方法花费了0.185秒，调用了1次，总共花费的时间（total）为0.022 + 0.185 = 0.207，相信如今你们都能名白这些指数的意义了。
如今咱们明白了这个输出的指标意思，假如这个程序是存在性能问题的，那么这些数听说明了什么问题？一般状况下， 咱们须要看两个指标，%self 和 calls，单纯看 %self 有时候是没有用的，上面这个例子，它的耗时方法是String#*， 咱们不太可能去改进语言自己的方法，这种状况下，咱们发现 calls 的值比较大，那么就想办法减小对String#*的方法调用。
利用 flat 输出格式，也就只能发现这样简单的问题，若是这时候想要减小String#*的方法调用，就须要知道是谁调用了它， 而这个输出格式是体现不出来的，就须要选择其余的输出格式。
##简单的调用关系输出 - graph
ruby-prof -p graph test.rb
Measure Mode: wall_time
Thread ID: 17371960
Fiber ID: 24397420
Total Time: 0.21026015281677246
Sort by: total_time
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
99.99% 0.01% 0.210 0.000 0.000 0.210 2 Global#[No method]
0.210 0.022 0.000 0.188 1/1 Object#start
0.000 0.000 0.000 0.000 3/3 Module#method_added
--------------------------------------------------------------------------------
0.210 0.022 0.000 0.188 1/1 Global#[No method]
99.98% 10.34% 0.210 0.022 0.000 0.188 1 Object#start
0.161 0.006 0.000 0.155 1/1 Integer#times
0.014 0.014 0.000 0.000 100001/100001 Fixnum#<
0.014 0.014 0.000 0.000 100000/100000 Fixnum#+
--------------------------------------------------------------------------------
0.161 0.006 0.000 0.155 1/1 Object#start
76.48% 2.68% 0.161 0.006 0.000 0.155 1 Integer#times
0.130 0.005 0.000 0.125 10000/10000 Object#m2
0.025 0.005 0.000 0.020 10000/10000 Object#m1
--------------------------------------------------------------------------------
0.020 0.020 0.000 0.000 10000/20000 Object#m1
0.125 0.125 0.000 0.000 10000/20000 Object#m2
69.23% 69.23% 0.146 0.146 0.000 0.000 20000 String#*
--------------------------------------------------------------------------------
0.130 0.005 0.000 0.125 10000/10000 Integer#times
61.81% 2.28% 0.130 0.005 0.000 0.125 10000 Object#m2
0.125 0.125 0.000 0.000 10000/20000 String#*
--------------------------------------------------------------------------------
0.025 0.005 0.000 0.020 10000/10000 Integer#times
11.99% 2.28% 0.025 0.005 0.000 0.020 10000 Object#m1
0.020 0.020 0.000 0.000 10000/20000 String#*
--------------------------------------------------------------------------------
0.014 0.014 0.000 0.000 100001/100001 Object#start
6.73% 6.73% 0.014 0.014 0.000 0.000 100001 Fixnum#<
--------------------------------------------------------------------------------
0.014 0.014 0.000 0.000 100000/100000 Object#start
6.42% 6.42% 0.014 0.014 0.000 0.000 100000 Fixnum#+
--------------------------------------------------------------------------------
0.01% 0.01% 0.000 0.000 0.000 0.000 2 IO#set_encoding
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 3/3 Global#[No method]
0.00% 0.00% 0.000 0.000 0.000 0.000 3 Module#method_added
* indicates recursively called methods
此次输出的内容就比较丰富，不过也可能让人头有点晕。咱们来慢慢分析一下。
首先此次排序方式不同了，是按照 total_time 排序的，flat 输出格式是按照self_time 排序的。整个报告被虚线分割为几部分，每部分中都描述了不定个数的方法调用信息，可是注意最左边两列，就是 %total, %self 那两列不为空的那一行，
先来看第二部分：
--------------------------------------------------------------------------------
0.210 0.022 0.000 0.188 1/1 Global#[No method]
99.98% 10.34% 0.210 0.022 0.000 0.188 1 Object#start
0.161 0.006 0.000 0.155 1/1 Integer#times
0.014 0.014 0.000 0.000 100001/100001 Fixnum#<
0.014 0.014 0.000 0.000 100000/100000 Fixnum#+
--------------------------------------------------------------------------------
Object#start方法的执行花费了 99.98% 的总时间，不包括子方法调用的话，花费了10.34%的时间，调用了 一次，而且在start方法中还调用了Integer#times、Fixnum#<和Fixnum#+三个方法。
再来看右数第二列(calls)，是被/分隔的两个数，左边的数是此方法在这一层级调用了多少次Object#start，右边的数是 Object#start这个程序运行过程当中总的运行次数。而Object#start调用的三个方法calls列出的是在Object#start 中执行的次数，以及总的执行次数。
最开始的一部分中有这样两个方法：Global#[No method]表明没有 caller，能够理解为 ruby 正在准备执行环境， Module#method_added是当有实例方法添加的时候，这个方法都会被触发。
那么这种输出格式能解释什么问题呢？在 flat 输出格式中咱们已经定位到了问题String#* 的调用次数太多， 那么根据这个 graph 格式的输出格式咱们应该能够找到是谁致使的这个问题。
先把能够发现问题的部分截出来：
--------------------------------------------------------------------------------
0.020 0.020 0.000 0.000 10000/20000 Object#m1
0.125 0.125 0.000 0.000 10000/20000 Object#m2
69.23% 69.23% 0.146 0.146 0.000 0.000 20000 String#*
--------------------------------------------------------------------------------
0.130 0.005 0.000 0.125 10000/10000 Integer#times
61.81% 2.28% 0.130 0.005 0.000 0.125 10000 Object#m2
0.125 0.125 0.000 0.000 10000/20000 String#*
--------------------------------------------------------------------------------
0.025 0.005 0.000 0.020 10000/10000 Integer#times
11.99% 2.28% 0.025 0.005 0.000 0.020 10000 Object#m1
0.020 0.020 0.000 0.000 10000/20000 String#*
--------------------------------------------------------------------------------
第一部分说明String#*在Object#m1和Object#m1中各被调用了10000次，一共执行了20000次，次数同样，接着看下面， 一样是10000次，在Object#m2中花费的时间是0.125秒，而在Object#m1中花费的时间是0.020秒，多出了0.105秒，这样， 咱们能定位出问题出在了Object#m2这里。
graph 可输出为 html 格式，这里只是演示了纯文本版，html 格式更容易交互，须要添加参数 -f 指定输出的路径和文件名。
##GraphViz dot - dot
ruby-prof -p dot test.rb -f dot.dot
有工具能够将 dot 文件转换为 pdf 查看，也有专门查看 dot 文件的工具，好比 ubuntu 上的 XDot。
这张图也明确说明了问题出在了Object#m2这里。 ##可交互的调用关系 - call_stack
ruby-prof -p call_stack test.rb -f callstack.html
这里真是一图胜千言，一目了然，Object#m2中的String#*的 10000 次调用花费了 60.52% 的时间，不用多解释，快点本身尝试一下吧。
##终极万能全视角 - call_tree
首先安装 KCacheGrind，ubuntu下直接sudo apt-get install kcachegrind
ruby-prof -p call_tree test.rb -f call_tree.out
打开KCacheGrind，而后打开call_tree.out（文件类型选全部），这个神奇的工具能呈现给你全部真相。
有了前面介绍的输出格式说明，看懂这个就很容易了，咱们仍是会介绍一下，不过是在另外一篇，由于这篇有点太长了，下一篇 会详细介绍一下KCacheGrind的使用方法。
本文系OneAPM工程师编译整理。OneAPM是中国基础软件领域的新兴领军企业，能帮助企业用户和开发者轻松实现：缓慢的程序代码和SQL语句的实时抓取。想阅读更多技术文章，请访问OneAPM官方技术博客。
- 1. Ruby Profiler 详解之 ruby-prof（I）
- 2. Ruby Profiler详解之stackprof
- 3. Ruby Profiler 详解之 stackprof
- 4. I/O之BIO详解
- 5. 【c++】i++和++i 详解
- 6. DIY Ruby CPU 分析——Part I
- 7. Ruby Gem命令详解
- 8. 详解I/O多路转接之select
- 9. Android Profiler之CPU
- 10. 详解Unity Profiler内存分析问题
- 更多相关文章...
- • 免费ARP详解 - TCP/IP教程
- • *.hbm.xml映射文件详解 - Hibernate教程
- • Flink 数据传输及反压详解
- • 为了进字节跳动，我精选了29道Java经典算法题，带详细讲解
-
每一个你不满意的现在，都有一个你没有努力的曾经。