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 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
示例程式
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官方技術部落格。
相關文章
- Ruby Profiler 詳解之 stackprof
- Ruby Profiler詳解之stackprof
- Java 程式設計要點之 I/O 流詳解Java程式設計
- "萬字" Java I/O 詳解Java
- VSCode + WSL 2 + Ruby環境搭建詳解VSCode
- rails on ruby，ruby on rails 之程式碼塊(二)AI
- IRP(I/O Request Package)詳解Package
- 五種網路I/O模型詳解模型
- oracle 9i statspack詳細講解Oracle
- js profilerJS
- Snapdragon profilerGo
- Ruby 札記 - Ruby 集合家族之陣列（Array）陣列
- Ruby程式語言與Ruby之間的比較
- Intel CPU（i3、i5、i7、i9）型號、效能詳細解讀Intel
- JavaScript之this詳解JavaScript
- iOS效能優化 - 工具Instruments之Time ProfileriOS優化
- RUBY實踐—Ruby Report之Ruport簡單應用
- Linux shell I/O重定向詳解(zt)Linux
- BeetleX之WebSocket詳解Web
- MySql之EXPLAN詳解MySql
- Flutter之ElevatedButton詳解Flutter
- Java之Super詳解Java
- CSS之Position詳解CSS
- Java 之 synchronized 詳解Javasynchronized
- 一起看 I/O | Flutter 3 更新詳解Flutter
- Ruby 裡的 %Q, %q, %W, %w, %x, %r, %s, %i (譯)轉
- 使用SQL Server ProfilerSQLServer
- java中的finally詳解(finally中沒有return i，卻有i=XX）Java
- 機器學習之Xgboost詳解機器學習
- Flutter之DataTable使用詳解Flutter
- 玩轉 JavaScript 之詳解 thisJavaScript
- JavaScript之原型深入詳解JavaScript原型
- Flutter 之 Row、Column詳解Flutter
- 【詳解】核心元件之UserDetailService元件AI
- Java之BigDecimal詳解JavaDecimal
- Javascript之字串拼接詳解JavaScript字串
- oracle之 Oracle LOB 詳解Oracle
- Java 之 ThreadLocal 詳解Javathread