Ruby Ruby Profiler 详解之 StackProf-CPU 和对象分配的采样剖析

oneapm · 2015年07月04日 · 最后由 ashui 回复于 2015年07月17日 · 4655 次阅读
本帖已被管理员设置为精华贴

简介

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.times1000.times.each 都是分配了 1 个对象,猜想虚拟机内部对其是等价的 1000.times {} 是分配了 0 个,内部对其优化没了

#1 楼 @dp90219 你说的:

1000.times {} 是分配了 0 个,内部对其优化没了

是什么意思呢?什么叫做内部对其优化没了?

#2 楼 @oneapm 抱歉表达不好,我意思是 没有产生任何对象,虚拟机优化后 就当做没有这行代码

#3 楼 @dp90219 你的猜测是基本是对的,但是1000.times1000.times.each不是等价的,虽然都是传入了一个block,但是这两个blockRuby内部的处理方式不一样。在1000.times.each {}产生的两个对象在 Ruby 的内部类型一个是T_DATA,一个是T_NODE,在这里,T_DATA代表的是Enumerator对象,T_NODE对象是因为后面的 block 产生,但并不是一个Proc对象。

需要 登录 后方可回复, 如果你还没有账号请 注册新账号