Ruby Profiler詳解之ruby-prof（I）

標籤：

項目地址： ruby-prof

在上一篇 Ruby 中的 Profiling 工具中，我們列舉了幾種最常用的 Profiler，不過只是簡單介紹，這一次詳細介紹一下 ruby-prof 的使用方法。

ruby-prof 是比較強大的，支援 cpu，記憶體使用量，對象分配等等的效能分析，而且提供了很多友好的輸出格式，不僅僅是有基於文字，html 的格式，還能輸出 graphviz 格式的 dot 檔案，以及適用與 KCacheGrind 的call tree格式， 其實這個格式是基於 Valgrind 的，這個工具很棒，大家可以去官網瞭解一下。

有兩種方式運行 ruby-prof，一種是需要在源碼中插入 ruby-prof 的啟動和停止代碼：

require ‘ruby-prof‘RubyProf.start# 這裡寫入要進行效能剖析的代碼 result = RubyProf.stop# 選擇一個Printer printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)

還有一種是在命令列直接啟動並執行，安裝了 Gem 包 ruby-prof 之後，會同時安裝 ruby-prof 命令，使用如下：

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 KCacheGrindcall_stack             - prints a HTML visualization of the call treedot                    - Prints a graph profile as a dot filemulti                  - Creates several reports in output directory

樣本程式

def m1  "string" * 1000enddef m2  "string" * 10000enddef start  n = 0  n = n + 1 while n < 100_000  10000.times do    m1    m2  endendstart

這是最基礎的測試程式，我們會在介紹ruby-prof的功能的同時添加其他代碼來進行示範。

GC 對效能剖析的影響

進行效能剖析的時候 GC 的運行總會對結果產生比較大的影響，這裡我們暫時不考慮它，我們會有另外一篇文章做專門的介紹。

最簡單的輸出格式 - flat

ruby-prof -p flat test.rbMeasure Mode: wall_timeThread ID: 12161840Fiber ID: 19223800Total: 0.206998Sort 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.rbMeasure Mode: wall_timeThread ID: 17371960Fiber ID: 24397420Total Time: 0.21026015281677246Sort 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官方技術部落格。

Ruby Profiler詳解之ruby-prof（I）