DIY Ruby CPU 分析 Part II

【編者按】做者 Emil Soman，Rubyist，除此以外居然同時也是藝術家，吉他手，Garden City RubyConf 組織者。本文是 DIY Ruby CPU Profiling 的第二部分。本文系 OneAPM 工程師編譯整理。 在第一部分中咱們學習了 CPU 分析的含義和進行 CPU 分析的兩種方法，點此處回顧第一篇精彩內容。在這一部分咱們將研究 CPU time 和 Wall time，這些部分總被用來測量執行開銷。咱們也會寫一些實現這些測量方法的代碼做爲創建 CPU 分析的第一步。

##Part II. CPU time 和 Wall time

###Wall time

Wall time 是在一個方法被調用和返回之間的真實時間。所以，若是你想要測量一個方法執行的 「Wall clock time」，理論上能夠用秒錶來測量。只要在方法開始執行時打開秒錶，在方法返回時按下中止。這個時間一般也被稱爲真實時間。

關於 Wall time 很重要的一點是，能夠預見，每次試圖測量同一段代碼可能獲得不一樣的結果。這是由於一系列後臺進程會影響 Wall time. 當 CPU 同時運行多個進程的時候，操做系統給同時運行的進程排期而且試圖爲它們公平的分配 CPU 空間。這意味着 CPU 花費的總時間被分紅多個片而咱們的方法只佔用其中的一些時間片。所以，當 Wall clock 開始計時，咱們的進程可能會閒置而且爲並行運行的其餘進程讓路。這意味着花費在其餘進程的時間將增長咱們的 Wall time!

###CPU time

CPU time 是指 CPU 執行方法的時間。CPU time 的度量單位是用於執行方法的 CPU 時鐘週期。若是咱們瞭解 CPU 頻率，它的單位是週期每秒，也能夠稱做赫茲，那麼咱們能夠將其轉換爲時間。若是 CPU 執行某一方法花了 x 個時鐘週期，這個 CPU 頻率是 y 赫茲，那麼 CPU 執行方法的時間爲 x/y 秒。有時操做系統會爲咱們自動進行轉換從而使咱們免於進行這種計算。 CPU 時間不等同於 Wall time，其中的差異在於方法的指令類型。咱們能夠寬泛的將指令分爲兩種類型：CPU 密集型 和 I/O 密集型. 在執行 I/O 指令時，CPU 空閒下來能夠轉去執行其餘 CPU 密集型指令。所以，若是咱們的方法在 I/O 指令上花費時間，CPU 能夠不把時間投入在該方法上，而是去處理其餘事情，直到 I/O 操做完成。 這段時間內 Wall time 在計時而 CPU time 中止計時，落後於 Wall time.

咱們來看看一個須要5分鐘來執行的慢方法的狀況。若是想知道這個方法花費了多長時間，你的 Wall clock 能夠顯示「執行該方法須要五分鐘」，但 CPU 會顯示「執行該方法中用時 3 分鐘」。因此應該遵從哪個說法呢？究竟哪一個時間可以更準確的測量執行方法的時間？

答案是：看狀況。這取決於你但願測量的方法的類型。若是該方法的大部分時間用於 I/O 操做，或者該方法沒有直接處理 CPU 密集型指令，由 CPU time 描述的時間開銷將十分不許確。對於這些類型的方法，經過 Wall time 來測量時間更加合適。而對於其餘狀況，堅持經過 CPU time 來測量是很可靠的。

###測量 CPU time 和 Wall time

鑑於想要寫一個 CPU 分析器，咱們須要一種測量 CPU time 和 Wall time 的方法。下面來看一看已經可以測量這兩項的 Ruby 的 Benchmark module 中的代碼。

def measure(label = "") # :yield:
  t0, r0 = Process.times, Process.clock_gettime(BENCHMARK_CLOCK)
  yield
  t1, r1 = Process.times, Process.clock_gettime(BENCHMARK_CLOCK)
  Benchmark::Tms.new(t1.utime  - t0.utime,
                     t1.stime  - t0.stime,
                     t1.cutime - t0.cutime,
                     t1.cstime - t0.cstime,
                     r1 - r0,
                     label)
end

因而可知，Ruby 經過兩種進程類中的方法來測量時間：

1. 經過times測量 CPU time.
2. 經過clock_gettime來測量真實時間，也就是 Wall time. 可是times方法返回的結果爲1秒，這表示經過分析器用times只能測量僅須要幾秒就能完成的 方法的 CPU time. 然而clock_gettime就有趣多了。

###clock_gettime

Process::clock_gettime是早在 Ruby 2.1 版本就已經被添加的方法，它使用 POSIX clock_gettime()功能並回退到 OS 仿真來得到時間以防clock_gettime在 OS 中失效或沒法實施。該功能接受clock_id及時間結果做爲參數。有不少能夠被選爲這種計時器的clock_ids，但咱們感興趣的是：

1. CLOCK_MONOTONIC: 這個計時器測量逃走的 Wall clock time，由於過去的任意時間點不會被系統時鐘的變化影響，最適合測量 Wall time.
2. CLOCK_PROCESS_CUPTIME_ID: 這個計時器測量每個進程的 CPU time，意即計算進程中全部線程的時間。咱們能夠用它來測量 CPU time. 讓咱們利用這個來寫一些代碼：

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

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

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

能夠在 benchmark 代碼中使用這些方法：

puts "****CPU Bound****"
c1, w1 = DiyProf::cpu_time, DiyProf::wall_time
10000.times do |i|
  Math.sqrt(i)
end
c2, w2 = DiyProf::cpu_time, DiyProf::wall_time
puts "CPU time\t=\t#{c2-c1}\nWall time\t=\t#{w2-w1}"

puts "\n****IO Bound****"
require 'tempfile'

c1, w1 = DiyProf::cpu_time, DiyProf::wall_time
1000.times do |i|
  Tempfile.create('file') do |f|
    f.puts(i)
  end
end
c2, w2 = DiyProf::cpu_time, DiyProf::wall_time
puts "CPU time\t=\t#{c2-c1}\nWall time\t=\t#{w2-w1}"

運行這些代碼會得出相似如下的結果：

****CPU Bound****
CPU time	=	5038
Wall time	=	5142

****IO Bound****
CPU time	=	337898
Wall time	=	475864

這些清楚地展示了單個 CPU 內核的狀況，在僅運行 CPU 密集型指令時 CPU time 和 Wall time 幾乎相等，而運行 I/O 密集型指令時 CPU time 老是少於 Wall time.

###歸納

咱們學習了 CPU time 和 Wall time 的含義與差別，以及何時用哪一種。與此同時，寫了一些 Ruby 代碼來測量 CPU time 和 Wall time 來爲咱們作的 CPU 分析器測量時間。在第三部分咱們將討論 Ruby TracePoint API 並利用它作一個儀表分析器。

原文連接：http://crypt.codemancers.com/posts/2015-03-06-diy-ruby-cpu-profiling-part-i/

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