Ruby Profiler詳解之stackprof

OneAPM官方技術部落格發表於2015-07-09

簡介

stackprof 是基於取樣的一個調優工具，取樣有什麼好處呢？好處就是你可以線上使用，按照內建的演算法抓取一部分資料，隻影響一小部分效能。它會產生一系列的 dump 檔案，然後你線上下分析這些檔案，從而定位出問題，google有一篇基於取樣的論文，也基本證明了取樣是可行的。而 stackprof 也是深受 google 的 perftools 的影響，採用了取樣的方式來做調優。

基本使用方法

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
11 06   (61.7%) /  1106  (61.7%)  |    10  |
                                  |    11  |   def start

我們可以看到 m2 這個方法定義在哪一個檔案的哪一行，同時是誰呼叫了它，以及還顯示了它在原始碼中的上下文。假如有多個方法呼叫了 m2 ，還會顯示出這幾個方法，以及他們呼叫 m2 所佔的比例，也就是上面的 callers 部分，因為只有一個 start 方法呼叫了 m2，所以它是 100% 。

在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

可以利用這樣的方式除錯線上的環境。

參考連結：

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

本文系OneAPM工程師原創文章。OneAPM是中國基礎軟體領域的新興領軍企業，能幫助企業使用者和開發者輕鬆實現：緩慢的程式程式碼和SQL語句的實時抓取。想閱讀更多技術文章，請訪問OneAPM官方技術部落格。

相關文章