Ruby Profiler詳解之ruby-prof（I）
項目地址： ruby-profhtml
在上一篇 Ruby 中的 Profiling 工具中，咱們列舉了幾種最經常使用的 Profiler，不過只是簡單介紹，這一次詳細介紹一下 ruby-prof 的使用方法。git
ruby-prof 是比較強大的，支持 cpu，內存使用，對象分配等等的性能分析，並且提供了不少友好的輸出格式，不只僅是有基於文字，html 的格式，還能輸出 graphviz 格式的 dot 文件，以及適用與 KCacheGrind 的call tree格式， 其實這個格式是基於 Valgrind 的，這個工具很棒，你們能夠去官網瞭解一下。github
有兩種方式運行 ruby-prof，一種是須要在源碼中插入 ruby-prof 的啓動和中止代碼：ubuntu
require 'ruby-prof' RubyProf.start # 這裏寫入要進行性能剖析的代碼 result = RubyProf.stop # 選擇一個Printer printer = RubyProf::FlatPrinter.new(result) printer.print(STDOUT)
還有一種是在命令行直接運行的，安裝了 Gem 包 ruby-prof 以後，會同時安裝 ruby-prof 命令，使用以下：ruby
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
##示例程序ui
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官方技術博客。
- 1. Ruby Profiler 詳解之 ruby-prof（I）
- 2. Ruby Profiler詳解之stackprof
- 3. Ruby Profiler 詳解之 stackprof
- 4. I/O之BIO詳解
- 5. 【c++】i++和++i 詳解
- 6. DIY Ruby CPU 分析——Part I
- 7. Ruby Gem命令詳解
- 8. 詳解I/O多路轉接之select
- 9. Android Profiler之CPU
- 10. 詳解Unity Profiler內存分析問題
- 更多相關文章...
- • 免費ARP詳解 - TCP/IP教程
- • *.hbm.xml映射文件詳解 - Hibernate教程
- • Flink 數據傳輸及反壓詳解
- • 爲了進字節跳動，我精選了29道Java經典算法題，帶詳細講解
-
每一个你不满意的现在，都有一个你没有努力的曾经。