DIY Ruby CPU 分析——Part III

【編者按】做者 Emil Soman，Rubyist，除此以外居然同時也是藝術家，吉他手，Garden City RubyConf 組織者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系 OneAPM 工程師編譯整理。

原文連接：http://crypt.codemancers.com/posts/2015-04-15-diy-ruby-cpu-profiling-part-iii/ 在第一部分咱們瞭解到儀表分析器如何工做，在第二部分咱們學習到如何使用 CPU time 和 Wall time 測量執行時間。建議在繼續學習以前先閱讀一下那些內容。本章咱們將應用學到的目前爲止知識作一個很基礎的儀表 CPU 分析器。 ###Part III. DIY 儀表 CPU 分析器 #####Ruby 的儀表盤 在第一部分，咱們學到了儀表分析工具利用可以被分析工具安裝或由語言自身提供的 hooks 來工做。幸運的是，Ruby 早就擁有這些 hooks 而且提供纖巧的TracePoint類來使用這些 hooks。 #####TracePoint API 執行代碼時，Ruby VM 發送一系列事件到不一樣的節點。Ruby 容許利用TracePoint類進行事件回調。TracePoint的 API 文檔列出了全部能夠監聽的事件，但咱們只對下面兩個感興趣：

1. ：call,當 Ruby 方法調用時被觸發。
2. :return, 當 Ruby 方法返回時被觸發。 咱們能夠經過TracePoint.new方法創造 tracepoint 對象並傳遞一個事件類型進行監聽，同時傳遞部分在事件觸發時執行的代碼。下面是爲:call和：return事件創造 tracepoint 的代碼。

trace = TracePoint.new(:call, :return) do |trace|
  puts "Method: #{trace.method_id}, event: #{trace.event}"
end

被傳到回調代碼塊的參數trace使你可以訪問一系列 tracepoint 的屬性，經過它們更加了解被觸發的事件。舉個例子，咱們須要經過method_id屬性獲得 method name，經過event屬性獲得被觸發的事件名。上文提到的回調代碼塊中將顯示出方法名和被觸發的事件類型，每一次都會伴隨着 Ruby 方法的調用或返回。 創建 tracepoint 以後，須要將其變成可用狀態：

trace.enable

一旦 tracepoint 變成可用狀態，咱們即可以建立方法對它進行調用，而且看咱們出發的回調命令是否被執行。

def hello
end

hello

#=> Method: hello, event: call
#=> Method: hello, event: return

不錯，咱們的回調命令如預期的同樣被執行了兩次。 #####diy_prof gem 最後咱們將結合以前學過的東西創造一個 RubyGem，並將這個 gem 命名爲 diy_prof. 關於此 gem 的資源放在 github 上。 如今咱們就用 bundler 來建造這個 gem：

bundle gem diy_prof

這就造出了咱們將要作的項目的骨架。接着，咱們將創建在 Part II 中介紹過的包含cpu_time和wall_time方法的 TimeHelpers模塊：

# lib/diy_prof/time_helpers.rb

module DiyProf::TimeHelpers
  # These methods make use of `clock_gettime` method introduced in Ruby 2.1
  # to measure CPU time and Wall clock time.

  def cpu_time
    Process.clock_gettime(Process::CLOCK_PROCESS_CPUTIME_ID, :microsecond)
  end

  def wall_time
    Process.clock_gettime(Process::CLOCK_MONOTONIC, :microsecond)
  end
end

咱們還須要請求 gem 主文件中的這個文件lib/diy_prof.rb：

# lib/diy_prof.rb

require 'diy_prof/version'
require 'diy_prof/time_helpers'
# Rest of the original file ..

下一步，當一個:call或return事件發生時，咱們將經過 gem 裏的 TracePoint API 來顯示時間。

module DiyProf
  class Tracer
    include TimeHelpers

    def initialize(clock_type: :cpu)
      @tracepoint = TracePoint.new(:call, :return) do |trace|
        time = clock_type == :wall ? wall_time : cpu_time
        printf("%-20s:%-20s%-20s\n", time, trace.event, trace.method_id)
      end
    end
    def enable
      @tracepoint.enable
    end

    def disable
      @tracepoint.disable
    end
  end
end

同時，咱們須要再一次調用這個 gem 主文件中的文件：

# lib/diy_prof.rb

require 'diy_prof/version'
require 'diy_prof/time_helpers'
require 'diy_prof/tracer'
# Rest of the original file ..

如今，讓咱們來寫一個例子腳原本測試至今爲止創造了什麼。咱們將使用在 Part I 中見過的那個例子：

# examples/demo.rb

$:<< File.join(File.dirname(__FILE__), "../lib")
require 'diy_prof'

### Begin sample program ###
def main
  3.times do
    find_many_square_roots
    find_many_squares
  end
end

def find_many_square_roots
  5000.times{|i| Math.sqrt(i)}
end

def find_many_squares
  5000.times{|i| i**2 }
end
### End sample program ###

tracer = DiyProf::Tracer.new(clock_type: :cpu)
tracer.enable
main
tracer.disable

若是運行了以上 Ruby 程序，咱們將獲得下列結果： 第一列顯示的是被觸發事件的 CPU time，第二列是被觸發的事件名，第三列是被調用或返回的方法名。這個結果與在 Part I 中學習儀表分析器如何工做時看到的結果很類似。能夠看到，咱們可以輕鬆地經過這個結果重建調用，由於咱們能夠知道各個方法間的調用關係。寫一個能解析這個結果並按執行時間有序顯示方法列的腳本並非很難。但這太無聊了，咱們能夠建造更有趣的東西。看着吧，下一部分將學習咱們可以利用這些數據來作的其餘事情。 #####歸納 咱們學習了 Ruby 的 TracePoint API 以及如何用它監聽方法的調用和返回。同時咱們整合寫過的代碼創建了一個可以顯示 Ruby 程序的執行 trace 的 gem。在第四部分咱們將學習如何有效利用 gem 收集到的數據並經過它們創造一些很酷的調用圖。感謝閱讀！若是你想要閱讀 DIY CPU 分析系列的其餘最新文章，請關注咱們的 twitter @codemancershq.

OneAPM for Ruby 可以深刻到全部 Ruby 應用內部完成應用性能管理和監控，包括代碼級別性能問題的可見性、性能瓶頸的快速識別與追溯、真實用戶體驗監控、服務器監控和端到端的應用性能管理。 想閱讀更多技術文章，請訪問 OneAPM 官方博客。