Ruby Ruby Profiler 详解之 StackProf-CPU 和对象分配的采样剖析
简介
stackprof 是基于采样的一个调优工具，采样有什么好处呢？好处就是你可以线上使用，按照内置的算法抓取一部分数据，只影响一小部分性能。它会产生一系列的 dump 文件，然后你在线下分析这些文件，从而定位出问题，google 有一篇基于采样的论文，也基本证明了采样是可行的。而 stackprof 也是深受 google 的 perftools 的影响，采用了采样的方式来做调优。
基本使用方法
CPU 模式
StackProf.run(mode: :cpu, out: './stackprof.dump') do
# 你的代码
end
这里我们给出一段示例代码，来作为测试目标：
require "stackprof"
class Compute
def m1
"string" * 100
end
def m2
"string" * 10000
end
def start
100_000.times do
m1
m2
end
end
end
StackProf.run(mode: :cpu, out: './stackprof.dump') do
Compute.new.start
end
保存为 test.rb，同时执行ruby test.rb就会在当前目录下生成 stackprof.dump 文件，我们用 stackprof 打开这个文件：
stackprof stackprof.dump --text
==================================
Mode: cpu(1000)
Samples: 1793 (0.61% miss rate)
GC: 587 (32.74%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1106 (61.7%) 1106 (61.7%) Compute#m2
98 (5.5%) 98 (5.5%) Compute#m1
1206 (67.3%) 2 (0.1%) block in Compute#start
1206 (67.3%) 0 (0.0%) <main>
1206 (67.3%) 0 (0.0%) Compute#start
1206 (67.3%) 0 (0.0%) <main>
1206 (67.3%) 0 (0.0%) block in <main>
这里可以很明显的看出是 m2 方法比较慢，占据了大部分的执行时间，相比其他的调优工具，它只是列出了用户自己的方法所占时间比，在 ruby-prof 中的测试中，它是会显示String#*这个方法的占比的，但是对于我们来说，它的意义不大，而 stackprof 是不会理会标准库里的方法的。同时 stackprof 也是可以过滤方法的，比如我们发现了 m2 这个方法有问题，那么就可以把它过滤出来，看看细节：
stackprof stackprof.dump --text --method 'Compute#m2'
Compute#m2 (/Users/lizhe/Workspace/ruby-performance-tuning/test.rb:9)
samples: 1106 self (61.7%) / 1106 total (61.7%)
callers:
1106 ( 100.0%) block in Compute#start
code:
| 9 | end
1106 (61.7%) / 1106 (61.7%) | 10 |
| 11 | def start
我们可以看到 m2 这个方法定义在哪一个文件的哪一行，同时是谁调用了它，以及还显示了它在源码中的上下文。假如有多个方法调用了 m2，还会显示出这几个方法，以及他们调用 m2 所占的比例，也就是上面的 callers 部分，因为只有一个 start 方法调用了 m2，所以它是 100%。
对象分配模式（内存占用排查）
只需要把mode改为object即可，输出的结果则变成对象分配的数量以及在哪里分配的，这里看一个小例子：
def m1
1000.times.each do |i|
i % 2 == 0 ? "even" : "odd"
end
end
m1
如何知道这段代码的执行会带来多少的对象分配呢？可以用 stackprof 来做这件事：
require "stackprof"
def m1
1000.times.each do |i|
i % 2 == 0 ? "even" : "odd"
end
end
StackProf.run mode: :object, out: 'stackprof.dump' do
m1
end
同样来分析输出的文件stackprof.dump：
==================================
Mode: object(1)
Samples: 1002 (0.00% miss rate)
GC: 0 (0.00%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
1000 (99.8%) 1000 (99.8%) block in Object#m1
1002 (100.0%) 2 (0.2%) Object#m1
1002 (100.0%) 0 (0.0%) block in <main>
1002 (100.0%) 0 (0.0%) <main>
1002 (100.0%) 0 (0.0%) <main>
通过结果可以看出，共有 1002 次对象分配，在 m1 的 block 中有 1000 次分配，除去这 1000 次，还有 2 次。你能知道为什么是 1002 次吗？
，自己想一想吧。试着把程序改成下面这样，自己运行一下 stackprof 试一试：
require "stackprof"
def m1
1000.times.each do |i|
i % 2 == 0 ? "even".freeze : "odd".freeze
end
end
StackProf.run mode: :object, out: 'stackprof.dump' do
m1
end
在 rack 中的使用方法
stackprof 本身实现了一个 rack middleware，所以可以很方便的挂载到一个 rack 应用中：
use StackProf::Middleware, enabled: true, mode: :cpu, save_every: 5
在 rails 中使用，先在 Gemfile 中添加 stackprof，然后添加 middleware：
config.middleware.use StackProf::Middleware, enabled: true, mode: :cpu, save_every: 5
然后请求你的应用，多请求几次，每 5 秒钟它会保存一次输出结果到 tmp 目录中，查看其中某一个结果：
==================================
Mode: cpu(1000)
Samples: 155 (0.00% miss rate)
GC: 11 (7.10%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
18 (11.6%) 18 (11.6%) Hike::Index#entries
12 (7.7%) 12 (7.7%) Hike::Index#stat
9 (5.8%) 9 (5.8%) #<Module:0x007fb72a0c7b08>.load_with_autoloading
18 (11.6%) 9 (5.8%) Sprockets::Cache::FileStore#[]
6 (3.9%) 6 (3.9%) block (2 levels) in BindingOfCaller::BindingExtensions#callers
5 (3.2%) 5 (3.2%) Time.parse
5 (3.2%) 5 (3.2%) Sprockets::Mime#mime_types
5 (3.2%) 5 (3.2%) Pathname#chop_basename
4 (2.6%) 4 (2.6%) block in ActionView::PathResolver#find_template_paths
4 (2.6%) 4 (2.6%) block in BetterErrors::ExceptionExtension#set_backtrace
15 (9.7%) 3 (1.9%) block in ActiveSupport::Dependencies#load_file
2 (1.3%) 2 (1.3%) Temple::Mixins::CompiledDispatcher::DispatchNode#initialize
5 (3.2%) 2 (1.3%) ActionDispatch::Cookies::EncryptedCookieJar#initialize
2 (1.3%) 2 (1.3%) ActiveSupport::KeyGenerator#generate_key
2 (1.3%) 2 (1.3%) block in ActionView::PathResolver#query
4 (2.6%) 2 (1.3%) Slim::Parser#initialize
113 (72.9%) 2 (1.3%) ActionView::Renderer#render_template
2 (1.3%) 2 (1.3%) Hike::Trail#stat
2 (1.3%) 2 (1.3%) block in ActiveSupport::Dependencies#search_for_file
22 (14.2%) 2 (1.3%) block in Temple::Filters::MultiFlattener#on_multi
20 (12.9%) 2 (1.3%) Temple::Filters::ControlFlow#dispatcher
15 (9.7%) 2 (1.3%) ActionView::Renderer#render_partial
1 (0.6%) 1 (0.6%) block in Slim::Parser#initialize
1 (0.6%) 1 (0.6%) Pathname#prepend_prefix
1 (0.6%) 1 (0.6%) String#blank?
1 (0.6%) 1 (0.6%) ActiveSupport::SafeBuffer#initialize
10 (6.5%) 1 (0.6%) Sprockets::Asset#dependency_fresh?
1 (0.6%) 1 (0.6%) Sprockets::Asset#init_with
1 (0.6%) 1 (0.6%) Hike::Index#sort_matches
1 (0.6%) 1 (0.6%) block in ActiveSupport::Dependencies::Loadable#require
总结
利用上面介绍的 stackprof 的 cpu 模式和 object 模式，你可以对你本地甚至线上的应用进行调优了，不过一搬来说，我们还是要结合 ruby-prof 一起使用。
参考链接：
https://github.com/tmm1/stackprof
本文由OneAPM工程师原创，欢迎大家来OneAPM做客，共同讨论各种技术问题，OneAPM提供包括Ruby在内的主流 6 种编程语言，以及浏览器端、移动端、服务器软硬件环境的性能监测服务。
1002 次中 剩下的 2 次对象分配，一次是 1000.times 生成 Enumerator 对象，一次是 block Proc 对象
而 1000.times 与 1000.times.each 都是分配了 1 个对象，猜想虚拟机内部对其是等价的
1000.times {} 是分配了 0 个，内部对其优化没了
